Re: Adding wait events statistics - Mailing list pgsql-hackers

Hi,

On 2025-06-30 13:36:12 +0000, Bertrand Drouvot wrote:
> Wait events are useful to know what backends are waiting for when there is/was
> a performance issue: for this we can sample pg_stat_activity at regular intervals
> and record historical data. That’s how it is commonly used.
>
> It could also be useful to observe the engine/backends behavior over time and
> help answer questions like:
>
> * Is the engine’s wait pattern the same over time?
> * Is application’s "A" wait pattern the same over time?
> * I observe a peak in wait event "W": is it because "W" is now waiting longer or
> is it because it is hit more frequently?
> * I observe a peak in some of them (say for example MultiXact%), is it due to a
> workload change?
>
> For the above use cases, we need a way to track the wait events that occur between
> samples: please find attached a proof of concept patch series doing so.
> >
> 0002 -  It adds wait events statistics
>
> It adds a new stat kind PGSTAT_KIND_WAIT_EVENT for the wait event statistics.
>
> This new statistic kind is a fixed one because we know the maximum number of wait
> events. Indeed:
>
>  * it does not take into account custom wait events as extensions have all they need
>  at their disposal to create custom stats on their own wait events should they
>  want to (limited by WAIT_EVENT_CUSTOM_HASH_MAX_SIZE though).
>
>  * it does not take into account LWLock > LWTRANCHE_FIRST_USER_DEFINED for the same
>  reasons as above. That said, there is no maximum limitation in LWLockNewTrancheId().
>
>  * we don't want to allocate memory in some places where the counters are
>  incremented (see 4feba03d8b9). We could still use the same implementation as for
>  backend statistics (i.e, make use of flush_static_cb) if we really want/need to
>  switch to variable stats.

Even without allocating memory, this makes wait events considerably more
expensive. Going from ~4 instructions to something more like ~40.  Including
external function calls.

Today:

start wait:
   0x0000000000a08e8f <+63>:    lea    0x735662(%rip),%r12        # 0x113e4f8 <my_wait_event_info>
   0x0000000000a08e96 <+70>:    mov    (%r12),%rax
   0x0000000000a08e9a <+74>:    movl   $0x9000006,(%rax)

   < do wait operation >


end wait:
   0x0000000000a08eaa <+90>:    mov    (%r12),%rax


After:

start wait:
   0x0000000000a0b39f <+63>:    lea    0x73673a(%rip),%r12        # 0x1141ae0 <my_wait_event_info>
   0x0000000000a0b3a6 <+70>:    mov    (%r12),%rax
   0x0000000000a0b3aa <+74>:    movl   $0x9000006,(%rax)


   < do wait operation >

end wait:

   0x0000000000a0b3ba <+90>:    mov    (%r12),%rax
   0x0000000000a0b3be <+94>:    mov    (%rax),%edi
   0x0000000000a0b3c0 <+96>:    rex call 0xa452e0 <waitEventIncrementCounter>
   0x0000000000a0b3c6 <+102>:    mov    (%r12),%rax

Where waitEventIncrementCounter ends up as:

   0x0000000000a452e0 <+0>:    lea    0x6fc7f9(%rip),%rax        # 0x1141ae0 <my_wait_event_info>
   0x0000000000a452e7 <+7>:    mov    (%rax),%rax
   0x0000000000a452ea <+10>:    mov    (%rax),%eax
   0x0000000000a452ec <+12>:    mov    %eax,%edx
   0x0000000000a452ee <+14>:    and    $0xff000000,%edx
   0x0000000000a452f4 <+20>:    jne    0xa45300 <waitEventIncrementCounter+32>
   0x0000000000a452f6 <+22>:    test   %ax,%ax
   0x0000000000a452f9 <+25>:    jne    0xa45300 <waitEventIncrementCounter+32>
   0x0000000000a452fb <+27>:    ret
   0x0000000000a452fc <+28>:    nopl   0x0(%rax)
   0x0000000000a45300 <+32>:    cmp    $0x1000000,%edx
   0x0000000000a45306 <+38>:    jne    0xa4530e <waitEventIncrementCounter+46>
   0x0000000000a45308 <+40>:    cmp    $0x5e,%ax
   0x0000000000a4530c <+44>:    ja     0xa452fb <waitEventIncrementCounter+27>
   0x0000000000a4530e <+46>:    cmp    $0x7000000,%edx
   0x0000000000a45314 <+52>:    sete   %cl
   0x0000000000a45317 <+55>:    test   %ax,%ax
   0x0000000000a4531a <+58>:    setne  %al
   0x0000000000a4531d <+61>:    test   %al,%cl
   0x0000000000a4531f <+63>:    jne    0xa452fb <waitEventIncrementCounter+27>
   0x0000000000a45321 <+65>:    cmp    $0xb000000,%edx
   0x0000000000a45327 <+71>:    je     0xa452fb <waitEventIncrementCounter+27>
   0x0000000000a45329 <+73>:    mov    %edi,%eax
   0x0000000000a4532b <+75>:    movzwl %di,%edi
   0x0000000000a4532e <+78>:    lea    0x714e4b(%rip),%rdx        # 0x115a180 <PendingWaitEventStats>
   0x0000000000a45335 <+85>:    shr    $0x18,%eax
   0x0000000000a45338 <+88>:    shl    $0x5,%rax
   0x0000000000a4533c <+92>:    add    0x4e1735(%rip),%rax        # 0xf26a78
   0x0000000000a45343 <+99>:    movslq 0x8(%rax),%rax
   0x0000000000a45347 <+103>:    add    %rdi,%rax
   0x0000000000a4534a <+106>:    incq   (%rdx,%rax,8)
   0x0000000000a4534e <+110>:    lea    0x714e0b(%rip),%rax        # 0x115a160 <have_wait_event_stats>
   0x0000000000a45355 <+117>:    movb   $0x1,(%rax)
   0x0000000000a45358 <+120>:    ret


That's about an order of magnitude increase in overhead, just based on the
number of instructions, and probably considerably xmore in runtime (you're
adding external function calls etc).


I think to make this viable, we would have to remove some wait events and be
more careful about adding them.  And optimize this code a good bit. This
really shouldn't end up with this mouch code.


Greetings,

Andres Freund