In an earlier post about using
EXPLAIN ANALYSE I mentioned that there were a couple of options to
EXPLAIN ANALYSE that were not widely known, but I only talked about one, the
BUFFERS option. In this article I will dig into that second option; IO timing tracking.
IO timing tracking
The second tweak to the default
EXPLAIN usage is using IO timing tracking. You can set this per session:
set track_io_timing = on;
As usual the Postgres docs do a thorough job explaining what this setting does:
Enables timing of database I/O calls. This parameter is off by default, as it will repeatedly query the operating system for the current time, which may cause significant overhead on some platforms. You can use the pg_test_timing tool to measure the overhead of timing on your system. I/O timing information is displayed in pg_stat_database, in the output of EXPLAIN when the BUFFERS option is used, in the output of VACUUM when the VERBOSE option is used, by autovacuum for auto-vacuums and auto-analyzes, when log_autovacuum_min_duration is set and by pg_stat_statements. Only superusers and users with the appropriate SET privilege can change this setting.
However simply put for our use case if you turn this setting on then when you run an
EXPLAIN (ANALYSE, BUFFERS) you will get the time in milliseconds that the IO operations in each part of your query took to perform, for example using one of the queries from the previous post:
EXPLAIN (ANALYSE, BUFFERS) SELECT events.* FROM events INNER JOIN activity_logs ON events.activity_logs_id = activity_logs.id WHERE activity_logs.user_id = 83463 AND events.date in ('2022-12-04') AND (events.event_start IS NOT NULL AND events.event_end IS NOT NULL AND events.duration != 0 OR events.exception_id IS NOT NULL) ORDER BY date ASC, events.event_start DESC NULLS LAST; Sort (cost=10157.36..10157.37 rows=1 width=166) (actual time=2290.762..2290.763 rows=0 loops=1) Sort Key: events.event_start DESC NULLS LAST Sort Method: quicksort Memory: 25kB Buffers: shared hit=1166 read=3117 I/O Timings: read=3221.979 -> Nested Loop (cost=1.13..10157.35 rows=1 width=166) (actual time=2290.757..2290.758 rows=0 loops=1) Buffers: shared hit=1166 read=3117 I/O Timings: read=3221.979 -> Index Scan using index_activity_logs_on_user_id_and_event_start_and_event_end on activity_logs (cost=0.56..325.89 rows=82 width=4) (actual time=0.018..14.964 rows=315 loops=1) Index Cond: (user_id = 83463) Buffers: shared hit=33 read=116 I/O Timings: read=137.986 -> Index Scan using index_events_on_activity_logs_id on events (cost=0.57..119.89 rows=1 width=166) (actual time=7.221..7.221 rows=0 loops=315) Index Cond: (activity_logs_id = activity_logs.id) Filter: ((((event_start IS NOT NULL) AND (event_end IS NOT NULL) AND (duration <> '0'::double precision)) OR (exception_id IS NOT NULL)) AND (date = '2022-12-04'::date)) Rows Removed by Filter: 11 Buffers: shared hit=1133 read=3001 I/O Timings: read=3083.993 Planning: Buffers: shared hit=146 Planning Time: 0.427 ms Execution Time: 2290.813 ms
As with the
BUFFERS option the timings are cumulative at each node in the hierarchy of the explain output.
This isn’t something that I’ve personally found particularly useful, I suspect it might be useful when diagnosing slow fetches if you’re storing data on different backend data stores across tables, but it’s interesting to see.