Re: [PATCH v1 0/7] Wait event timing and tracing instrumentation

Hi hackers,

This is v12 of the timed-wait-event series, five patches. It is a
follow-up to my v11 mail:

What changed since v11
======================

Patches 0001, 0002 and 0003 are byte-identical to v11. Their
patch-ids are the same.

In 0004, only three TAP tests changed: 002_ownership, 003_reset_acl
and 004_reset_race. Each of them reads the statistics of another
backend right after that backend ran its last statement. Since the
deferred accounting in v11, the last wait of a backend becomes
visible only when its next wait starts. This is the visibility lag
that the documentation already describes. One run on my fork's CI
failed on Linux with Autoconf because of it. The tests now poll
until the value appears. There is no code change in 0004.

0005 changes pg_wait_event_trace_by_statement(), the SQL function
that assigns the waits of a trace to statements. It adds a column
named phase, a new bucket named <no-statement>, documentation, new
regression cases and three new tests. There are also two new comments
in the C file. There is no change in compiled code.

The v11 tests checked this function with one simple-protocol query.
That is why they did not find the problems below. The new tests are:

- t/014_by_statement_pre.pl: a second session holds a lock while a
statement waits in Bind or in parse analysis, and a lock_timeout
during Bind.
- t/015_by_statement_pgbench.pl: pgbench with -M simple, extended
and prepared, while a second session holds a table lock for a
short time. No wait except Client waits may stay in <idle>, and
every lock wait must be inside a statement.
- t/016_by_statement_oracle.pl: a fixed script of statement shapes
(extended protocol, prepared statements, pipeline, explicit
transaction, DO, CALL with COMMIT, an error). The test takes the
expected query_id of each statement from EXPLAIN (VERBOSE), not
from the trace, and checks that each wait is in the right
statement.

I checked that these tests catch the bugs: with the v11 function,
both 015 and 016 fail.

Why: a lock-convoy test
=======================

While testing v11 against a lock-convoy workload, I found two
problems in by_statement(). The workload was 16 pgbench clients with
-M prepared, running a single-row lookup at 8,000 requests per
second. Autovacuum truncated the table and held ACCESS EXCLUSIVE in
bursts of about 20 ms. Capture was set to trace.

Problem 1: an execution of a named prepared statement over the
extended protocol writes ExecStart, but no QueryStart. The function
opened a bucket only on QueryStart and UtilityStart, so all the waits
of such a statement went to <idle>. The C marker code already treats
ExecStart as a start. The SQL function did not.

Problem 2: some waits happen after the request has arrived but before
the start marker is written. These are relation locks taken in Bind
by the plan cache, or in parse analysis with the simple protocol. By
position, they went to <idle>. In my run, these were exactly the
convoy waits: 208 Lock:relation waits, 38.9 ms on average, 101.5 ms
at most.

What v12 does
=============

The rule is written in full in the new documentation section. In
short:

- A top-level ExecStart opens its own bucket, unless a QueryStart
or UtilityStart of the same statement has opened one already.
- The statements run inside a top-level DO, CALL, EXECUTE or
CREATE TABLE AS stay in the bucket of that statement.
- Waits between the last Idle, TxnCommit or TxnAbort marker and the
start marker of a statement belong to that statement, with
phase = 'pre'. ClientRead stays in <idle>.
- A request that fails before any statement starts, for example
with lock_timeout during Bind, goes to <no-statement>.
- Also fixed: in v11, a utility statement sent through the simple
protocol got two buckets.

Four ambiguous cases remain. The documentation lists them:

- Without a commit between two statements of a transaction or
pipeline, the waits between them stay with the earlier statement.
- If the next request was already buffered, so no Idle was written,
the work after TxnCommit counts as 'pre' of the next statement.
- An error caught by a PL/pgSQL EXCEPTION block inside a utility
statement can leave the count of open utility statements too
high, until the next Idle or TxnAbort.
- With several Parse messages pipelined ahead of their Executes,
the first Execute is attributed to the last Parse.

Results with v12
================

Same workload as above, three runs with capture = trace. I checked
all three runs against the raw data.

run convoy avg / max in statement lookup
Lock:relation ms buckets, DataFileRead
waits phase 'pre' in <idle>
--- ------------- ------------ -------------- ------------
1 144 45.2 / 107.1 144 0
2 208 38.8 / 110.1 208 0
3 32 94.1 / 119.2 32 0

Only ClientRead remains in <idle>. In run 1, 231 executions started
right after a commit with no Idle marker in between, because the next
request was already buffered. Those of them that had waits each got
their own bucket.

In these runs I also used a sampling profiler, pg_wait_sampling, at
10 ms. It attributed none of the Lock:relation time to the lookup
query: in its per-query profile the share was 0.00%. log_lock_waits
stayed silent too, because each wait was shorter than
deadlock_timeout. Sampling and exact per-wait timing answer different
questions, as the v11 mail already said; this case is one where the
exact per-statement view adds something.

Cost
====

The numbers from v11 stand for v12. The measured path has not
changed: 0001 to 0003 are identical, and neither 0004 nor 0005
changes compiled code. The benchmark never calls by_statement(). The
numbers are in my v11 mail and in the evidence release:

https://github.com/DmitryNFomin/postgres/releases/tag/v11-evidence-20260924

One more observation, which is not a benchmark. In the convoy test,
requests slower than 15 ms showed no visible difference between
capture = trace and capture = off over four runs of each. With n = 4
and a large spread from autovacuum's lock time, it cannot show a
small difference.

CI and attachments
==================

The full CI of my fork is green on the tip, f8abf1f0cc9:

https://github.com/DmitryNFomin/postgres/actions/runs/39804808641

The series is at https://github.com/DmitryNFomin/postgres/tree/wet-v12
and is based on 311df1dc039, as v11. Attached: the five v12 patches
only.

Regards,
Dmitry Fomin