How to verify disk hit by a query

Question

I want to know how to verify disk hits by a select query in PostgreSQL 9.4 on CentOS 6.5. Also please let me know how far enabling the log_statement_stats in the postgresql.conf will help me.

I need to understand the 'filesystem blocks in/out' value in the logs when I switch the above parameter to on.

For example, please check the log snippet:

2016-02-03 14:12:45 PST LOG:  statement: select * from test_stats_collect ;
2016-02-03 14:12:45 PST LOG:  QUERY STATISTICS
2016-02-03 14:12:45 PST DETAIL:  ! system usage stats:
        !       0.069489 elapsed 0.027995 user 0.002999 system sec
        !       [0.131979 user 0.146977 sys total]
        !       0/0 [3280/26440] filesystem blocks in/out
        !       0/5 [19/4866] page faults/reclaims, 0 [0] swaps
        !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
        !       20/116 [125/174] voluntary/involuntary context switches

Answer 1

The numbers reported by log_statement_stats come directly from the getrusage system call (assuming your OS has one). The numbers in square brackets are total for the session so far, the other numbers are deltas between the start and stop of the statement.

The filesystem block size is not normalized to be the same as the PostgresSQL block size. It is in whatever units of block size your OS reports in getrusage.

Answer 2

If you want to see the impact of a single query on I/O, you can also use EXPLAIN (ANALYZE, BUFFERS). Since disk reads are heavily dependent on what is already cached, results are obviously going to vary across runs.

Example on a table without index, where you can see 32 blocks were cached and 65562 blocks were read:

explain (analyze, verbose, buffers) SELECT ipaddr, status, bytes, upstream_time, timestamp, path from accesslog where timestamp > '2016-02-05 09:35:00' and timestamp < '2016-02-05 10:00:00';
                                                                                QUERY PLAN                                                                                 
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Seq Scan on public.accesslog  (cost=0.00..94247.03 rows=9191 width=74) (actual time=483.209..558.841 rows=8189 loops=1)
   Output: ipaddr, status, bytes, upstream_time, "timestamp", path
   Filter: ((accesslog."timestamp" > '2016-02-05 09:35:00+00'::timestamp with time zone) AND (accesslog."timestamp" < '2016-02-05 10:00:00+00'::timestamp with time zone))
   Rows Removed by Filter: 1900894
   Buffers: shared hit=32 read=65562
 Planning time: 0.112 ms
 Execution time: 559.331 ms
(7 rows)

Same query, after I create a B-tree index on timestamp. Here you can see 6 blocks were cached and 311 were read:

explain (analyze, verbose, buffers) SELECT ipaddr, status, bytes, upstream_time, timestamp, path from accesslog where timestamp > '2016-02-05 09:35:00' and timestamp < '2016-02-05 10:00:00';
                                                                                  QUERY PLAN                                                                                   
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Index Scan using accesslog_timestamp_idx on public.accesslog  (cost=0.43..607.15 rows=9186 width=74) (actual time=0.083..7.658 rows=8189 loops=1)
   Output: ipaddr, status, bytes, upstream_time, "timestamp", path
   Index Cond: ((accesslog."timestamp" > '2016-02-05 09:35:00+00'::timestamp with time zone) AND (accesslog."timestamp" < '2016-02-05 10:00:00+00'::timestamp with time zone))
   Buffers: shared hit=6 read=311
 Planning time: 0.640 ms
 Execution time: 8.348 ms
(6 rows)

And a repeat of same query shows that the second time all 317 blocks were cached:

explain (analyze, verbose, buffers) SELECT ipaddr, status, bytes, upstream_time, timestamp, path from accesslog where timestamp > '2016-02-05 09:35:00' and timestamp < '2016-02-05 10:00:00';
                                                                                  QUERY PLAN                                                                                   
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Index Scan using accesslog_timestamp_idx on public.accesslog  (cost=0.43..607.15 rows=9186 width=74) (actual time=0.051..8.436 rows=8189 loops=1)
   Output: ipaddr, status, bytes, upstream_time, "timestamp", path
   Index Cond: ((accesslog."timestamp" > '2016-02-05 09:35:00+00'::timestamp with time zone) AND (accesslog."timestamp" < '2016-02-05 10:00:00+00'::timestamp with time zone))
   Buffers: shared hit=317
 Planning time: 0.154 ms
 Execution time: 9.454 ms
(6 rows)