Log connection establishment timings

From: Melanie Plageman <melanieplageman(at)gmail(dot)com>
To: Pg Hackers <pgsql-hackers(at)postgresql(dot)org>
Cc: Daniel Gustafsson <daniel(at)yesql(dot)se>, andrey(dot)chudnovskiy(at)microsoft(dot)com, Jelte Fennema-Nio <postgres(at)jeltef(dot)nl>
Subject: Log connection establishment timings
Date: 2024-12-16 21:00:02
Message-ID: CAAKRu_b_smAHK0ZjrnL5GRxnAVWujEXQWpLXYzGbmpcZd3nLYw@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-hackers

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.

- Melanie

Attachment Content-Type Size
v1-0001-Add-connection-establishment-duration-logging.patch text/x-patch 12.0 KB

Responses

Browse pgsql-hackers by date

  From Date Subject
Next Message David Rowley 2024-12-16 21:20:46 Re: Pg18 Recursive Crash
Previous Message Tom Lane 2024-12-16 20:55:27 Re: Improving default column names/aliases of subscript text expressions