On 26/02/2025 08:41, Bertrand Drouvot wrote:
Hi,
On Wed, Feb 26, 2025 at 01:46:19PM +0900, Fujii Masao wrote:
On 2025/02/26 6:36, Melanie Plageman wrote:
On Tue, Feb 25, 2025 at 3:23 PM Melanie Plageman
<melanieplage...@gmail.com> wrote:
Thanks for doing this! I have implemented your suggestion in attached v3.
Thanks for the new patch version!
+1
+ /* Capture time Postmaster initiates fork for logging */
+ if (child_type == B_BACKEND)
+ INSTR_TIME_SET_CURRENT(((BackendStartupData *)
startup_data)->fork_time);
When log_connections is enabled, walsender connections are also logged.
However, with the patch, it seems the connection time for walsenders isn't
captured.
Is this intentional?
Good point. I'm tempted to say that it should also be, specially because a
connection done as "psql replication=database" is of "walsender" backend type
and
would not be reported.
Agreed.
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)
track_connection_delay_timing ? I'm fine with this, but I'm a bit afraid
that it will lead us to an awful lot of GUCs for simple things.
+ ereport(LOG,
+ errmsg("backend ready for query.
pid=%d. socket=%d. connection establishment times (ms): total: %ld, fork: %ld,
authentication: %ld",
+ MyProcPid,
+ (int)
MyClientSocket->sock,
Why expose the socket's file descriptor? I'm not sure how users would use that
information.
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?
Sounds definitely better to me.
A few random comments:
=== 1
+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).
=== 2
+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.
=== 3
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)
=== 4
+ /* 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?
Regards,
--
Guillaume Lelarge
Consultant
https://dalibo.com
