From 18cd15e706ac1f2d6b1c49847a82774ca143352f Mon Sep 17 00:00:00 2001 From: Melanie Plageman Date: Wed, 12 Mar 2025 11:33:08 -0400 Subject: Add connection establishment duration logging Add log_connections option 'setup_durations' which logs durations of several key parts of connection establishment and backend setup. For an incoming connection, starting from when the postmaster gets a socket from accept() and ending when the forked child backend is first ready for query, there are multiple steps that could each take longer than expected due to external factors. This logging provides visibility into authentication and fork duration as well as the end-to-end connection establishment and backend initialization time. To make this portable, the timings captured in the postmaster (socket creation time, fork initiation time) are passed through the BackendStartupData. Author: Melanie Plageman Reviewed-by: Bertrand Drouvot Reviewed-by: Fujii Masao Reviewed-by: Daniel Gustafsson Reviewed-by: Jacob Champion Reviewed-by: Jelte Fennema-Nio Reviewed-by: Guillaume Lelarge Discussion: https://postgr.es/m/flat/CAAKRu_b_smAHK0ZjrnL5GRxnAVWujEXQWpLXYzGbmpcZd3nLYw%40mail.gmail.com --- src/backend/tcop/postgres.c | 33 +++++++++++++++++++++++++++++++++ 1 file changed, 33 insertions(+) (limited to 'src/backend/tcop/postgres.c') diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c index 947ffb40421..55ab2da299b 100644 --- a/src/backend/tcop/postgres.c +++ b/src/backend/tcop/postgres.c @@ -66,6 +66,7 @@ #include "storage/proc.h" #include "storage/procsignal.h" #include "storage/sinval.h" +#include "tcop/backend_startup.h" #include "tcop/fastpath.h" #include "tcop/pquery.h" #include "tcop/tcopprot.h" @@ -4607,6 +4608,38 @@ PostgresMain(const char *dbname, const char *username) /* Report any recently-changed GUC options */ ReportChangedGUCOptions(); + /* + * The first time this backend is ready for query, log the + * durations of the different components of connection + * establishment and setup. + */ + if (conn_timing.ready_for_use == TIMESTAMP_MINUS_INFINITY && + (log_connections & LOG_CONNECTION_SETUP_DURATIONS) && + IsExternalConnectionBackend(MyBackendType)) + { + uint64 total_duration, + fork_duration, + auth_duration; + + conn_timing.ready_for_use = GetCurrentTimestamp(); + + total_duration = + TimestampDifferenceMicroseconds(conn_timing.socket_create, + conn_timing.ready_for_use); + fork_duration = + TimestampDifferenceMicroseconds(conn_timing.fork_start, + conn_timing.fork_end); + auth_duration = + TimestampDifferenceMicroseconds(conn_timing.auth_start, + conn_timing.auth_end); + + ereport(LOG, + errmsg("connection ready: setup total=%.3f ms, fork=%.3f ms, authentication=%.3f ms", + (double) total_duration / NS_PER_US, + (double) fork_duration / NS_PER_US, + (double) auth_duration / NS_PER_US)); + } + ReadyForQuery(whereToSendOutput); send_ready_for_query = false; } -- cgit v1.2.3