Re: Log connection establishment timings

Hello,

Le lun. 16 déc. 2024 à 22:00, Melanie Plageman <melanieplageman(at)gmail(dot)com>
a écrit :

> Hi,
>
> Users wishing to debug slow connection establishment have little
> visibility into which steps take the most time. We don't expose any
> stats and none of the logging includes durations.
>
> The attached patch logs durations for authentication, forking the
> Postgres backend, and the end-to-end connection establishment duration
> starting from when the postmaster calls accept() and ending the first
> time the forked backend is ready for query.
>
> As an example of how this could be useful, I artificially slowed down
> authentication and you can see that that is now visible in logs:
>
> LOG: backend ready for query. pid=86341. socket=10. connection
> establishment times (ms): total: 8, fork: 0, authentication: 0
> LOG: backend ready for query. pid=86794. socket=10. connection
> establishment times (ms): total: 108, fork: 0, authentication: 100
>
> Two notes on implementation:
>
> To make this portable, the timestamps captured in the postmaster
> (socket creation time, fork initiation time) are passed through the
> ClientSocket and BackendStartupData structures instead of simply saved
> in backend local memory inherited by the child process.
>
> Secondly, I used TimestampTz for the times, but it is pretty unclear
> to me when instr_time should be used vs TimestampTz for such things.
> instr_time says it is more portable, but there are all sorts of places
> that use TimestampTz that would probably need to be portable.
> Also, INSTR_TIME_SUBTRACT() isn't overflow safe, which must be because
> the actual data type of ticks is platform dependent and so the caller
> is responsible for not passing it values that would overflow when
> subtracted.
>
>
Just a quick note. I like this patch a lot and it would help to diagnose
some situations our customers may have. I tried the patch on my laptop, and
it works fine. I'll find some time to read the code as well, but in the
meantime, this looks like a nice thing to have in PostgreSQL.

Thanks Melanie.

--
Guillaume.