Re: Adding wait events statistics

Hi,

On 2025-07-09 07:26:05 +0000, Bertrand Drouvot wrote:
> On Tue, Jul 08, 2025 at 10:19:07PM -0400, Andres Freund wrote:
> > On 2025-06-30 13:36:12 +0000, Bertrand Drouvot wrote:
> > > * 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.
>
> Yeah looking at the performance impacts and discuss those was in my todo (as
> mentioned above), thanks for looking at it!

TBH, the more I think about this, the less convinced a pure counter provides
*any* additional value over stats we already have, in which case the overhead
is moot.

We use commonly use wait events unconditionally around system calls, e.g.:

pgstat_report_wait_start(wait_event_info);
returnCode = pg_preadv(vfdP->fd, iov, iovcnt, offset);
pgstat_report_wait_end();

A counter for the number of wait events is just less informative version of
what we already have in pg_stat_io. There's literally no value provided by
tracking the number of times that wait event is hit.

A pretty large number of wait events operate that way. For those the
interesting information would be to measure *how long* you are in the wait
event, not the number of times the wait event was entered for a very short
amount of time.

The obvious counter to that is that you likely are planning to add timing
information at some point down the line - leaving overhead aside, that would
*also* just duplicate information for the above case, namely track_io_timing.

The wait events we have as-is are useful because they tell you what's
currently happening, and you can correlate that with other things that are
going on. But a pure counter of wait events encountered doesn't allow for
that.

> > end wait:
> > 0x0000000000a08eaa <+90>: mov (%r12),%rax
>
> Yeah this one is unbeatable, it will have to be more expensive...
>
> On my side, I'm getting:
>
> => 0x000000000091a320 <+0>: mov 0x5337f9(%rip),%rax # 0xe4db20 <my_wait_event_info>
> 0x000000000091a327 <+7>: mov (%rax),%eax
> 0x000000000091a329 <+9>: mov %eax,%edx
> 0x000000000091a32b <+11>: and $0xff000000,%edx
> 0x000000000091a331 <+17>: jne 0x91a340 <waitEventIncrementCounter+32>
> 0x000000000091a333 <+19>: test %ax,%ax
> 0x000000000091a336 <+22>: jne 0x91a340 <waitEventIncrementCounter+32>
> 0x000000000091a338 <+24>: ret
> 0x000000000091a339 <+25>: nopl 0x0(%rax)
> 0x000000000091a340 <+32>: cmp $0x1000000,%edx
> 0x000000000091a346 <+38>: jne 0x91a34e <waitEventIncrementCounter+46>
> 0x000000000091a348 <+40>: cmp $0x5e,%ax
> 0x000000000091a34c <+44>: ja 0x91a338 <waitEventIncrementCounter+24>
> 0x000000000091a34e <+46>: cmp $0x7000000,%edx
> 0x000000000091a354 <+52>: sete %cl
> 0x000000000091a357 <+55>: test %ax,%ax
> 0x000000000091a35a <+58>: setne %al
> 0x000000000091a35d <+61>: test %al,%cl
> 0x000000000091a35f <+63>: jne 0x91a338 <waitEventIncrementCounter+24>
> 0x000000000091a361 <+65>: cmp $0xb000000,%edx
> 0x000000000091a367 <+71>: je 0x91a338 <waitEventIncrementCounter+24>
> 0x000000000091a369 <+73>: mov %edi,%eax
> 0x000000000091a36b <+75>: movzwl %di,%edi
> 0x000000000091a36e <+78>: shr $0x18,%eax
> 0x000000000091a371 <+81>: shl $0x5,%rax
> 0x000000000091a375 <+85>: movslq 0xe4d9c8(%rax),%rax
> 0x000000000091a37c <+92>: movb $0x1,0x56045d(%rip) # 0xe7a7e0 <have_wait_event_stats>
> 0x000000000091a383 <+99>: add %rdi,%rax
> 0x000000000091a386 <+102>: addq $0x1,0xe7a800(,%rax,8)
> 0x000000000091a38f <+111>: ret

I think adding 6 conditional branches to this is just out of question...

> > I think to make this viable, we would have to remove some wait events and be
> > more careful about adding them.
>
> You mean incrementing the counters for wait events for which we expect that
> the increment is "negligible" as compare to the wait event itself? (Like DATAFILE
> IO and such)?

I mean that we would need to either *remove* a bunch of wait events, or change
the API so that there are "cheap" wait events that just have the current
overhead, and expensive wait events that do this tracking.

> If so I agree and that's something I also have discussed with a few (also if we
> add the timings later), that we could/should be more granular. If we go that way
> we could also imagine a GUC to set the stats for all of them? (default being
> off).

Any conditional code that you add makes this stuff more expensive...

> > And optimize this code a good bit. This
> > really shouldn't end up with this mouch code.
>
> Yes, with the idea mentioned in [1] (code not shared yet), I end up with:
>
> Dump of assembler code for function waitEventIncrementCounter:
> => 0x000000000091b320 <+0>: mov %edi,%eax
> 0x000000000091b322 <+2>: and $0xff000000,%eax
> 0x000000000091b327 <+7>: jne 0x91b330 <waitEventIncrementCounter+16>
> 0x000000000091b329 <+9>: test %di,%di
> 0x000000000091b32c <+12>: jne 0x91b330 <waitEventIncrementCounter+16>
> 0x000000000091b32e <+14>: ret
> 0x000000000091b32f <+15>: nop
> 0x000000000091b330 <+16>: cmp $0x1000000,%eax
> 0x000000000091b335 <+21>: jne 0x91b33d <waitEventIncrementCounter+29>
> 0x000000000091b337 <+23>: cmp $0x5e,%di
> 0x000000000091b33b <+27>: ja 0x91b32e <waitEventIncrementCounter+14>
> 0x000000000091b33d <+29>: cmp $0x7000000,%eax
> 0x000000000091b342 <+34>: sete %cl
> 0x000000000091b345 <+37>: test %di,%di
> 0x000000000091b348 <+40>: setne %dl
> 0x000000000091b34b <+43>: test %dl,%cl
> 0x000000000091b34d <+45>: jne 0x91b32e <waitEventIncrementCounter+14>
> 0x000000000091b34f <+47>: cmp $0xb000000,%eax
> 0x000000000091b354 <+52>: je 0x91b32e <waitEventIncrementCounter+14>
> 0x000000000091b356 <+54>: mov %edi,%eax
> 0x000000000091b358 <+56>: movzwl %di,%edi
> 0x000000000091b35b <+59>: shr $0x18,%eax
> 0x000000000091b35e <+62>: mov 0xe4e9c0(,%rax,8),%rax
> 0x000000000091b366 <+70>: movb $0x1,0x5603f3(%rip) # 0xe7b760 <have_wait_event_stats>
> 0x000000000091b36d <+77>: mov 0x8(%rax),%rax
> 0x000000000091b371 <+81>: addq $0x1,(%rax,%rdi,8)
> 0x000000000091b376 <+86>: ret

That's still way too many jumps.

> That looks better before the first branch (could be done in v1 too) as it uses
> registers only but looks worse when it's time to increment the counter while
> the code is much simpler:
>
> "
> WAIT_EVENT_INFO_DECODE(waitInfo, wait_event_info);
>
> AllWaitClasses[waitInfo.classId]->pendingCounts[eventId]++;
> "

Too many indirections. The increment should be doable without needing to
dereference intermediary memory locations.

Greetings,

Andres Freund