Horton

Re: Log connection establishment timings

Melanie Plageman <melanieplageman@gmail.com>

View thread View on postgr.es
From: Melanie Plageman <melanieplageman@gmail.com>
To: Fujii Masao <masao.fujii@oss.nttdata.com>
Cc: Bertrand Drouvot <bertranddrouvot.pg@gmail.com>, Andres Freund <andres@anarazel.de>, Guillaume Lelarge <guillaume@lelarge.info>, Pg Hackers <pgsql-hackers@postgresql.org>, Daniel Gustafsson <daniel@yesql.se>, andrey.chudnovskiy@microsoft.com, Jelte Fennema-Nio <postgres@jeltef.nl>, Jacob Champion <jacob.champion@enterprisedb.com>
Date: 2025-03-04T23:34:47Z
Lists: pgsql-hackers 
On Mon, Mar 3, 2025 at 11:45 PM Fujii Masao <masao.fujii@oss.nttdata.com> wrote:
>
> When log_connection is empty string in postgresql.conf and I ran
> "psql -d "options=-clog_connections=all"", I got the following log message.
> You can see the total duration in this message is unexpected.
> It looks like this happens because creation_time wasn’t collected,
> as log_connections was empty before the fork.
>
>      LOG:  connection establishment times (ms): total: 1148052469, fork: 0, authentication: 0

Wow, yes, thanks for catching that. I didn't remember that you could
pass startup options like that. For that example,
process_startup_options() actually happens so late that we do not have
the intended value of log_connections until after we've already taken
all of the timings. As such, I propose we take those measurements
unconditionally (since we established they aren't too expensive when
compared to the cost of actually forking the backend) and then only
emit the message if log_connections is "timings". We are guaranteed to
have the intended value of log_connections by the time we are
ready-for-query. I've implemented this in [1].

- Melanie

[1] https://www.postgresql.org/message-id/CAAKRu_aoerKAOYKkc7-JGq2bixrYTbViK_7EeLNhFUGoT_omFw%40mail.gmail.com

Commits

  1. Replace deprecated log_connections values in docs and tests