Thanks for the continued review!
On Wed, Feb 26, 2025 at 2:41 AM Bertrand Drouvot
<bertranddrouvot...@gmail.com> wrote:
>
> On Wed, Feb 26, 2025 at 01:46:19PM +0900, Fujii Masao wrote:
> >
> > With the current patch, when log_connections is enabled, the connection
> > time is always
> > captured, and which might introduce performance overhead. No? Some users
> > who enable
> > log_connections may not want this extra detail and want to avoid such
> > overhead.
> > So, would it make sense to extend log_connections with a new option like
> > "timing" and
> > log the connection time only when "timing" is specified?
>
> +1, I also think it's a good idea to let users decide if they want the timing
> measurement overhead (and it's common practice with track_io_timing,
> track_wal_io_timing, the newly track_cost_delay_timing for example)
It seems to me like the extra timing collected and the one additional
log message isn't enough overhead to justify its own guc (for now).
> > Including the PID seems unnecessary since it's already available via
> > log_line_prefix with %p?
>
> Yeah, we would get things like:
>
> [1111539] LOG: connection received: host=[local]
> [1111539] LOG: connection authenticated: user="postgres" method=trust
> (/home/postgres/postgresql/pg_installed/pg18/data/pg_hba.conf:117)
> [1111539] LOG: connection authorized: user=postgres database=postgres
> application_name=psql
> [1111539] LOG: backend ready for query. pid=1111539. socket=9. connection
> establishment times (ms): total: 2, fork: 0, authentication: 0
>
> I also wonder if "backend ready for query" is worth it. Maybe something like:
>
> 2025-02-26 06:44:23.265 UTC [1111539] LOG: connection establishment times
> (ms): total: 2, fork: 0, authentication: 0
>
> would be good enough?
Yes, thank you. v5 attached in [1] changes the wording as you recommend..
> +typedef struct ConnectionTiming
> +{
> + instr_time fork_duration;
> + instr_time auth_duration;
> +} ConnectionTiming;
>
> As it's all about instr_time, I wonder if we could use an enum + array
> instead.
> That's probably just a matter of taste but that sounds more flexible to extend
> (should we want to add more timing in the future).
I think we can change it later if we add many more. For now I prefer
the clarity of accessing members by name. Especially because we don't
have any code yet that loops through all of them or anything like
that.
> +ConnectionTiming conn_timing = {0};
>
> There is no padding in ConnectionTiming and anyway we just access its fields
> so that's ok to initialize that way.
Yes, this properly zero initializes the struct. In fact it shouldn't
be needed since a global like this should be zero initialized. But all
of the globals defined above conn_timing zero initialize themselves,
so I thought I would be consistent with them.
> Add a few words in the log_connections GUC doc? (anyway we will have to if
> Fujii-san idea above about the timing is implemented)
I forgot to do this in v5 attached in [1]. Let me go ahead and do this next.
> + /* Calculate total fork duration in child backend for logging
> */
> + if (child_type == B_BACKEND)
> + {
> + INSTR_TIME_SET_CURRENT(conn_timing.fork_duration);
> + INSTR_TIME_SUBTRACT(conn_timing.fork_duration,
> +
> ((BackendStartupData *) startup_data)->fork_time);
> + }
> +
> /* Close the postmaster's sockets */
> ClosePostmasterPorts(child_type == B_LOGGER);
>
> @@ -618,6 +630,14 @@ SubPostmasterMain(int argc, char *argv[])
> /* Read in the variables file */
> read_backend_variables(argv[2], &startup_data, &startup_data_len);
>
> + /* Calculate total fork duration in child backend for logging */
> + if (child_type == B_BACKEND)
> + {
> + INSTR_TIME_SET_CURRENT(conn_timing.fork_duration);
> + INSTR_TIME_SUBTRACT(conn_timing.fork_duration,
> + ((BackendStartupData *)
> startup_data)->fork_time);
> + }
>
> worth to add a helper function to avoid code duplication?
I've added INSTR_TIME_GET_DURATION_SINCE(start_time). Which I like
because it seems generally useful. It does not however cut down on
LOC, so I'm somewhat on the fence.
- Melanie
[1]
https://www.postgresql.org/message-id/CAAKRu_Y9sgZAWCiQoHtpwx6Mv28fBGav5ztrWyeSrx%2BB%3DACN6g%40mail.gmail.com
