Hi,
I was trying to extract a commitable piece out of [1]. To be able to judge
changes in timing overhead more accurately, I thought it'd be sensible to
update pg_test_timing to report nanoseconds instead of microseconds. Which
lead to trying to update pg_test_timing's docs [2].
The "Measuring Executor Timing Overhead" section seems misleading:
<para>
The i7-860 system measured runs the count query in 9.8 ms while
the <command>EXPLAIN ANALYZE</command> version takes 16.6 ms, each
processing just over 100,000 rows. That 6.8 ms difference means the timing
overhead per row is 68 ns, about twice what pg_test_timing estimated it
would be. Even that relatively small amount of overhead is making the fully
timed count statement take almost 70% longer. On more substantial queries,
the timing overhead would be less problematic.
</para>
The main reason for the ~2x discrepancy is that we do 2 timestamp calls for
each invocation of an executor node, one in InstrStartNode(), one in
InstrStopNode(). I think this should be clarified in the section?
I also think we should update the section to compare
EXPLAIN (ANALYZE, TIMING OFF) with
EXPLAIN (ANALYZE, TIMING ON)
rather than comparing the "bare" statement with EXPLAIN ANALYZE. There's
plenty other overhead in EXPLAIN, even without TIMING ON.
With the instr_time-as-nanosec patches applied (I'll post a new version in a
few minutes), I get the following:
pg_test_timing:
Per loop time including overhead: 13.97 ns
Histogram of timing durations:
< ns % of total count
16 97.48221 209400569
32 2.51201 5396022
64 0.00477 10246
128 0.00030 640
256 0.00005 117
512 0.00000 0
1024 0.00000 3
2048 0.00034 729
4096 0.00001 14
8192 0.00000 8
16384 0.00015 320
32768 0.00014 303
65536 0.00001 26
131072 0.00000 0
262144 0.00000 1
psql -Xc 'DROP TABLE IF EXISTS t; CREATE TABLE t AS SELECT * FROM
generate_series(1, 100000) g(i);' && pgbench -n -r -t 100 -f <(echo -e "SELECT
COUNT(*) FROM t;EXPLAIN (ANALYZE, TIMING OFF) SELECT COUNT(*) FROM t;EXPLAIN
(ANALYZE, TIMING ON) SELECT COUNT(*) FROM t;") |grep '^ '
DROP TABLE
SELECT 100000
3.431 0 SELECT COUNT(*) FROM t;
3.888 0 EXPLAIN (ANALYZE, TIMING OFF) SELECT COUNT(*) FROM
t;
6.671 0 EXPLAIN (ANALYZE, TIMING ON) SELECT COUNT(*) FROM t;
Pgbench reports about 11% lost just from TIMING OFF ANALYZE, and a further 45%
from TIMING ON. The per-row overhead, compared between TIMING ON/OFF:
((6.187ms - 3.423 ms) * 1000000)/(100000 * 2) = 13.82ns
which is within the run-to-run variance of the pg_test_timing result.
Greetings,
Andres Freund
[1] https://postgr.es/m/20230116023639.rn36vf6ajqmfciua%40awork3.anarazel.de
[2] https://www.postgresql.org/docs/current/pgtesttiming.html#id-1.9.5.11.7.3
