7 Profiling

Find expensive queries with PostgreSQL logs, pg_stat_statements, auto_explain, and profilers, and relate measurements to total workload cost.

1. What Profiling Is

In the previous chapters we looked at how queries work, which building blocks make up an execution plan, and what affects the planner’s choice among alternative plans. This is the hardest and most important part. Once you understand the mechanisms, logic and common sense go a long way: you can work out whether a query is executing efficiently and what might improve it.

But how do you find the query that is actually worth optimizing?

Any optimization task—not only database optimization— starts with profiling, even if we do not always use that word. We break the problematic task into smaller parts and measure how much of the total work each part consumes. It is also useful to know how often each part is executed.

The larger a component’s share of the total cost, the larger the potential gain from optimizing it. In practice, the optimization effort matters too: a theoretically large gain may be expensive or risky to obtain.

Sometimes a component is individually fast but executed far too often. This is common, for example, with queries generated by ORMs. Then a more useful question may be: should this operation be executed this many times at all? Changing application architecture is rarely easy, but it can produce a much larger gain than tuning one query invocation.

A profile of overall database activity is also valuable to an administrator who is not investigating one complaint but looking for the largest consumers of system resources. A monitoring system should make such a profile visible.

Andrey Zubkov’s pg_profile extension is one tool for this job. It builds on PostgreSQL statistics views and stores periodic activity snapshots. Comparing snapshots can reveal both performance problems and the conditions under which they appeared. A full discussion of monitoring architecture, tools, and metric selection is beyond this book.

Postgres Professional also publishes Alexey Lesovsky’s Russian-language book Monitoring PostgreSQL, which goes much deeper into that subject. When investigating one concrete problem, however, the profile should be scoped to the actions needed to reproduce that problem.

To solve a specific problem, the profile should be built so that measurements cover only the actions needed to reproduce that particular problem.

2. What to Measure

What unit should we use for the cost of a component? For the end user, the most meaningful measure is response time: how many seconds pass between an action and the result.

In this sense, it can be more convenient to look at the amount of I/O, that is, the number of pages read and written. This measure is more stable: with the same data and configuration parameters, it does not depend on hardware characteristics or current server load.

It is also important to investigate realistic data volumes. Tools such as Postgres.ai’s Database Lab Engine make it possible to create thin database clones quickly, which can be useful when reproducing production-scale behavior without duplicating all storage.

I/O usually reflects the amount of work required to execute a query reasonably well, because much of the time is spent reading and processing data pages. This measure, however, has little meaning to the end user.

3. Application Profile

Performance problems often are in the database: one bad execution plan can change runtime by orders of magnitude. But not always. A slow client connection, serialization, application-server work, client-side rendering, queueing, remote service calls, and network transfer can all dominate the user’s response time. A complete profile should therefore cover the client, application server, network, and database.

Obtaining such an end-to-end profile is difficult unless every component of the system exposes useful telemetry. At a minimum, measure total response time and compare it with the time accounted for by database work. Check for obvious network delays and time spent outside PostgreSQL before assuming that the database is the bottleneck.

From here on, assume that the problem has already been localized to the database.

4. PL/pgSQL Profile

One user action usually executes more than one SQL statement. To find the statement worth optimizing, we need a profile with statement-level detail.

The server-side application may also contain procedural code rather than SQL alone.

For PL/pgSQL code, Jan Wieck’s PL Profiler can profile scripts and live sessions. It produces HTML reports and can visualize call relationships as flame graphs.

Pavel Stěhule’s plpgsql_check is another useful extension. It can perform additional checks on PL/pgSQL code, detect some performance problems, and includes profiling facilities.

5. Query Profile

PostgreSQL provides two main built-in paths to a profile of executed SQL: server logging and cumulative statement statistics, most commonly through pg_stat_statements.

Server Log

Configuration parameters can enable logging of statements and their execution durations. log_min_duration_statement is a common starting point.

How can we identify in the log exactly the queries that belong to a user’s actions? Changing log_min_duration_statement in a session affects only that same session; there is no standard way for a performance specialist to change it from another session for an arbitrary backend. The common stream of log messages can be filtered to select only the required ones. For this purpose, it is useful to include additional identifying information in log_line_prefix, such as process ID, session ID, user, database, or application name. Connection pooling makes the situation even more complicated. Nested SQL executed inside functions is a separate problem. The auto_explain module can log plans, including nested statements when configured with auto_explain.log_nested_statements.

A busy server log can become enormous. External tools such as pgBadger can aggregate and analyze PostgreSQL log data.

Application code can also emit its own correlation identifiers and diagnostic messages when that helps connect user-visible work to database activity.

Statement Statistics

The second approach is statement execution statistics collected by the pg_stat_statements extension. The word statistics here means something different from Chapter VI, “Statistics.” Planner statistics describe the distribution of data and help predict future execution. pg_stat_statements records aggregated information about work that actually happened. The collected query execution statistics include information about I/O in terms of pages.

