Going Deep on Stats

Postgres includes lots of monitoring tools that allow you to see what is happening, but there are a few settings that really go into detail, e.g. log_statement_stats:

SET client_min_messages = log;

SET log_statement_stats = true;

 

SELECT 100;

LOG: QUERY STATISTICS
DETAIL: ! system usage stats:

1 ! 0.000000 s user, 0.000000 s system, 0.000201 s elapsed

2 ! [0.000000 s user, 0.000000 s system total]

3 ! 0/0 [0/0] filesystem blocks in/out

4 ! 0/14 [0/363] page faults/reclaims, 0 [0] swaps

5 ! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent

6 ! 0/0 [3/0] voluntary/involuntary context switches

 ?column?

----------
 100

What do all those numbers mean? Well, the Linux getrusage() manual page has a clue — these are kernel resource usage statistics. The first two lines show the user and kernel (“system”) cpu time used, as well as elapsed time. (The numbers in brackets on line #2 and following are totals for this process.) Line #3 shows I/O from/to the storage device (not from the kernel cache). Line #4 covers memory pages faulted into the process address space and reclaimed. Line #5 shows signal and ipc message activity. Line #6 shows process context switches.

Let’s look at some more interesting queries by populating a new table:

CREATE TABLE test(x INTEGER);
INSERT INTO test SELECT x FROM generate_series(1, 1000) t(x);

By clearing the kernel buffers with echo 3 > /proc/sys/vm/drop_caches and restarting the server we can see reads from the storage device (via log_statement_stats) and reads from the kernel cache (via explain (buffers true):

EXPLAIN (ANALYZE true, BUFFERS true, TIMING false, COSTS false)
SELECT COUNT() FROM test;

LOG: QUERY STATISTICS

DETAIL: ! system usage stats:

! 0.000000 s user, 0.000000 s system, 0.019259 s elapsed

! [0.008000 s user, 0.000000 s system total]

! 1712/0 [5840/280] filesystem blocks in/out

! 7/94 [21/586] page faults/reclaims, 0 [0] swaps

! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent

! 29/1 [73/3] voluntary/involuntary context switches

 QUERY PLAN

---------------------------------------------------
 
Aggregate (actual rows=1 loops=1)

 Buffers: shared read=5

 -> Seq Scan on test (actual rows=1000 loops=1)

 Buffers: shared read=5

 Planning time: 3.673 ms

 Execution time: 2.221 ms

EXPLAIN (ANALYZE true, BUFFERS true, TIMING false, COSTS false)

SELECT COUNT() FROM test;

LOG: QUERY STATISTICS

DETAIL: ! system usage stats:

! 0.000000 s user, 0.000000 s system, 0.000408 s elapsed

! [0.008000 s user, 0.000000 s system total]

! 0/0 [5840/288] filesystem blocks in/out

! 0/3 [21/591] page faults/reclaims, 0 [0] swaps

! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent

! 0/0 [74/3] voluntary/involuntary context switches

 QUERY PLAN

---------------------------------------------------
 
Aggregate (actual rows=1 loops=1)

 Buffers: shared hit=5

 -> Seq Scan on test (actual rows=1000 loops=1)

 Buffers: shared hit=5

 Planning time: 0.027 ms

 Execution time: 0.250 ms

Notice the first count reads 1712 512-byte blocks from storage and 5 8kB blocks from the kernel cache into the shared buffer cache. (The unrecorded reads are probably system table information.) The second query shows no I/O from the storage device, and a hit on 5 8kB shared buffer pages.

As you might know, Postgres executes queries in stages. Fortunately, you can get rusage statistics for each stage with log_parser_stats, log_planner_stats, and log_executor_stats. (explain (analyze true) also shows planning and execution durations, which you can see above.)

As you can see, you can access a wealth of information about Postgres and how it is using the cpus, storage, and caches. These have a large impact on how quickly queries execute.

Bruce Momjian is a Senior Database Architect at EnterpriseDB.