MIME-Version: 1.0
References: <CAAKRu_b_smAHK0ZjrnL5GRxnAVWujEXQWpLXYzGbmpcZd3nLYw@mail.gmail.com>
 <CAECtzeW3bFOT8v_th9hu6O9c0p+yNkD0ceBneWOtXYcwVd73rA@mail.gmail.com>
 <Z45lUorFBcmCKxp7@ip-10-97-1-34.eu-west-3.compute.internal>
 <CAAKRu_YrNsA7-v5L9d318XZu+tPqcxp+ctCGy2EGYrSt69ON=A@mail.gmail.com>
 <CAAKRu_aV+B2yLpkcfh06tJV7XQPodjasxQ=XKh+MjD8ixkXwrA@mail.gmail.com>
 <65fe2d68-a214-40f0-80a8-56ca7323ad5c@oss.nttdata.com> <Z77Fxf49c+LIW74a@ip-10-97-1-34.eu-west-3.compute.internal>
In-Reply-To: <Z77Fxf49c+LIW74a@ip-10-97-1-34.eu-west-3.compute.internal>
From: Melanie Plageman <melanieplageman@gmail.com>
Date: Wed, 26 Feb 2025 13:45:39 -0500
Message-ID: <CAAKRu_bWRipJ2HA8cwvxrZOhSpvpPLkvhcBHecXBx8_wS4cjQQ@mail.gmail.com>
Subject: Re: Log connection establishment timings
To: Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
Cc: Fujii Masao <masao.fujii@oss.nttdata.com>, 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>
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable
Archived-At: <https://www.postgresql.org/message-id/CAAKRu_bWRipJ2HA8cwvxrZOhSpvpPLkvhcBHecXBx8_wS4cjQQ%40mail.gmail.com>
Precedence: bulk

Thanks for the continued review!

On Wed, Feb 26, 2025 at 2:41=E2=80=AFAM Bertrand Drouvot
<bertranddrouvot.pg@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 user=
s who enable
> > log_connections may not want this extra detail and want to avoid such o=
verhead.
> > So, would it make sense to extend log_connections with a new option lik=
e "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 ti=
ming
> 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 lo=
g_line_prefix with %p?
>
> Yeah, we would get things like:
>
> [1111539] LOG:  connection received: host=3D[local]
> [1111539] LOG:  connection authenticated: user=3D"postgres" method=3Dtrus=
t (/home/postgres/postgresql/pg_installed/pg18/data/pg_hba.conf:117)
> [1111539] LOG:  connection authorized: user=3Dpostgres database=3Dpostgre=
s application_name=3Dpsql
> [1111539] LOG:  backend ready for query. pid=3D1111539. socket=3D9. conne=
ction establishment times (ms): total: 2, fork: 0, authentication: 0
>
> I also wonder if "backend ready for query" is worth it. Maybe something l=
ike:
>
> 2025-02-26 06:44:23.265 UTC [1111539] LOG:  connection establishment time=
s (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 in=
stead.
> That's probably just a matter of taste but that sounds more flexible to e=
xtend
> (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 =3D {0};
>
> There is no padding in ConnectionTiming and anyway we just access its fie=
lds
> 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 i=
f
> 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 log=
ging */
> +               if (child_type =3D=3D B_BACKEND)
> +               {
> +                       INSTR_TIME_SET_CURRENT(conn_timing.fork_duration)=
;
> +                       INSTR_TIME_SUBTRACT(conn_timing.fork_duration,
> +                                                               ((Backend=
StartupData *) startup_data)->fork_time);
> +               }
> +
>                 /* Close the postmaster's sockets */
>                 ClosePostmasterPorts(child_type =3D=3D 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 =3D=3D B_BACKEND)
> +       {
> +               INSTR_TIME_SET_CURRENT(conn_timing.fork_duration);
> +               INSTR_TIME_SUBTRACT(conn_timing.fork_duration,
> +                               ((BackendStartupData *) startup_data)->fo=
rk_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_Y9sgZAWCiQoHtpwx6Mv28fBGav=
5ztrWyeSrx%2BB%3DACN6g%40mail.gmail.com