Because the number of distinct queries can be very large, storage is bounded by pg_stat_statements.max. When the table fills, information about less frequently executed statement entries is discarded.

Queries are considered the same when they have the same parse tree except for constants. Keep in mind that such queries may have different execution plans and may take different amounts of time to execute.

When compute_query_id is set to auto or on, query identifiers are computed by the PostgreSQL core. This makes it possible to correlate information obtained from different extensions using unified identifiers.

Enable the pg_stat_statements extension, which we will use to build the profile:

CREATE EXTENSION pg_stat_statements;
CREATE EXTENSION
ALTER SYSTEM SET shared_preload_libraries =
  'pg_stat_statements';
ALTER SYSTEM

The server must then be restarted.

postgres$ pg_ctl restart -l /home/postgres/logfile
postgres$ /usr/local/pgsql/bin/psql demo

For the following example, we are going to collect nested statements too:

SET pg_stat_statements.track = 'all';
SET

Create a compact view over the fields we want to inspect:

CREATE VIEW statements_v AS
SELECT
  queryid,
  toplevel,
  substring(regexp_replace(query,' +',' ','g') FOR 55)
    AS query,
  calls,
  round(total_exec_time)/1000 AS time_sec,
  shared_blks_hit + shared_blks_read +
    shared_blks_written AS shared_blks
FROM pg_stat_statements
ORDER BY total_exec_time DESC;
CREATE VIEW

Now consider a report that shows the number of passengers by airplane model and fare class. First define a function that counts passengers for one airplane and fare class:

CREATE FUNCTION qty(
  airplane_code text, fare_conditions text
) RETURNS bigint
AS $$
  SELECT count(*)
  FROM timetable tt
    JOIN boarding_passes bp ON bp.flight_id = tt.flight_id
    JOIN seats s ON s.airplane_code = tt.airplane_code
                AND s.seat_no = bp.seat_no
  WHERE tt.airplane_code = qty.airplane_code
    AND s.fare_conditions = qty.fare_conditions;
$$ STABLE LANGUAGE sql;
CREATE FUNCTION

Then build a table function around it:

CREATE FUNCTION report()
RETURNS TABLE(
  model text,
  economy bigint, comfort bigint, business bigint
)
AS $$
DECLARE
  r record;
BEGIN
  FOR r IN
    SELECT a.airplane_code, a.model
    FROM airplanes a
    ORDER BY a.model
  LOOP
    report.model := r.model;
    report.economy := qty(r.airplane_code, 'Economy');
    report.comfort := qty(r.airplane_code, 'Comfort');
    report.business := qty(r.airplane_code, 'Business');
    RETURN NEXT;
  END LOOP;
END;
$$ STABLE LANGUAGE plpgsql;

Reset statement statistics and execute the report:

SELECT pg_stat_statements_reset();
SELECT * FROM report();
          model          | economy | comfort | business
-------------------------+---------+---------+----------
 Aerobus A320neo         |  120803 |       0 |    24494
 Aerobus A330-900neo     |  337923 |   42242 |    43775
 Aerobus A350-1000       |  736214 |       0 |   115244
 Aerobus A350F           |       0 |       0 |        0
 Boeing 737 MAX 7        |  556344 |       0 |    61743
 Boeing 767-300F         |       0 |       0 |        0
 Boeing 777-300ER        | 2238243 |  329509 |   205873
 Boeing 787-9 Dreamliner |  613540 |   68505 |   156712
 Bombardier CRJ700       |   91626 |   21181 |    10604
 Embraer E170            |  191837 |       0 |    16006
(10 rows)

Now inspect the profile:

SELECT * FROM statements_v \gx
-[ RECORD 1 ]----------------------------------
queryid     | -3009688052632882778
toplevel    | t
query       | SELECT * FROM report()
calls       | 1
time_sec    | 28.311
shared_blks | 9417875
-[ RECORD 2 ]----------------------------------
queryid     | -3792749405278051211
toplevel    | f
query       | SELECT count(*)                  +
            |  FROM timetable tt               +
            |  JOIN boarding_passe
calls       | 30
time_sec    | 28.292
shared_blks | 9416655
-[ RECORD 3 ]----------------------------------
queryid     | 704897965492952962
toplevel    | f
query       | SELECT a.airplane_code, a.model  +
            |  FROM airplanes a                +
            |  ORDE
calls       | 1
time_sec    | 0
shared_blks | 4
-[ RECORD 4 ]----------------------------------
queryid     | -3948231919979109674
toplevel    | t
query       | SELECT pg_stat_statements_reset()
calls       | 1
time_sec    | 0
shared_blks | 0

Three entries matter:

The top-level report() call
The query inside qty, executed 30 times
The query driving the PL/pgSQL loop

Almost all execution time and buffer work comes from the qty query. That repeated work is the obvious target: the report should be restructured around one set-oriented query.

6. Profile of Single Query

