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.