Once profiling has identified the statement worth optimizing, we need a profile inside that query. EXPLAIN ANALYZE provides one. The components of this profile are plan nodes. But the plan is a tree, not a flat list, and that matters when interpreting times.

For each node, actual time, rows, and loops tell us what happened during execution.

The buffers option of EXPLAIN shows the amount of I/O; if track_io_timing is enabled, it also shows the time spent on I/O operations.

For plan diagnosis, cardinality estimates are at least as important as runtime. Compare estimated rows with actual rows, taking loops into account. A large error low in the plan tree can propagate upward and distort join-method, access-path, aggregation, and memory decisions.

Start with the deepest node where the estimates first become badly wrong rather than blaming every parent node that inherits the error.

Good cardinality estimates do not guarantee a good plan— cost parameters and the cost model can still be wrong—but large cardinality errors are one of the first things to investigate.

Sometimes a query runs so long that using EXPLAIN ANALYZE is impractical. In that case we have to settle for plain EXPLAIN and try to understand the cause of inefficiency without complete information.

Now rewrite the passenger report as one SQL query and examine it:

EXPLAIN (analyze, costs off, timing off)
WITH rf AS MATERIALIZED (
  SELECT f.flight_id, r.airplane_code
  FROM flights f
    JOIN routes r ON r.route_no = f.route_no
                 AND r.validity @> f.scheduled_departure
), t AS (
  SELECT rf.airplane_code,
    count(*) FILTER
         (WHERE s.fare_conditions = 'Economy') AS economy,
    count(*) FILTER
         (WHERE s.fare_conditions = 'Comfort') AS comfort,
    count(*) FILTER
         (WHERE s.fare_conditions = 'Business') AS business
  FROM rf
    JOIN boarding_passes bp ON bp.flight_id = rf.flight_id
    JOIN seats s ON s.airplane_code = rf.airplane_code
                AND s.seat_no = bp.seat_no
  GROUP BY rf.airplane_code
)
SELECT a.model,
  coalesce(t.economy, 0) AS economy,
  coalesce(t.comfort, 0) AS comfort,
  coalesce(t.business, 0) AS business
FROM airplanes a
  LEFT JOIN t ON a.airplane_code = t.airplane_code
ORDER BY a.model;

As the next page clearly shows, large plans are not always convenient to work with in text form. For better visibility, third-party tools can be used; one of them is explain.tensor.ru.

Notice how much the query execution time decreased and how many fewer pages had to be read after redundant reads were eliminated:

                         QUERY PLAN
------------------------------------------------------------
 Sort (actual rows=10.00 loops=1)
   Sort Key: ((ml.model ->> current_setting('bookings.la...
   Sort Method: quicksort  Memory: 25kB
   Buffers: shared hit=13059 read=37154
   CTE rf
     -> Hash Join (actual rows=37671.00 loops=1)
         Hash Cond: (f.route_no = r.route_no)
         Join Filter: (r.validity @> f.scheduled_departure)
         Rows Removed by Join Filter: 115016
         Buffers: shared hit=397 read=5
         -> Seq Scan on flights f (actual rows=37671.00 ...
             Buffers: shared hit=368
         -> Hash (actual rows=2030.00 loops=1)
             Buckets: 2048  Batches: 1  Memory Usage: 145kB
             Buffers: shared hit=29 read=5
             -> Seq Scan on routes r (actual rows=2030.0...
                 Buffers: shared hit=29 read=5
 ...
                   Buffers: shared hit=13059 read=37153
                   -> Hash Join (actual rows=5982418.00 ...
                       Hash Cond: ((rf.airplane_code = s...
                       Buffers: shared hit=13059 read=37153
                       -> Hash Join (actual rows=5982418...
                           Hash Cond: (bp.flight_id = rf...
                           Buffers: shared hit=13057 rea...
                           -> Seq Scan on boarding_passe...
                               Buffers: shared hit=12660...
                           -> Hash (actual rows=37671.00...
                               Buckets: 65536 (originall...
                               Buffers: shared hit=397 r...
                               -> CTE Scan on rf (actual...
                                   Storage: Memory  Maxi...
                                   Buffers: shared hit=3...
                       -> Hash (actual rows=1741.00 loop...
                           Buckets: 2048  Batches: 1  Me...
                           Buffers: shared hit=2 read=8
                           -> Seq Scan on seats s (actua...
                               Buffers: shared hit=2 read=8
 Planning:
   Buffers: shared hit=5 read=1
 Planning Time: 0.287 ms
 Execution Time: 1388.015 ms
(54 rows)

For perspective, count the heap pages of the main tables involved:

SELECT sum(relpages)
FROM pg_class
WHERE relname IN ('flights', 'routes', 'boarding_passes',
  'seats', 'airplanes');
  sum
-------
 50212
(1 row)

This number can serve as a rough upper estimate for a query that needs all rows: processing substantially more pages may indicate that the same data is scanned several times.

In this case the plan is already close to optimal. It can still be improved, but not nearly as radically.