public inbox for [email protected]
help / color / mirror / Atom feed[PATCH v4 5/7] Row pattern recognition patch (docs).
24+ messages / 6 participants
[nested] [flat]
* [PATCH v4 5/7] Row pattern recognition patch (docs).
@ 2023-08-09 07:56 Tatsuo Ishii <[email protected]>
0 siblings, 0 replies; 24+ messages in thread
From: Tatsuo Ishii @ 2023-08-09 07:56 UTC (permalink / raw)
---
doc/src/sgml/advanced.sgml | 52 ++++++++++++++++++++++++++++++++++
doc/src/sgml/func.sgml | 54 ++++++++++++++++++++++++++++++++++++
doc/src/sgml/ref/select.sgml | 38 +++++++++++++++++++++++--
3 files changed, 142 insertions(+), 2 deletions(-)
diff --git a/doc/src/sgml/advanced.sgml b/doc/src/sgml/advanced.sgml
index 755c9f1485..eda3612822 100644
--- a/doc/src/sgml/advanced.sgml
+++ b/doc/src/sgml/advanced.sgml
@@ -537,6 +537,58 @@ WHERE pos < 3;
<literal>rank</literal> less than 3.
</para>
+ <para>
+ Row pattern common syntax can be used with row pattern common syntax to
+ perform row pattern recognition in a query. Row pattern common syntax
+ includes two sub clauses. <literal>DEFINE</literal> defines definition
+ variables along with an expression. The expression must be a logical
+ expression, which means it must
+ return <literal>TRUE</literal>, <literal>FALSE</literal>
+ or <literal>NULL</literal>. Moreover if the expression comprises a column
+ reference, it must be the argument of <function>rpr</function>. An example
+ of <literal>DEFINE</literal> is as follows.
+
+<programlisting>
+DEFINE
+ LOWPRICE AS price <= 100,
+ UP AS price > PREV(price),
+ DOWN AS price < PREV(price)
+</programlisting>
+
+ Note that <function>PREV</function> returns price column in the previous
+ row if it's called in a context of row pattern recognition. So in the
+ second line means the definition variable "UP" is <literal>TRUE</literal>
+ when price column in the current row is greater than the price column in
+ the previous row. Likewise, "DOWN" is <literal>TRUE</literal> when when
+ price column in the current row is lower than the price column in the
+ previous row.
+ </para>
+ <para>
+ Once <literal>DEFINE</literal> exists, <literal>PATTERN</literal> can be
+ used. <literal>PATTERN</literal> defines a sequence of rows that satisfies
+ certain conditions. For example following <literal>PATTERN</literal>
+ defines that a row starts with the condition "LOWPRICE", then one or more
+ rows satisfy "UP" and finally one or more rows satisfy "DOWN". If a
+ sequence of rows found, rpr returns the column at the starting row.
+ Example of a <literal>SELECT</literal> using the <literal>DEFINE</literal>
+ and <literal>PATTERN</literal> clause is as follows.
+
+<programlisting>
+SELECT company, tdate, price, max(price) OVER w FROM stock
+ WINDOW w AS (
+ PARTITION BY company
+ ROWS BETWEEN CURRENT ROW AND UNBOUNDED FOLLOWING
+ AFTER MATCH SKIP PAST LAST ROW
+ INITIAL
+ PATTERN (LOWPRICE UP+ DOWN+)
+ DEFINE
+ LOWPRICE AS price <= 100,
+ UP AS price > PREV(price),
+ DOWN AS price < PREV(price)
+);
+</programlisting>
+ </para>
+
<para>
When a query involves multiple window functions, it is possible to write
out each one with a separate <literal>OVER</literal> clause, but this is
diff --git a/doc/src/sgml/func.sgml b/doc/src/sgml/func.sgml
index be2f54c914..6cda164522 100644
--- a/doc/src/sgml/func.sgml
+++ b/doc/src/sgml/func.sgml
@@ -21715,6 +21715,7 @@ SELECT count(*) FROM sometable;
returns <literal>NULL</literal> if there is no such row.
</para></entry>
</row>
+
</tbody>
</tgroup>
</table>
@@ -21754,6 +21755,59 @@ SELECT count(*) FROM sometable;
Other frame specifications can be used to obtain other effects.
</para>
+ <para>
+ Row pattern recognition navigation functions are listed in
+ <xref linkend="functions-rpr-navigation-table"/>. These functions
+ can be used to describe DEFINE clause of Row pattern recognition.
+ </para>
+
+ <table id="functions-rpr-navigation-table">
+ <title>Row Pattern Navigation Functions</title>
+ <tgroup cols="1">
+ <thead>
+ <row>
+ <entry role="func_table_entry"><para role="func_signature">
+ Function
+ </para>
+ <para>
+ Description
+ </para></entry>
+ </row>
+ </thead>
+
+ <tbody>
+ <row>
+ <entry role="func_table_entry"><para role="func_signature">
+ <indexterm>
+ <primary>prev</primary>
+ </indexterm>
+ <function>prev</function> ( <parameter>value</parameter> <type>anyelement</type> )
+ <returnvalue>anyelement</returnvalue>
+ </para>
+ <para>
+ Returns the column value at the previous row;
+ returns NULL if there is no previous row in the window frame.
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="func_table_entry"><para role="func_signature">
+ <indexterm>
+ <primary>next</primary>
+ </indexterm>
+ <function>next</function> ( <parameter>value</parameter> <type>anyelement</type> )
+ <returnvalue>anyelement</returnvalue>
+ </para>
+ <para>
+ Returns the column value at the next row;
+ returns NULL if there is no next row in the window frame.
+ </para></entry>
+ </row>
+
+ </tbody>
+ </tgroup>
+ </table>
+
<note>
<para>
The SQL standard defines a <literal>RESPECT NULLS</literal> or
diff --git a/doc/src/sgml/ref/select.sgml b/doc/src/sgml/ref/select.sgml
index 0ee0cc7e64..8d3becd57a 100644
--- a/doc/src/sgml/ref/select.sgml
+++ b/doc/src/sgml/ref/select.sgml
@@ -966,8 +966,8 @@ WINDOW <replaceable class="parameter">window_name</replaceable> AS ( <replaceabl
The <replaceable class="parameter">frame_clause</replaceable> can be one of
<synopsis>
-{ RANGE | ROWS | GROUPS } <replaceable>frame_start</replaceable> [ <replaceable>frame_exclusion</replaceable> ]
-{ RANGE | ROWS | GROUPS } BETWEEN <replaceable>frame_start</replaceable> AND <replaceable>frame_end</replaceable> [ <replaceable>frame_exclusion</replaceable> ]
+{ RANGE | ROWS | GROUPS } <replaceable>frame_start</replaceable> [ <replaceable>frame_exclusion</replaceable> ] [row_pattern_common_syntax]
+{ RANGE | ROWS | GROUPS } BETWEEN <replaceable>frame_start</replaceable> AND <replaceable>frame_end</replaceable> [ <replaceable>frame_exclusion</replaceable> ] [row_pattern_common_syntax]
</synopsis>
where <replaceable>frame_start</replaceable>
@@ -1074,6 +1074,40 @@ EXCLUDE NO OTHERS
a given peer group will be in the frame or excluded from it.
</para>
+ <para>
+ The
+ optional <replaceable class="parameter">row_pattern_common_syntax</replaceable>
+ defines the <firstterm>row pattern recognition condition</firstterm> for
+ this
+ window. <replaceable class="parameter">row_pattern_common_syntax</replaceable>
+ includes following subclauses. <literal>AFTER MATCH SKIP PAST LAST
+ ROW</literal> or <literal>AFTER MATCH SKIP TO NEXT ROW</literal> controls
+ how to proceed to next row position after a match
+ found. With <literal>AFTER MATCH SKIP PAST LAST ROW</literal> (the
+ default) next row position is next to the last row of previous match. On
+ the other hand, with <literal>AFTER MATCH SKIP TO NEXT ROW</literal> next
+ row position is always next to the last row of previous
+ match. <literal>DEFINE</literal> defines definition variables along with a
+ boolean expression. <literal>PATTERN</literal> defines a sequence of rows
+ that satisfies certain conditions using variables defined
+ in <literal>DEFINE</literal> clause. If the variable is not defined in
+ the <literal>DEFINE</literal> clause, it is implicitly assumed
+ following is defined in the <literal>DEFINE</literal> clause.
+
+<synopsis>
+<literal>variable_name</literal> AS TRUE
+</synopsis>
+
+ Note that the maximu number of variables defined
+ in <literal>DEFINE</literal> clause is 26.
+
+<synopsis>
+[ AFTER MATCH SKIP PAST LAST ROW | AFTER MATCH SKIP TO NEXT ROW ]
+PATTERN <replaceable class="parameter">pattern_variable_name</replaceable>[+] [, ...]
+DEFINE <replaceable class="parameter">definition_varible_name</replaceable> AS <replaceable class="parameter">expression</replaceable> [, ...]
+</synopsis>
+ </para>
+
<para>
The purpose of a <literal>WINDOW</literal> clause is to specify the
behavior of <firstterm>window functions</firstterm> appearing in the query's
--
2.25.1
----Next_Part(Wed_Aug__9_17_41_12_2023_134)--
Content-Type: Text/X-Patch; charset=us-ascii
Content-Transfer-Encoding: 7bit
Content-Disposition: inline;
filename="v4-0006-Row-pattern-recognition-patch-tests.patch"
^ permalink raw reply [nested|flat] 24+ messages in thread
* Re: Log connection establishment timings
@ 2025-02-25 20:23 Melanie Plageman <[email protected]>
2025-02-25 21:36 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
0 siblings, 1 reply; 24+ messages in thread
From: Melanie Plageman @ 2025-02-25 20:23 UTC (permalink / raw)
To: Bertrand Drouvot <[email protected]>; +Cc: Guillaume Lelarge <[email protected]>; pgsql-hackers; Daniel Gustafsson <[email protected]>; [email protected]; Jelte Fennema-Nio <[email protected]>
Thanks for taking a look!
On Mon, Jan 20, 2025 at 10:01 AM Bertrand Drouvot
<[email protected]> wrote:
>
> The patch needed a rebase due to 34486b6092e. I did it in v2 attached (it's
> a minor rebase due to the AmRegularBackendProcess() introduction in miscadmin.h).
>
> v2 could rely on AmRegularBackendProcess() instead of AmClientBackendProcess()
> but I kept it with AmClientBackendProcess() to reduce "my" changes as compared to
> v1.
Thanks for doing this! I have implemented your suggestion in attached v3.
> Regarding the TimestampTz vs instr_time choice, we have things like:
< -- snip -- >
> So with TimestampTz, we would:
>
> 1. return 0 if we moved the time backward
> 2. provide an inflated duration including the time jump (if the time move
> forward).
>
> But with instr_time (and on systems that support CLOCK_MONOTONIC) then
> pg_clock_gettime_ns() should not be affected by system time change IIUC.
>
> Though time changes are "rare", given the fact that those metrics could provide
> "inaccurate" measurements during that particular moment (time change) then it
> might be worth considering instr_time instead for this particular metric.
Great point. This all makes sense. I've switched to using instr_time in v3.
- Melanie
Attachments:
[text/x-patch] v3-0001-Add-connection-establishment-duration-logging.patch (10.3K, ../../CAAKRu_YrNsA7-v5L9d318XZu+tPqcxp+ctCGy2EGYrSt69ON=A@mail.gmail.com/2-v3-0001-Add-connection-establishment-duration-logging.patch)
download | inline diff:
From 660e2f3846fd1af74956a45559da5ea17d5dbc92 Mon Sep 17 00:00:00 2001
From: Melanie Plageman <[email protected]>
Date: Tue, 25 Feb 2025 13:08:48 -0500
Subject: [PATCH v3] Add connection establishment duration logging
Add durations for several key parts of connection establishment when
log_connections is enabled.
For a new incoming conneciton, 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. Provide visibility into
authentication and fork duration as well as the end-to-end connection
establishment time with logging.
To make this portable, the timestamps captured in the postmaster (socket
creation time, fork initiation time) are passed through the ClientSocket
and BackendStartupData structures instead of simply saved in backend
local memory inherited by the child process.
Reviewed-by: Bertrand Drouvot <[email protected]>
Reviewed-by: Jelte Fennema-Nio <[email protected]>
Reviewed-by: Jacob Champion <[email protected]>
Discussion: https://postgr.es/m/flat/CAAKRu_b_smAHK0ZjrnL5GRxnAVWujEXQWpLXYzGbmpcZd3nLYw%40mail.gmail.com
---
src/backend/postmaster/launch_backend.c | 20 ++++++++++++++++++++
src/backend/postmaster/postmaster.c | 8 ++++++++
src/backend/tcop/postgres.c | 24 ++++++++++++++++++++++++
src/backend/utils/init/globals.c | 2 ++
src/backend/utils/init/postinit.c | 13 +++++++++++++
src/include/libpq/libpq-be.h | 2 ++
src/include/miscadmin.h | 2 ++
src/include/postmaster/postmaster.h | 7 +++++++
src/include/tcop/backend_startup.h | 1 +
src/tools/pgindent/typedefs.list | 1 +
10 files changed, 80 insertions(+)
diff --git a/src/backend/postmaster/launch_backend.c b/src/backend/postmaster/launch_backend.c
index 47375e5bfaa..37b31069120 100644
--- a/src/backend/postmaster/launch_backend.c
+++ b/src/backend/postmaster/launch_backend.c
@@ -232,6 +232,10 @@ postmaster_child_launch(BackendType child_type, int child_slot,
Assert(IsPostmasterEnvironment && !IsUnderPostmaster);
+ /* Capture time Postmaster initiates fork for logging */
+ if (child_type == B_BACKEND)
+ INSTR_TIME_SET_CURRENT(((BackendStartupData *) startup_data)->fork_time);
+
#ifdef EXEC_BACKEND
pid = internal_forkexec(child_process_kinds[child_type].name, child_slot,
startup_data, startup_data_len, client_sock);
@@ -240,6 +244,14 @@ postmaster_child_launch(BackendType child_type, int child_slot,
pid = fork_process();
if (pid == 0) /* child */
{
+ /* 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);
+ }
+
/* Close the postmaster's sockets (as soon as we know them) */
ClosePostmasterPorts(child_type == B_LOGGER);
diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index 5dd3b6a4fd4..880f491a9f7 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -1685,7 +1685,14 @@ ServerLoop(void)
ClientSocket s;
if (AcceptConnection(events[i].fd, &s) == STATUS_OK)
+ {
+ /*
+ * Capture time that Postmaster got a socket from accept
+ * (for logging connection establishment duration)
+ */
+ INSTR_TIME_SET_CURRENT(s.creation_time);
BackendStartup(&s);
+ }
/* We no longer need the open socket in this process */
if (s.sock != PGINVALID_SOCKET)
@@ -3511,6 +3518,7 @@ BackendStartup(ClientSocket *client_sock)
/* Pass down canAcceptConnections state */
startup_data.canAcceptConnections = cac;
+ INSTR_TIME_SET_ZERO(startup_data.fork_time);
bn->rw = NULL;
/* Hasn't asked to be notified about any bgworkers yet */
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index f2f75aa0f88..abd7e648657 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -4153,6 +4153,7 @@ PostgresMain(const char *dbname, const char *username)
volatile bool send_ready_for_query = true;
volatile bool idle_in_transaction_timeout_enabled = false;
volatile bool idle_session_timeout_enabled = false;
+ bool reported_first_ready_for_query = false;
Assert(dbname != NULL);
Assert(username != NULL);
@@ -4607,6 +4608,29 @@ 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.
+ */
+ if (!reported_first_ready_for_query &&
+ Log_connections && AmRegularBackendProcess())
+ {
+ instr_time total_duration;
+
+ INSTR_TIME_SET_CURRENT(total_duration);
+ INSTR_TIME_SUBTRACT(total_duration, MyClientSocket->creation_time);
+
+ 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,
+ (long int) INSTR_TIME_GET_MILLISEC(total_duration),
+ (long int) INSTR_TIME_GET_MILLISEC(conn_timing.fork_duration),
+ (long int) INSTR_TIME_GET_MILLISEC(conn_timing.auth_duration)));
+
+ reported_first_ready_for_query = true;
+ }
ReadyForQuery(whereToSendOutput);
send_ready_for_query = false;
}
diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c
index b844f9fdaef..3c7b14dd57d 100644
--- a/src/backend/utils/init/globals.c
+++ b/src/backend/utils/init/globals.c
@@ -43,6 +43,8 @@ volatile uint32 InterruptHoldoffCount = 0;
volatile uint32 QueryCancelHoldoffCount = 0;
volatile uint32 CritSectionCount = 0;
+ConnectionTiming conn_timing = {0};
+
int MyProcPid;
pg_time_t MyStartTime;
TimestampTz MyStartTimestamp;
diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index 318600d6d02..c262849b9ac 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -190,9 +190,15 @@ GetDatabaseTupleByOid(Oid dboid)
static void
PerformAuthentication(Port *port)
{
+ instr_time auth_start_time;
+
/* This should be set already, but let's make sure */
ClientAuthInProgress = true; /* limit visibility of log messages */
+ /* Capture authentication start time for logging */
+ if (AmRegularBackendProcess())
+ INSTR_TIME_SET_CURRENT(auth_start_time);
+
/*
* In EXEC_BACKEND case, we didn't inherit the contents of pg_hba.conf
* etcetera from the postmaster, and have to load them ourselves.
@@ -251,6 +257,13 @@ PerformAuthentication(Port *port)
*/
disable_timeout(STATEMENT_TIMEOUT, false);
+ /* Calculate authentication duration for logging */
+ if (AmRegularBackendProcess())
+ {
+ INSTR_TIME_SET_CURRENT(conn_timing.auth_duration);
+ INSTR_TIME_SUBTRACT(conn_timing.auth_duration, auth_start_time);
+ }
+
if (Log_connections)
{
StringInfoData logmsg;
diff --git a/src/include/libpq/libpq-be.h b/src/include/libpq/libpq-be.h
index 7fe92b15477..b16ad69efff 100644
--- a/src/include/libpq/libpq-be.h
+++ b/src/include/libpq/libpq-be.h
@@ -58,6 +58,7 @@ typedef struct
#include "datatype/timestamp.h"
#include "libpq/hba.h"
#include "libpq/pqcomm.h"
+#include "portability/instr_time.h"
/*
@@ -252,6 +253,7 @@ typedef struct ClientSocket
{
pgsocket sock; /* File descriptor */
SockAddr raddr; /* remote addr (client) */
+ instr_time creation_time;
} ClientSocket;
#ifdef USE_SSL
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index a2b63495eec..9dd18a2c74f 100644
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -178,6 +178,8 @@ extern PGDLLIMPORT int MaxConnections;
extern PGDLLIMPORT int max_worker_processes;
extern PGDLLIMPORT int max_parallel_workers;
+extern PGDLLIMPORT struct ConnectionTiming conn_timing;
+
extern PGDLLIMPORT int commit_timestamp_buffers;
extern PGDLLIMPORT int multixact_member_buffers;
extern PGDLLIMPORT int multixact_offset_buffers;
diff --git a/src/include/postmaster/postmaster.h b/src/include/postmaster/postmaster.h
index b6a3f275a1b..71a3f5f644d 100644
--- a/src/include/postmaster/postmaster.h
+++ b/src/include/postmaster/postmaster.h
@@ -15,6 +15,7 @@
#include "lib/ilist.h"
#include "miscadmin.h"
+#include "portability/instr_time.h"
/*
* A struct representing an active postmaster child process. This is used
@@ -126,6 +127,12 @@ extern PMChild *AllocDeadEndChild(void);
extern bool ReleasePostmasterChildSlot(PMChild *pmchild);
extern PMChild *FindPostmasterChildByPid(int pid);
+typedef struct ConnectionTiming
+{
+ instr_time fork_duration;
+ instr_time auth_duration;
+} ConnectionTiming;
+
/*
* These values correspond to the special must-be-first options for dispatching
* to various subprograms. parse_dispatch_option() can be used to convert an
diff --git a/src/include/tcop/backend_startup.h b/src/include/tcop/backend_startup.h
index 73285611203..d5d13bf140a 100644
--- a/src/include/tcop/backend_startup.h
+++ b/src/include/tcop/backend_startup.h
@@ -37,6 +37,7 @@ typedef enum CAC_state
typedef struct BackendStartupData
{
CAC_state canAcceptConnections;
+ instr_time fork_time;
} BackendStartupData;
extern void BackendMain(const void *startup_data, size_t startup_data_len) pg_attribute_noreturn();
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index 1649f5e1011..34d2daa0c9b 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -484,6 +484,7 @@ ConnParams
ConnStatusType
ConnType
ConnectionStateEnum
+ConnectionTiming
ConsiderSplitContext
Const
ConstrCheck
--
2.34.1
^ permalink raw reply [nested|flat] 24+ messages in thread
* Re: Log connection establishment timings
2025-02-25 20:23 Re: Log connection establishment timings Melanie Plageman <[email protected]>
@ 2025-02-25 21:36 ` Melanie Plageman <[email protected]>
2025-02-26 04:46 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
0 siblings, 1 reply; 24+ messages in thread
From: Melanie Plageman @ 2025-02-25 21:36 UTC (permalink / raw)
To: Bertrand Drouvot <[email protected]>; +Cc: Guillaume Lelarge <[email protected]>; pgsql-hackers; Daniel Gustafsson <[email protected]>; [email protected]; Jelte Fennema-Nio <[email protected]>; Jacob Champion <[email protected]>
On Tue, Feb 25, 2025 at 3:23 PM Melanie Plageman
<[email protected]> wrote:
>
> Thanks for doing this! I have implemented your suggestion in attached v3.
I missed an include in the EXEC_BACKEND not defined case. attached v4
is fixed up.
- Melanie
Attachments:
[text/x-patch] v4-0001-Add-connection-establishment-duration-logging.patch (10.4K, ../../CAAKRu_aV+B2yLpkcfh06tJV7XQPodjasxQ=XKh+MjD8ixkXwrA@mail.gmail.com/2-v4-0001-Add-connection-establishment-duration-logging.patch)
download | inline diff:
From c493f0be7243bfe965d3493f07982ea1072d89b7 Mon Sep 17 00:00:00 2001
From: Melanie Plageman <[email protected]>
Date: Tue, 25 Feb 2025 13:08:48 -0500
Subject: [PATCH v4] Add connection establishment duration logging
Add durations for several key parts of connection establishment when
log_connections is enabled.
For a new incoming conneciton, 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. Provide visibility into
authentication and fork duration as well as the end-to-end connection
establishment time with logging.
To make this portable, the timestamps captured in the postmaster (socket
creation time, fork initiation time) are passed through the ClientSocket
and BackendStartupData structures instead of simply saved in backend
local memory inherited by the child process.
Reviewed-by: Bertrand Drouvot <[email protected]>
Reviewed-by: Jelte Fennema-Nio <[email protected]>
Reviewed-by: Jacob Champion <[email protected]>
Discussion: https://postgr.es/m/flat/CAAKRu_b_smAHK0ZjrnL5GRxnAVWujEXQWpLXYzGbmpcZd3nLYw%40mail.gmail.com
---
src/backend/postmaster/launch_backend.c | 20 ++++++++++++++++++++
src/backend/postmaster/postmaster.c | 8 ++++++++
src/backend/tcop/postgres.c | 24 ++++++++++++++++++++++++
src/backend/utils/init/globals.c | 2 ++
src/backend/utils/init/postinit.c | 13 +++++++++++++
src/include/libpq/libpq-be.h | 2 ++
src/include/miscadmin.h | 2 ++
src/include/postmaster/postmaster.h | 7 +++++++
src/include/tcop/backend_startup.h | 3 +++
src/tools/pgindent/typedefs.list | 1 +
10 files changed, 82 insertions(+)
diff --git a/src/backend/postmaster/launch_backend.c b/src/backend/postmaster/launch_backend.c
index 47375e5bfaa..37b31069120 100644
--- a/src/backend/postmaster/launch_backend.c
+++ b/src/backend/postmaster/launch_backend.c
@@ -232,6 +232,10 @@ postmaster_child_launch(BackendType child_type, int child_slot,
Assert(IsPostmasterEnvironment && !IsUnderPostmaster);
+ /* Capture time Postmaster initiates fork for logging */
+ if (child_type == B_BACKEND)
+ INSTR_TIME_SET_CURRENT(((BackendStartupData *) startup_data)->fork_time);
+
#ifdef EXEC_BACKEND
pid = internal_forkexec(child_process_kinds[child_type].name, child_slot,
startup_data, startup_data_len, client_sock);
@@ -240,6 +244,14 @@ postmaster_child_launch(BackendType child_type, int child_slot,
pid = fork_process();
if (pid == 0) /* child */
{
+ /* 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);
+ }
+
/* Close the postmaster's sockets (as soon as we know them) */
ClosePostmasterPorts(child_type == B_LOGGER);
diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index 5dd3b6a4fd4..880f491a9f7 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -1685,7 +1685,14 @@ ServerLoop(void)
ClientSocket s;
if (AcceptConnection(events[i].fd, &s) == STATUS_OK)
+ {
+ /*
+ * Capture time that Postmaster got a socket from accept
+ * (for logging connection establishment duration)
+ */
+ INSTR_TIME_SET_CURRENT(s.creation_time);
BackendStartup(&s);
+ }
/* We no longer need the open socket in this process */
if (s.sock != PGINVALID_SOCKET)
@@ -3511,6 +3518,7 @@ BackendStartup(ClientSocket *client_sock)
/* Pass down canAcceptConnections state */
startup_data.canAcceptConnections = cac;
+ INSTR_TIME_SET_ZERO(startup_data.fork_time);
bn->rw = NULL;
/* Hasn't asked to be notified about any bgworkers yet */
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index f2f75aa0f88..abd7e648657 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -4153,6 +4153,7 @@ PostgresMain(const char *dbname, const char *username)
volatile bool send_ready_for_query = true;
volatile bool idle_in_transaction_timeout_enabled = false;
volatile bool idle_session_timeout_enabled = false;
+ bool reported_first_ready_for_query = false;
Assert(dbname != NULL);
Assert(username != NULL);
@@ -4607,6 +4608,29 @@ 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.
+ */
+ if (!reported_first_ready_for_query &&
+ Log_connections && AmRegularBackendProcess())
+ {
+ instr_time total_duration;
+
+ INSTR_TIME_SET_CURRENT(total_duration);
+ INSTR_TIME_SUBTRACT(total_duration, MyClientSocket->creation_time);
+
+ 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,
+ (long int) INSTR_TIME_GET_MILLISEC(total_duration),
+ (long int) INSTR_TIME_GET_MILLISEC(conn_timing.fork_duration),
+ (long int) INSTR_TIME_GET_MILLISEC(conn_timing.auth_duration)));
+
+ reported_first_ready_for_query = true;
+ }
ReadyForQuery(whereToSendOutput);
send_ready_for_query = false;
}
diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c
index b844f9fdaef..3c7b14dd57d 100644
--- a/src/backend/utils/init/globals.c
+++ b/src/backend/utils/init/globals.c
@@ -43,6 +43,8 @@ volatile uint32 InterruptHoldoffCount = 0;
volatile uint32 QueryCancelHoldoffCount = 0;
volatile uint32 CritSectionCount = 0;
+ConnectionTiming conn_timing = {0};
+
int MyProcPid;
pg_time_t MyStartTime;
TimestampTz MyStartTimestamp;
diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index 318600d6d02..c262849b9ac 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -190,9 +190,15 @@ GetDatabaseTupleByOid(Oid dboid)
static void
PerformAuthentication(Port *port)
{
+ instr_time auth_start_time;
+
/* This should be set already, but let's make sure */
ClientAuthInProgress = true; /* limit visibility of log messages */
+ /* Capture authentication start time for logging */
+ if (AmRegularBackendProcess())
+ INSTR_TIME_SET_CURRENT(auth_start_time);
+
/*
* In EXEC_BACKEND case, we didn't inherit the contents of pg_hba.conf
* etcetera from the postmaster, and have to load them ourselves.
@@ -251,6 +257,13 @@ PerformAuthentication(Port *port)
*/
disable_timeout(STATEMENT_TIMEOUT, false);
+ /* Calculate authentication duration for logging */
+ if (AmRegularBackendProcess())
+ {
+ INSTR_TIME_SET_CURRENT(conn_timing.auth_duration);
+ INSTR_TIME_SUBTRACT(conn_timing.auth_duration, auth_start_time);
+ }
+
if (Log_connections)
{
StringInfoData logmsg;
diff --git a/src/include/libpq/libpq-be.h b/src/include/libpq/libpq-be.h
index 7fe92b15477..b16ad69efff 100644
--- a/src/include/libpq/libpq-be.h
+++ b/src/include/libpq/libpq-be.h
@@ -58,6 +58,7 @@ typedef struct
#include "datatype/timestamp.h"
#include "libpq/hba.h"
#include "libpq/pqcomm.h"
+#include "portability/instr_time.h"
/*
@@ -252,6 +253,7 @@ typedef struct ClientSocket
{
pgsocket sock; /* File descriptor */
SockAddr raddr; /* remote addr (client) */
+ instr_time creation_time;
} ClientSocket;
#ifdef USE_SSL
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index a2b63495eec..9dd18a2c74f 100644
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -178,6 +178,8 @@ extern PGDLLIMPORT int MaxConnections;
extern PGDLLIMPORT int max_worker_processes;
extern PGDLLIMPORT int max_parallel_workers;
+extern PGDLLIMPORT struct ConnectionTiming conn_timing;
+
extern PGDLLIMPORT int commit_timestamp_buffers;
extern PGDLLIMPORT int multixact_member_buffers;
extern PGDLLIMPORT int multixact_offset_buffers;
diff --git a/src/include/postmaster/postmaster.h b/src/include/postmaster/postmaster.h
index b6a3f275a1b..71a3f5f644d 100644
--- a/src/include/postmaster/postmaster.h
+++ b/src/include/postmaster/postmaster.h
@@ -15,6 +15,7 @@
#include "lib/ilist.h"
#include "miscadmin.h"
+#include "portability/instr_time.h"
/*
* A struct representing an active postmaster child process. This is used
@@ -126,6 +127,12 @@ extern PMChild *AllocDeadEndChild(void);
extern bool ReleasePostmasterChildSlot(PMChild *pmchild);
extern PMChild *FindPostmasterChildByPid(int pid);
+typedef struct ConnectionTiming
+{
+ instr_time fork_duration;
+ instr_time auth_duration;
+} ConnectionTiming;
+
/*
* These values correspond to the special must-be-first options for dispatching
* to various subprograms. parse_dispatch_option() can be used to convert an
diff --git a/src/include/tcop/backend_startup.h b/src/include/tcop/backend_startup.h
index 73285611203..deb59c78425 100644
--- a/src/include/tcop/backend_startup.h
+++ b/src/include/tcop/backend_startup.h
@@ -14,6 +14,8 @@
#ifndef BACKEND_STARTUP_H
#define BACKEND_STARTUP_H
+#include "portability/instr_time.h"
+
/* GUCs */
extern PGDLLIMPORT bool Trace_connection_negotiation;
@@ -37,6 +39,7 @@ typedef enum CAC_state
typedef struct BackendStartupData
{
CAC_state canAcceptConnections;
+ instr_time fork_time;
} BackendStartupData;
extern void BackendMain(const void *startup_data, size_t startup_data_len) pg_attribute_noreturn();
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index 1649f5e1011..34d2daa0c9b 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -484,6 +484,7 @@ ConnParams
ConnStatusType
ConnType
ConnectionStateEnum
+ConnectionTiming
ConsiderSplitContext
Const
ConstrCheck
--
2.34.1
^ permalink raw reply [nested|flat] 24+ messages in thread
* Re: Log connection establishment timings
2025-02-25 20:23 Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-25 21:36 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
@ 2025-02-26 04:46 ` Fujii Masao <[email protected]>
2025-02-26 07:41 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-26 18:37 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
0 siblings, 2 replies; 24+ messages in thread
From: Fujii Masao @ 2025-02-26 04:46 UTC (permalink / raw)
To: Melanie Plageman <[email protected]>; Bertrand Drouvot <[email protected]>; +Cc: Guillaume Lelarge <[email protected]>; pgsql-hackers; Daniel Gustafsson <[email protected]>; [email protected]; Jelte Fennema-Nio <[email protected]>; Jacob Champion <[email protected]>
On 2025/02/26 6:36, Melanie Plageman wrote:
> On Tue, Feb 25, 2025 at 3:23 PM Melanie Plageman
> <[email protected]> wrote:
>>
>> Thanks for doing this! I have implemented your suggestion in attached v3.
>
> I missed an include in the EXEC_BACKEND not defined case. attached v4
> is fixed up.
Thanks for updating the patch!
+ /* 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?
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?
+ 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?
Regards,
--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION
^ permalink raw reply [nested|flat] 24+ messages in thread
* Re: Log connection establishment timings
2025-02-25 20:23 Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-25 21:36 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-26 04:46 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
@ 2025-02-26 07:41 ` Bertrand Drouvot <[email protected]>
2025-02-26 13:22 ` Re: Log connection establishment timings Guillaume Lelarge <[email protected]>
2025-02-26 18:45 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
1 sibling, 2 replies; 24+ messages in thread
From: Bertrand Drouvot @ 2025-02-26 07:41 UTC (permalink / raw)
To: Fujii Masao <[email protected]>; +Cc: Melanie Plageman <[email protected]>; Guillaume Lelarge <[email protected]>; pgsql-hackers; Daniel Gustafsson <[email protected]>; [email protected]; Jelte Fennema-Nio <[email protected]>; Jacob Champion <[email protected]>
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
> > <[email protected]> wrote:
> > >
> > > Thanks for doing this! I have implemented your suggestion in attached v3.
Thanks for the new patch version!
> + /* 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.
> 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)
> + 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?
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,
--
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com
^ permalink raw reply [nested|flat] 24+ messages in thread
* Re: Log connection establishment timings
2025-02-25 20:23 Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-25 21:36 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-26 04:46 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
2025-02-26 07:41 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
@ 2025-02-26 13:22 ` Guillaume Lelarge <[email protected]>
1 sibling, 0 replies; 24+ messages in thread
From: Guillaume Lelarge @ 2025-02-26 13:22 UTC (permalink / raw)
To: [email protected]
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
>>> <[email protected]> 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
^ permalink raw reply [nested|flat] 24+ messages in thread
* Re: Log connection establishment timings
2025-02-25 20:23 Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-25 21:36 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-26 04:46 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
2025-02-26 07:41 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
@ 2025-02-26 18:45 ` Melanie Plageman <[email protected]>
2025-02-26 19:29 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-27 06:50 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
1 sibling, 2 replies; 24+ messages in thread
From: Melanie Plageman @ 2025-02-26 18:45 UTC (permalink / raw)
To: Bertrand Drouvot <[email protected]>; +Cc: Fujii Masao <[email protected]>; Guillaume Lelarge <[email protected]>; pgsql-hackers; Daniel Gustafsson <[email protected]>; [email protected]; Jelte Fennema-Nio <[email protected]>; Jacob Champion <[email protected]>
Thanks for the continued review!
On Wed, Feb 26, 2025 at 2:41 AM Bertrand Drouvot
<[email protected]> 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...
^ permalink raw reply [nested|flat] 24+ messages in thread
* Re: Log connection establishment timings
2025-02-25 20:23 Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-25 21:36 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-26 04:46 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
2025-02-26 07:41 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-26 18:45 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
@ 2025-02-26 19:29 ` Melanie Plageman <[email protected]>
1 sibling, 0 replies; 24+ messages in thread
From: Melanie Plageman @ 2025-02-26 19:29 UTC (permalink / raw)
To: Bertrand Drouvot <[email protected]>; +Cc: Fujii Masao <[email protected]>; Guillaume Lelarge <[email protected]>; pgsql-hackers; Daniel Gustafsson <[email protected]>; [email protected]; Jelte Fennema-Nio <[email protected]>; Jacob Champion <[email protected]>
On Wed, Feb 26, 2025 at 1:45 PM Melanie Plageman
<[email protected]> wrote:
>
> Thanks for the continued review!
>
> On Wed, Feb 26, 2025 at 2:41 AM Bertrand Drouvot
> <[email protected]> wrote:
>
> > 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.
I took a stab at this in attached v6. I feel that what I have is a bit
stilted, but I'm not sure how to fix it.
- Melanie
Attachments:
[text/x-patch] v6-0001-Add-connection-establishment-duration-logging.patch (12.1K, ../../CAAKRu_ZbwQcW_NbZG=5AvargFOQHNfQb1eu9ye+P7ZgibpYzFA@mail.gmail.com/2-v6-0001-Add-connection-establishment-duration-logging.patch)
download | inline diff:
From 990f6841c3a6795d315821278d985cf0c5632f5e Mon Sep 17 00:00:00 2001
From: Melanie Plageman <[email protected]>
Date: Tue, 25 Feb 2025 13:08:48 -0500
Subject: [PATCH v6] Add connection establishment duration logging
Add durations for several key parts of connection establishment when
log_connections is enabled.
For a new 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. Provide visibility into
authentication and fork duration as well as the end-to-end connection
establishment time with logging.
To make this portable, the timestamps captured in the postmaster (socket
creation time, fork initiation time) are passed through the ClientSocket
and BackendStartupData structures instead of simply saved in backend
local memory inherited by the child process.
Reviewed-by: Bertrand Drouvot <[email protected]>
Reviewed-by: Fujii Masao <[email protected]>
Reviewed-by: Jelte Fennema-Nio <[email protected]>
Reviewed-by: Jacob Champion <[email protected]>
Reviewed-by: Guillaume Lelarge <[email protected]>
Discussion: https://postgr.es/m/flat/CAAKRu_b_smAHK0ZjrnL5GRxnAVWujEXQWpLXYzGbmpcZd3nLYw%40mail.gmail.com
ci-os-only:
---
doc/src/sgml/config.sgml | 1 +
src/backend/postmaster/launch_backend.c | 23 +++++++++++++++++++++++
src/backend/postmaster/postmaster.c | 8 ++++++++
src/backend/tcop/postgres.c | 21 +++++++++++++++++++++
src/backend/utils/init/globals.c | 2 ++
src/backend/utils/init/postinit.c | 12 ++++++++++++
src/include/libpq/libpq-be.h | 2 ++
src/include/miscadmin.h | 2 ++
src/include/portability/instr_time.h | 9 +++++++++
src/include/postmaster/postmaster.h | 7 +++++++
src/include/tcop/backend_startup.h | 5 +++++
src/tools/pgindent/typedefs.list | 1 +
12 files changed, 93 insertions(+)
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index e55700f35b8..4861796654b 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -7325,6 +7325,7 @@ local0.* /var/log/postgresql
Causes each attempted connection to the server to be logged,
as well as successful completion of both client authentication (if
necessary) and authorization.
+ Successful connections log the connection establishment duration.
Only superusers and users with the appropriate <literal>SET</literal>
privilege can change this parameter at session start,
and it cannot be changed at all within a session.
diff --git a/src/backend/postmaster/launch_backend.c b/src/backend/postmaster/launch_backend.c
index 47375e5bfaa..c482cb299f7 100644
--- a/src/backend/postmaster/launch_backend.c
+++ b/src/backend/postmaster/launch_backend.c
@@ -232,6 +232,11 @@ postmaster_child_launch(BackendType child_type, int child_slot,
Assert(IsPostmasterEnvironment && !IsUnderPostmaster);
+ /* Capture time Postmaster initiates fork for logging */
+ if (Log_connections &&
+ (child_type == B_BACKEND || child_type == B_WAL_SENDER))
+ INSTR_TIME_SET_CURRENT(((BackendStartupData *) startup_data)->fork_time);
+
#ifdef EXEC_BACKEND
pid = internal_forkexec(child_process_kinds[child_type].name, child_slot,
startup_data, startup_data_len, client_sock);
@@ -240,6 +245,15 @@ postmaster_child_launch(BackendType child_type, int child_slot,
pid = fork_process();
if (pid == 0) /* child */
{
+ /* Calculate total fork duration in child backend for logging */
+ if (Log_connections &&
+ (child_type == B_BACKEND || child_type == B_WAL_SENDER))
+ {
+ instr_time fork_time = ((BackendStartupData *) startup_data)->fork_time;
+
+ conn_timing.fork_duration = INSTR_TIME_GET_DURATION_SINCE(fork_time);
+ }
+
/* Close the postmaster's sockets */
ClosePostmasterPorts(child_type == B_LOGGER);
@@ -618,6 +632,15 @@ 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 (Log_connections &&
+ (child_type == B_BACKEND || child_type == B_WAL_SENDER))
+ {
+ instr_time fork_time = ((BackendStartupData *) startup_data)->fork_time;
+
+ conn_timing.fork_duration = INSTR_TIME_GET_DURATION_SINCE(fork_time);
+ }
+
/* Close the postmaster's sockets (as soon as we know them) */
ClosePostmasterPorts(child_type == B_LOGGER);
diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index 5dd3b6a4fd4..880f491a9f7 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -1685,7 +1685,14 @@ ServerLoop(void)
ClientSocket s;
if (AcceptConnection(events[i].fd, &s) == STATUS_OK)
+ {
+ /*
+ * Capture time that Postmaster got a socket from accept
+ * (for logging connection establishment duration)
+ */
+ INSTR_TIME_SET_CURRENT(s.creation_time);
BackendStartup(&s);
+ }
/* We no longer need the open socket in this process */
if (s.sock != PGINVALID_SOCKET)
@@ -3511,6 +3518,7 @@ BackendStartup(ClientSocket *client_sock)
/* Pass down canAcceptConnections state */
startup_data.canAcceptConnections = cac;
+ INSTR_TIME_SET_ZERO(startup_data.fork_time);
bn->rw = NULL;
/* Hasn't asked to be notified about any bgworkers yet */
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index f2f75aa0f88..61d4ae2474d 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -4153,6 +4153,7 @@ PostgresMain(const char *dbname, const char *username)
volatile bool send_ready_for_query = true;
volatile bool idle_in_transaction_timeout_enabled = false;
volatile bool idle_session_timeout_enabled = false;
+ bool reported_first_ready_for_query = false;
Assert(dbname != NULL);
Assert(username != NULL);
@@ -4607,6 +4608,26 @@ 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.
+ */
+ if (!reported_first_ready_for_query &&
+ Log_connections &&
+ (AmRegularBackendProcess() || AmWalSenderProcess()))
+ {
+ instr_time total_duration =
+ INSTR_TIME_GET_DURATION_SINCE(MyClientSocket->creation_time);
+
+ ereport(LOG,
+ errmsg("connection establishment times (ms): total: %ld, fork: %ld, authentication: %ld",
+ (long int) INSTR_TIME_GET_MILLISEC(total_duration),
+ (long int) INSTR_TIME_GET_MILLISEC(conn_timing.fork_duration),
+ (long int) INSTR_TIME_GET_MILLISEC(conn_timing.auth_duration)));
+
+ reported_first_ready_for_query = true;
+ }
ReadyForQuery(whereToSendOutput);
send_ready_for_query = false;
}
diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c
index b844f9fdaef..3c7b14dd57d 100644
--- a/src/backend/utils/init/globals.c
+++ b/src/backend/utils/init/globals.c
@@ -43,6 +43,8 @@ volatile uint32 InterruptHoldoffCount = 0;
volatile uint32 QueryCancelHoldoffCount = 0;
volatile uint32 CritSectionCount = 0;
+ConnectionTiming conn_timing = {0};
+
int MyProcPid;
pg_time_t MyStartTime;
TimestampTz MyStartTimestamp;
diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index 318600d6d02..30eed2e85f7 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -190,9 +190,16 @@ GetDatabaseTupleByOid(Oid dboid)
static void
PerformAuthentication(Port *port)
{
+ instr_time auth_start_time;
+
/* This should be set already, but let's make sure */
ClientAuthInProgress = true; /* limit visibility of log messages */
+ /* Capture authentication start time for logging */
+ if (Log_connections &&
+ (AmRegularBackendProcess() || AmWalSenderProcess()))
+ INSTR_TIME_SET_CURRENT(auth_start_time);
+
/*
* In EXEC_BACKEND case, we didn't inherit the contents of pg_hba.conf
* etcetera from the postmaster, and have to load them ourselves.
@@ -251,6 +258,11 @@ PerformAuthentication(Port *port)
*/
disable_timeout(STATEMENT_TIMEOUT, false);
+ /* Calculate authentication duration for logging */
+ if (Log_connections &&
+ (AmRegularBackendProcess() || AmWalSenderProcess()))
+ conn_timing.auth_duration = INSTR_TIME_GET_DURATION_SINCE(auth_start_time);
+
if (Log_connections)
{
StringInfoData logmsg;
diff --git a/src/include/libpq/libpq-be.h b/src/include/libpq/libpq-be.h
index 7fe92b15477..b16ad69efff 100644
--- a/src/include/libpq/libpq-be.h
+++ b/src/include/libpq/libpq-be.h
@@ -58,6 +58,7 @@ typedef struct
#include "datatype/timestamp.h"
#include "libpq/hba.h"
#include "libpq/pqcomm.h"
+#include "portability/instr_time.h"
/*
@@ -252,6 +253,7 @@ typedef struct ClientSocket
{
pgsocket sock; /* File descriptor */
SockAddr raddr; /* remote addr (client) */
+ instr_time creation_time;
} ClientSocket;
#ifdef USE_SSL
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index a2b63495eec..9dd18a2c74f 100644
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -178,6 +178,8 @@ extern PGDLLIMPORT int MaxConnections;
extern PGDLLIMPORT int max_worker_processes;
extern PGDLLIMPORT int max_parallel_workers;
+extern PGDLLIMPORT struct ConnectionTiming conn_timing;
+
extern PGDLLIMPORT int commit_timestamp_buffers;
extern PGDLLIMPORT int multixact_member_buffers;
extern PGDLLIMPORT int multixact_offset_buffers;
diff --git a/src/include/portability/instr_time.h b/src/include/portability/instr_time.h
index f71a851b18d..48d7ff1bfad 100644
--- a/src/include/portability/instr_time.h
+++ b/src/include/portability/instr_time.h
@@ -184,6 +184,15 @@ GetTimerFrequency(void)
#define INSTR_TIME_ACCUM_DIFF(x,y,z) \
((x).ticks += (y).ticks - (z).ticks)
+static inline instr_time
+INSTR_TIME_GET_DURATION_SINCE(instr_time start_time)
+{
+ instr_time now;
+
+ INSTR_TIME_SET_CURRENT(now);
+ INSTR_TIME_SUBTRACT(now, start_time);
+ return now;
+}
#define INSTR_TIME_GET_DOUBLE(t) \
((double) INSTR_TIME_GET_NANOSEC(t) / NS_PER_S)
diff --git a/src/include/postmaster/postmaster.h b/src/include/postmaster/postmaster.h
index b6a3f275a1b..71a3f5f644d 100644
--- a/src/include/postmaster/postmaster.h
+++ b/src/include/postmaster/postmaster.h
@@ -15,6 +15,7 @@
#include "lib/ilist.h"
#include "miscadmin.h"
+#include "portability/instr_time.h"
/*
* A struct representing an active postmaster child process. This is used
@@ -126,6 +127,12 @@ extern PMChild *AllocDeadEndChild(void);
extern bool ReleasePostmasterChildSlot(PMChild *pmchild);
extern PMChild *FindPostmasterChildByPid(int pid);
+typedef struct ConnectionTiming
+{
+ instr_time fork_duration;
+ instr_time auth_duration;
+} ConnectionTiming;
+
/*
* These values correspond to the special must-be-first options for dispatching
* to various subprograms. parse_dispatch_option() can be used to convert an
diff --git a/src/include/tcop/backend_startup.h b/src/include/tcop/backend_startup.h
index 73285611203..7d9c43ce77b 100644
--- a/src/include/tcop/backend_startup.h
+++ b/src/include/tcop/backend_startup.h
@@ -14,6 +14,8 @@
#ifndef BACKEND_STARTUP_H
#define BACKEND_STARTUP_H
+#include "portability/instr_time.h"
+
/* GUCs */
extern PGDLLIMPORT bool Trace_connection_negotiation;
@@ -37,6 +39,9 @@ typedef enum CAC_state
typedef struct BackendStartupData
{
CAC_state canAcceptConnections;
+
+ /* Time at which the postmaster initiates a fork of a backend process */
+ instr_time fork_time;
} BackendStartupData;
extern void BackendMain(const void *startup_data, size_t startup_data_len) pg_attribute_noreturn();
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index cfbab589d61..566b0d8d73b 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -484,6 +484,7 @@ ConnParams
ConnStatusType
ConnType
ConnectionStateEnum
+ConnectionTiming
ConsiderSplitContext
Const
ConstrCheck
--
2.34.1
^ permalink raw reply [nested|flat] 24+ messages in thread
* Re: Log connection establishment timings
2025-02-25 20:23 Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-25 21:36 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-26 04:46 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
2025-02-26 07:41 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-26 18:45 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
@ 2025-02-27 06:50 ` Bertrand Drouvot <[email protected]>
2025-02-27 16:08 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-27 16:14 ` Re: Log connection establishment timings Andres Freund <[email protected]>
1 sibling, 2 replies; 24+ messages in thread
From: Bertrand Drouvot @ 2025-02-27 06:50 UTC (permalink / raw)
To: Melanie Plageman <[email protected]>; +Cc: Fujii Masao <[email protected]>; Guillaume Lelarge <[email protected]>; pgsql-hackers; Daniel Gustafsson <[email protected]>; [email protected]; Jelte Fennema-Nio <[email protected]>; Jacob Champion <[email protected]>
Hi,
On Wed, Feb 26, 2025 at 01:45:39PM -0500, Melanie Plageman wrote:
> Thanks for the continued review!
>
> On Wed, Feb 26, 2025 at 2:41 AM Bertrand Drouvot
> <[email protected]> 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).
Agree. IIUC, I think that Fujii-san's idea was to extend log_connections with
a new option "timing" (i.e move it from ConfigureNamesBool to say
ConfigureNamesEnum with say on, off and timing?). I think that's a good idea.
I just did a quick check and changing a GUC from ConfigureNamesBool to
ConfigureNamesEnum is something that has already been done in the past (see
240067b3b0f and ffd37740ee6 for example).
In my previous up-thead message, I did not mean to suggest to add a new GUC,
just saying that when new "timing" is measured then users have the choice to
enable or disable it.
> > > 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..
Thanks for the updated version!
> > +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.
Yeah makes sense.
> > 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 took a stab at this in attached v6. I feel that what I have is a bit
> stilted, but I'm not sure how to fix it.
Yeah, that might be easier to reason about if we're going with Fujii-san
suggestion to extend log_connections with a new option?
> > + /* 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.
Great idea! Could probably be used in other places but I did not check and
it's outside the scope of this thread anyway.
> It does not however cut down on LOC, so I'm somewhat on the fence.
I think that's somehow also around code maintenance (not only LOC), say for example
if we want to add more "child_type" in the check (no need to remember to update both
locations).
Regards,
--
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com
^ permalink raw reply [nested|flat] 24+ messages in thread
* Re: Log connection establishment timings
2025-02-25 20:23 Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-25 21:36 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-26 04:46 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
2025-02-26 07:41 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-26 18:45 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-27 06:50 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
@ 2025-02-27 16:08 ` Melanie Plageman <[email protected]>
2025-02-27 16:30 ` Re: Log connection establishment timings Andres Freund <[email protected]>
2025-02-28 05:16 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
1 sibling, 2 replies; 24+ messages in thread
From: Melanie Plageman @ 2025-02-27 16:08 UTC (permalink / raw)
To: Bertrand Drouvot <[email protected]>; +Cc: Fujii Masao <[email protected]>; Guillaume Lelarge <[email protected]>; pgsql-hackers; Daniel Gustafsson <[email protected]>; [email protected]; Jelte Fennema-Nio <[email protected]>; Jacob Champion <[email protected]>
On Thu, Feb 27, 2025 at 1:50 AM Bertrand Drouvot
<[email protected]> wrote:
>
> Agree. IIUC, I think that Fujii-san's idea was to extend log_connections with
> a new option "timing" (i.e move it from ConfigureNamesBool to say
> ConfigureNamesEnum with say on, off and timing?). I think that's a good idea.
>
> I just did a quick check and changing a GUC from ConfigureNamesBool to
> ConfigureNamesEnum is something that has already been done in the past (see
> 240067b3b0f and ffd37740ee6 for example).
>
> In my previous up-thead message, I did not mean to suggest to add a new GUC,
> just saying that when new "timing" is measured then users have the choice to
> enable or disable it.
I was just talking to Andres off-list and he mentioned that the volume
of log_connections messages added in recent releases can really be a
problem for users. He said ideally we would emit one message which
consolidated these (and make sure we did so for failed connections too
detailing the successfully completed stages).
However, since that is a bigger project (with more refactoring, etc),
he suggested that we change log_connections to a GUC_LIST
(ConfigureNamesString) with options like "none", "received,
"authenticated", "authorized", "all".
Then we could add one like "established" for the final message and
timings my patch set adds. I think the overhead of an additional log
message being emitted probably outweighs the overhead of taking those
additional timings.
String GUCs are a lot more work than enum GUCs, so I was thinking if
there is a way to do it as an enum.
I think we want the user to be able to specify a list of all the log
messages they want included, not just have each one include the
previous ones. So, then it probably has to be a list right? There is
no good design that would fit as an enum.
> > I've added INSTR_TIME_GET_DURATION_SINCE(start_time). Which I like
> > because it seems generally useful.
>
> Great idea! Could probably be used in other places but I did not check and
> it's outside the scope of this thread anyway.
>
> > It does not however cut down on LOC, so I'm somewhat on the fence.
>
> I think that's somehow also around code maintenance (not only LOC), say for example
> if we want to add more "child_type" in the check (no need to remember to update both
> locations).
I didn't include checking the child_type in that function since it is
unrelated to instr_time, so it sadly wouldn't help with that. We could
macro-ize the child_type check were we to add another child_type.
- Melanie
^ permalink raw reply [nested|flat] 24+ messages in thread
* Re: Log connection establishment timings
2025-02-25 20:23 Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-25 21:36 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-26 04:46 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
2025-02-26 07:41 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-26 18:45 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-27 06:50 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-27 16:08 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
@ 2025-02-27 16:30 ` Andres Freund <[email protected]>
2025-02-27 22:55 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
1 sibling, 1 reply; 24+ messages in thread
From: Andres Freund @ 2025-02-27 16:30 UTC (permalink / raw)
To: Melanie Plageman <[email protected]>; +Cc: Bertrand Drouvot <[email protected]>; Fujii Masao <[email protected]>; Guillaume Lelarge <[email protected]>; pgsql-hackers; Daniel Gustafsson <[email protected]>; [email protected]; Jelte Fennema-Nio <[email protected]>; Jacob Champion <[email protected]>
Hi,
On 2025-02-27 11:08:04 -0500, Melanie Plageman wrote:
> I was just talking to Andres off-list and he mentioned that the volume
> of log_connections messages added in recent releases can really be a
> problem for users.
For some added color: I've seen plenty systems where almost all the log volume
is log_connection messages, which they *have* to enable for various regulatory
reasons. It'd still be a lot if we just emitted one message for each
connection, but logging three (and possibly four with $thread), for each
connection makes it substantially worse.
> He said ideally we would emit one message which consolidated these (and make
> sure we did so for failed connections too detailing the successfully
> completed stages).
A combined message would also not *quite* replace all use-cases, e.g. if you
want to debug arriving connections or auth problems you do want the additional
messages. But yea, for normal operation, I do think most folks want just one
message.
> However, since that is a bigger project (with more refactoring, etc),
> he suggested that we change log_connections to a GUC_LIST
> (ConfigureNamesString) with options like "none", "received,
> "authenticated", "authorized", "all".
Yep.
> Then we could add one like "established" for the final message and
> timings my patch set adds. I think the overhead of an additional log
> message being emitted probably outweighs the overhead of taking those
> additional timings.
To bikeshed a bit: "established" could be the TCP connection establishment
just as well. I'd go for "completed" or "timings".
> String GUCs are a lot more work than enum GUCs, so I was thinking if
> there is a way to do it as an enum.
>
> I think we want the user to be able to specify a list of all the log
> messages they want included, not just have each one include the
> previous ones. So, then it probably has to be a list right? There is
> no good design that would fit as an enum.
I don't see a way to comfortably shove this into an enum either.
Greetings,
Andres Freund
^ permalink raw reply [nested|flat] 24+ messages in thread
* Re: Log connection establishment timings
2025-02-25 20:23 Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-25 21:36 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-26 04:46 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
2025-02-26 07:41 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-26 18:45 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-27 06:50 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-27 16:08 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-27 16:30 ` Re: Log connection establishment timings Andres Freund <[email protected]>
@ 2025-02-27 22:55 ` Melanie Plageman <[email protected]>
2025-02-28 05:54 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
0 siblings, 1 reply; 24+ messages in thread
From: Melanie Plageman @ 2025-02-27 22:55 UTC (permalink / raw)
To: Andres Freund <[email protected]>; +Cc: Bertrand Drouvot <[email protected]>; Fujii Masao <[email protected]>; Guillaume Lelarge <[email protected]>; pgsql-hackers; Daniel Gustafsson <[email protected]>; [email protected]; Jelte Fennema-Nio <[email protected]>; Jacob Champion <[email protected]>
On Thu, Feb 27, 2025 at 11:30 AM Andres Freund <[email protected]> wrote:
>
> On 2025-02-27 11:08:04 -0500, Melanie Plageman wrote:
>
> > However, since that is a bigger project (with more refactoring, etc),
> > he suggested that we change log_connections to a GUC_LIST
> > (ConfigureNamesString) with options like "none", "received,
> > "authenticated", "authorized", "all".
>
> Yep.
I've done a draft of this in attached v7 (see 0001). It still needs
polishing (e.g. I need to figure out where to put the new guc hook
functions and enums and such), but I want to see if this is a viable
direction forward.
I'm worried the list of possible connection log messages could get
unwieldy if we add many more.
- Melanie
Attachments:
[text/x-patch] v7-0002-Add-connection-establishment-duration-logging.patch (13.2K, ../../CAAKRu_asMtUpxDjts1J60batVqLsSGRodMOq4E9ryg1XdO8EZw@mail.gmail.com/2-v7-0002-Add-connection-establishment-duration-logging.patch)
download | inline diff:
From 6f7f1a2e3ea660596bee0348691e192b8c2fce24 Mon Sep 17 00:00:00 2001
From: Melanie Plageman <[email protected]>
Date: Thu, 27 Feb 2025 17:33:38 -0500
Subject: [PATCH v7 2/2] Add connection establishment duration logging
Add durations for several key parts of connection establishment when
log_connections is enabled.
For a new 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. Provide visibility into
authentication and fork duration as well as the end-to-end connection
establishment time with logging.
To make this portable, the timestamps captured in the postmaster (socket
creation time, fork initiation time) are passed through the ClientSocket
and BackendStartupData structures instead of simply saved in backend
local memory inherited by the child process.
Reviewed-by: Bertrand Drouvot <[email protected]>
Reviewed-by: Fujii Masao <[email protected]>
Reviewed-by: Jelte Fennema-Nio <[email protected]>
Reviewed-by: Jacob Champion <[email protected]>
Reviewed-by: Guillaume Lelarge <[email protected]>
Discussion: https://postgr.es/m/flat/CAAKRu_b_smAHK0ZjrnL5GRxnAVWujEXQWpLXYzGbmpcZd3nLYw%40mail.gmail.com
---
doc/src/sgml/config.sgml | 2 +-
src/backend/postmaster/launch_backend.c | 23 +++++++++++++++++++++++
src/backend/postmaster/postmaster.c | 12 +++++++++++-
src/backend/tcop/postgres.c | 21 +++++++++++++++++++++
src/backend/utils/init/globals.c | 2 ++
src/backend/utils/init/postinit.c | 12 ++++++++++++
src/include/libpq/libpq-be.h | 2 ++
src/include/miscadmin.h | 2 ++
src/include/portability/instr_time.h | 9 +++++++++
src/include/postmaster/postmaster.h | 8 ++++++++
src/include/tcop/backend_startup.h | 5 +++++
src/tools/pgindent/typedefs.list | 1 +
12 files changed, 97 insertions(+), 2 deletions(-)
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index c927efd22d1..82b06179a38 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -7324,7 +7324,7 @@ local0.* /var/log/postgresql
<para>
Causes each attempted connection to the server to be logged, as well as
successful completion of both client authentication (if necessary) and
- authorization.
+ authorization. Also logs connection establishment component durations.
</para>
<para>
diff --git a/src/backend/postmaster/launch_backend.c b/src/backend/postmaster/launch_backend.c
index 47375e5bfaa..3fe68601899 100644
--- a/src/backend/postmaster/launch_backend.c
+++ b/src/backend/postmaster/launch_backend.c
@@ -232,6 +232,11 @@ postmaster_child_launch(BackendType child_type, int child_slot,
Assert(IsPostmasterEnvironment && !IsUnderPostmaster);
+ /* Capture time Postmaster initiates fork for logging */
+ if ((log_connections & LOG_CONNECTION_TIMINGS) &&
+ (child_type == B_BACKEND || child_type == B_WAL_SENDER))
+ INSTR_TIME_SET_CURRENT(((BackendStartupData *) startup_data)->fork_time);
+
#ifdef EXEC_BACKEND
pid = internal_forkexec(child_process_kinds[child_type].name, child_slot,
startup_data, startup_data_len, client_sock);
@@ -240,6 +245,15 @@ postmaster_child_launch(BackendType child_type, int child_slot,
pid = fork_process();
if (pid == 0) /* child */
{
+ /* Calculate total fork duration in child backend for logging */
+ if ((log_connections & LOG_CONNECTION_TIMINGS) &&
+ (child_type == B_BACKEND || child_type == B_WAL_SENDER))
+ {
+ instr_time fork_time = ((BackendStartupData *) startup_data)->fork_time;
+
+ conn_timing.fork_duration = INSTR_TIME_GET_DURATION_SINCE(fork_time);
+ }
+
/* Close the postmaster's sockets */
ClosePostmasterPorts(child_type == B_LOGGER);
@@ -618,6 +632,15 @@ 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 ((log_connections & LOG_CONNECTION_READY) &&
+ (child_type == B_BACKEND || child_type == B_WAL_SENDER))
+ {
+ instr_time fork_time = ((BackendStartupData *) startup_data)->fork_time;
+
+ conn_timing.fork_duration = INSTR_TIME_GET_DURATION_SINCE(fork_time);
+ }
+
/* Close the postmaster's sockets (as soon as we know them) */
ClosePostmasterPorts(child_type == B_LOGGER);
diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index aef63793aa7..71aa47c8d36 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -1536,7 +1536,7 @@ check_log_connections(char **newval, void **extra, GucSource source)
if (pg_strcasecmp(*newval, "none") == 0)
effval = "";
else if (pg_strcasecmp(*newval, "all") == 0)
- effval = "received, authenticated, authorized";
+ effval = "received, authenticated, authorized, timings";
/* Need a modifiable copy of string */
rawstring = pstrdup(effval);
@@ -1558,6 +1558,8 @@ check_log_connections(char **newval, void **extra, GucSource source)
flags |= LOG_CONNECTION_AUTHENTICATED;
else if (pg_strcasecmp(item, "authorized") == 0)
flags |= LOG_CONNECTION_AUTHORIZED;
+ else if (pg_strcasecmp(item, "timings") == 0)
+ flags |= LOG_CONNECTION_TIMINGS;
else if (pg_strcasecmp(item, "none") == 0 || pg_strcasecmp(item, "all") == 0)
{
GUC_check_errdetail("Cannot specify \"%s\" in a list of other log_connections options.", item);
@@ -1759,7 +1761,14 @@ ServerLoop(void)
ClientSocket s;
if (AcceptConnection(events[i].fd, &s) == STATUS_OK)
+ {
+ /*
+ * Capture time that Postmaster got a socket from accept
+ * (for logging connection establishment duration)
+ */
+ INSTR_TIME_SET_CURRENT(s.creation_time);
BackendStartup(&s);
+ }
/* We no longer need the open socket in this process */
if (s.sock != PGINVALID_SOCKET)
@@ -3585,6 +3594,7 @@ BackendStartup(ClientSocket *client_sock)
/* Pass down canAcceptConnections state */
startup_data.canAcceptConnections = cac;
+ INSTR_TIME_SET_ZERO(startup_data.fork_time);
bn->rw = NULL;
/* Hasn't asked to be notified about any bgworkers yet */
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index f2f75aa0f88..d753c6bbd5b 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -4153,6 +4153,7 @@ PostgresMain(const char *dbname, const char *username)
volatile bool send_ready_for_query = true;
volatile bool idle_in_transaction_timeout_enabled = false;
volatile bool idle_session_timeout_enabled = false;
+ bool reported_first_ready_for_query = false;
Assert(dbname != NULL);
Assert(username != NULL);
@@ -4607,6 +4608,26 @@ 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.
+ */
+ if (!reported_first_ready_for_query &&
+ (log_connections & LOG_CONNECTION_TIMINGS) &&
+ (AmRegularBackendProcess() || AmWalSenderProcess()))
+ {
+ instr_time total_duration =
+ INSTR_TIME_GET_DURATION_SINCE(MyClientSocket->creation_time);
+
+ ereport(LOG,
+ errmsg("connection establishment times (ms): total: %ld, fork: %ld, authentication: %ld",
+ (long int) INSTR_TIME_GET_MILLISEC(total_duration),
+ (long int) INSTR_TIME_GET_MILLISEC(conn_timing.fork_duration),
+ (long int) INSTR_TIME_GET_MILLISEC(conn_timing.auth_duration)));
+
+ reported_first_ready_for_query = true;
+ }
ReadyForQuery(whereToSendOutput);
send_ready_for_query = false;
}
diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c
index b844f9fdaef..3c7b14dd57d 100644
--- a/src/backend/utils/init/globals.c
+++ b/src/backend/utils/init/globals.c
@@ -43,6 +43,8 @@ volatile uint32 InterruptHoldoffCount = 0;
volatile uint32 QueryCancelHoldoffCount = 0;
volatile uint32 CritSectionCount = 0;
+ConnectionTiming conn_timing = {0};
+
int MyProcPid;
pg_time_t MyStartTime;
TimestampTz MyStartTimestamp;
diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index 8811f2ba3e6..44e086ceca7 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -190,9 +190,16 @@ GetDatabaseTupleByOid(Oid dboid)
static void
PerformAuthentication(Port *port)
{
+ instr_time auth_start_time;
+
/* This should be set already, but let's make sure */
ClientAuthInProgress = true; /* limit visibility of log messages */
+ /* Capture authentication start time for logging */
+ if ((log_connections & LOG_CONNECTION_TIMINGS) &&
+ (AmRegularBackendProcess() || AmWalSenderProcess()))
+ INSTR_TIME_SET_CURRENT(auth_start_time);
+
/*
* In EXEC_BACKEND case, we didn't inherit the contents of pg_hba.conf
* etcetera from the postmaster, and have to load them ourselves.
@@ -251,6 +258,11 @@ PerformAuthentication(Port *port)
*/
disable_timeout(STATEMENT_TIMEOUT, false);
+ /* Calculate authentication duration for logging */
+ if ((log_connections & LOG_CONNECTION_TIMINGS) &&
+ (AmRegularBackendProcess() || AmWalSenderProcess()))
+ conn_timing.auth_duration = INSTR_TIME_GET_DURATION_SINCE(auth_start_time);
+
if (log_connections & LOG_CONNECTION_AUTHORIZED)
{
StringInfoData logmsg;
diff --git a/src/include/libpq/libpq-be.h b/src/include/libpq/libpq-be.h
index 7fe92b15477..b16ad69efff 100644
--- a/src/include/libpq/libpq-be.h
+++ b/src/include/libpq/libpq-be.h
@@ -58,6 +58,7 @@ typedef struct
#include "datatype/timestamp.h"
#include "libpq/hba.h"
#include "libpq/pqcomm.h"
+#include "portability/instr_time.h"
/*
@@ -252,6 +253,7 @@ typedef struct ClientSocket
{
pgsocket sock; /* File descriptor */
SockAddr raddr; /* remote addr (client) */
+ instr_time creation_time;
} ClientSocket;
#ifdef USE_SSL
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index a2b63495eec..9dd18a2c74f 100644
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -178,6 +178,8 @@ extern PGDLLIMPORT int MaxConnections;
extern PGDLLIMPORT int max_worker_processes;
extern PGDLLIMPORT int max_parallel_workers;
+extern PGDLLIMPORT struct ConnectionTiming conn_timing;
+
extern PGDLLIMPORT int commit_timestamp_buffers;
extern PGDLLIMPORT int multixact_member_buffers;
extern PGDLLIMPORT int multixact_offset_buffers;
diff --git a/src/include/portability/instr_time.h b/src/include/portability/instr_time.h
index f71a851b18d..48d7ff1bfad 100644
--- a/src/include/portability/instr_time.h
+++ b/src/include/portability/instr_time.h
@@ -184,6 +184,15 @@ GetTimerFrequency(void)
#define INSTR_TIME_ACCUM_DIFF(x,y,z) \
((x).ticks += (y).ticks - (z).ticks)
+static inline instr_time
+INSTR_TIME_GET_DURATION_SINCE(instr_time start_time)
+{
+ instr_time now;
+
+ INSTR_TIME_SET_CURRENT(now);
+ INSTR_TIME_SUBTRACT(now, start_time);
+ return now;
+}
#define INSTR_TIME_GET_DOUBLE(t) \
((double) INSTR_TIME_GET_NANOSEC(t) / NS_PER_S)
diff --git a/src/include/postmaster/postmaster.h b/src/include/postmaster/postmaster.h
index adc693a6b2b..dae7551e7ad 100644
--- a/src/include/postmaster/postmaster.h
+++ b/src/include/postmaster/postmaster.h
@@ -15,6 +15,7 @@
#include "lib/ilist.h"
#include "miscadmin.h"
+#include "portability/instr_time.h"
/*
* A struct representing an active postmaster child process. This is used
@@ -127,6 +128,12 @@ extern PMChild *AllocDeadEndChild(void);
extern bool ReleasePostmasterChildSlot(PMChild *pmchild);
extern PMChild *FindPostmasterChildByPid(int pid);
+typedef struct ConnectionTiming
+{
+ instr_time fork_duration;
+ instr_time auth_duration;
+} ConnectionTiming;
+
/*
* These values correspond to the special must-be-first options for dispatching
* to various subprograms. parse_dispatch_option() can be used to convert an
@@ -149,6 +156,7 @@ typedef enum ConnectionLogType
LOG_CONNECTION_RECEIVED,
LOG_CONNECTION_AUTHENTICATED,
LOG_CONNECTION_AUTHORIZED,
+ LOG_CONNECTION_TIMINGS,
} ConnectionLogType;
#endif /* _POSTMASTER_H */
diff --git a/src/include/tcop/backend_startup.h b/src/include/tcop/backend_startup.h
index 73285611203..7d9c43ce77b 100644
--- a/src/include/tcop/backend_startup.h
+++ b/src/include/tcop/backend_startup.h
@@ -14,6 +14,8 @@
#ifndef BACKEND_STARTUP_H
#define BACKEND_STARTUP_H
+#include "portability/instr_time.h"
+
/* GUCs */
extern PGDLLIMPORT bool Trace_connection_negotiation;
@@ -37,6 +39,9 @@ typedef enum CAC_state
typedef struct BackendStartupData
{
CAC_state canAcceptConnections;
+
+ /* Time at which the postmaster initiates a fork of a backend process */
+ instr_time fork_time;
} BackendStartupData;
extern void BackendMain(const void *startup_data, size_t startup_data_len) pg_attribute_noreturn();
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index 59839013d28..ea7163fdada 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -485,6 +485,7 @@ ConnStatusType
ConnType
ConnectionLogType
ConnectionStateEnum
+ConnectionTiming
ConsiderSplitContext
Const
ConstrCheck
--
2.34.1
[text/x-patch] v7-0001-Make-log_connections-a-list.patch (22.7K, ../../CAAKRu_asMtUpxDjts1J60batVqLsSGRodMOq4E9ryg1XdO8EZw@mail.gmail.com/3-v7-0001-Make-log_connections-a-list.patch)
download | inline diff:
From 6178535e0be8e25e4209f42d52c8402b6d1e4724 Mon Sep 17 00:00:00 2001
From: Melanie Plageman <[email protected]>
Date: Thu, 27 Feb 2025 17:32:17 -0500
Subject: [PATCH v7 1/2] Make log_connections a list
Instead of a boolean, make log_connections a list of the possible log
connections events to log. all and none mimic current behavior of on and
off. This is in response to feedback that log_connections logs too many
messages.
---
doc/src/sgml/config.sgml | 25 ++++--
src/backend/libpq/auth.c | 5 +-
src/backend/postmaster/postmaster.c | 76 ++++++++++++++++++-
src/backend/tcop/backend_startup.c | 2 +-
src/backend/utils/init/postinit.c | 2 +-
src/backend/utils/misc/guc_tables.c | 20 ++---
src/backend/utils/misc/postgresql.conf.sample | 4 +-
src/include/postmaster/postmaster.h | 10 ++-
src/include/utils/guc_hooks.h | 2 +
.../libpq/t/005_negotiate_encryption.pl | 2 +-
src/test/authentication/t/001_password.pl | 2 +-
src/test/authentication/t/003_peer.pl | 2 +-
src/test/authentication/t/005_sspi.pl | 2 +-
src/test/kerberos/t/001_auth.pl | 2 +-
src/test/ldap/t/001_auth.pl | 2 +-
src/test/ldap/t/002_bindpasswd.pl | 2 +-
.../t/001_mutated_bindpasswd.pl | 2 +-
.../modules/oauth_validator/t/001_server.pl | 2 +-
.../modules/oauth_validator/t/002_client.pl | 2 +-
.../postmaster/t/002_connection_limits.pl | 2 +-
src/test/postmaster/t/003_start_stop.pl | 2 +-
src/test/recovery/t/013_crash_restart.pl | 2 +-
src/test/recovery/t/022_crash_temp_files.pl | 2 +-
src/test/recovery/t/032_relfilenode_reuse.pl | 2 +-
src/test/recovery/t/037_invalid_database.pl | 2 +-
src/test/ssl/t/SSL/Server.pm | 2 +-
src/tools/ci/pg_ci_base.conf | 2 +-
src/tools/pgindent/typedefs.list | 1 +
28 files changed, 141 insertions(+), 42 deletions(-)
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index e55700f35b8..c927efd22d1 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -140,7 +140,7 @@
An example of what this file might look like is:
<programlisting>
# This is a comment
-log_connections = yes
+log_connections = 'all'
log_destination = 'syslog'
search_path = '"$user", public'
shared_buffers = 128MB
@@ -337,7 +337,7 @@ UPDATE pg_settings SET setting = reset_val WHERE name = 'configuration_parameter
<option>-c name=value</option> command-line parameter, or its equivalent
<option>--name=value</option> variation. For example,
<programlisting>
-postgres -c log_connections=yes --log-destination='syslog'
+postgres -c log_connections='all' --log-destination='syslog'
</programlisting>
Settings provided in this way override those set via
<filename>postgresql.conf</filename> or <command>ALTER SYSTEM</command>,
@@ -7315,20 +7315,31 @@ local0.* /var/log/postgresql
</varlistentry>
<varlistentry id="guc-log-connections" xreflabel="log_connections">
- <term><varname>log_connections</varname> (<type>boolean</type>)
+ <term><varname>log_connections</varname> (<type>string</type>)
<indexterm>
<primary><varname>log_connections</varname> configuration parameter</primary>
</indexterm>
</term>
<listitem>
<para>
- Causes each attempted connection to the server to be logged,
- as well as successful completion of both client authentication (if
- necessary) and authorization.
+ Causes each attempted connection to the server to be logged, as well as
+ successful completion of both client authentication (if necessary) and
+ authorization.
+ </para>
+
+ <para>
+ May be set to <literal>none</literal> to disable this logging,
+ <literal>all</literal> to enable all connection log message types, or a
+ comma-separated list of the specific connection log message types to
+ emit. The valid options are <literal>received</literal>,
+ <literal>authenticated</literal>, and <literal>authorized</literal>.
+ </para>
+
+ <para>
Only superusers and users with the appropriate <literal>SET</literal>
privilege can change this parameter at session start,
and it cannot be changed at all within a session.
- The default is <literal>off</literal>.
+ The default is <literal>'none'</literal>.
</para>
<note>
diff --git a/src/backend/libpq/auth.c b/src/backend/libpq/auth.c
index 81e2f8184e3..b4cc8cb4dd1 100644
--- a/src/backend/libpq/auth.c
+++ b/src/backend/libpq/auth.c
@@ -349,7 +349,7 @@ set_authn_id(Port *port, const char *id)
MyClientConnectionInfo.authn_id = MemoryContextStrdup(TopMemoryContext, id);
MyClientConnectionInfo.auth_method = port->hba->auth_method;
- if (Log_connections)
+ if (log_connections & LOG_CONNECTION_AUTHENTICATED)
{
ereport(LOG,
errmsg("connection authenticated: identity=\"%s\" method=%s "
@@ -633,7 +633,8 @@ ClientAuthentication(Port *port)
#endif
}
- if (Log_connections && status == STATUS_OK &&
+ if ((log_connections & LOG_CONNECTION_AUTHENTICATED) &&
+ status == STATUS_OK &&
!MyClientConnectionInfo.authn_id)
{
/*
diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index 5dd3b6a4fd4..aef63793aa7 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -118,6 +118,7 @@
#include "utils/pidfile.h"
#include "utils/timestamp.h"
#include "utils/varlena.h"
+#include "utils/guc_hooks.h"
#ifdef EXEC_BACKEND
#include "common/file_utils.h"
@@ -237,7 +238,8 @@ int PreAuthDelay = 0;
int AuthenticationTimeout = 60;
bool log_hostname; /* for ps display and logging */
-bool Log_connections = false;
+char *log_connections_string = NULL;
+int log_connections = 0;
bool enable_bonjour = false;
char *bonjour_name;
@@ -1517,6 +1519,78 @@ checkControlFile(void)
FreeFile(fp);
}
+bool
+check_log_connections(char **newval, void **extra, GucSource source)
+{
+ int flags = 0;
+ char *rawstring = NULL;
+ List *elemlist;
+ ListCell *l;
+
+ char *effval = *newval;
+
+ /*
+ * log_connections can be "all" or "none" or a list of comma separated
+ * options
+ */
+ if (pg_strcasecmp(*newval, "none") == 0)
+ effval = "";
+ else if (pg_strcasecmp(*newval, "all") == 0)
+ effval = "received, authenticated, authorized";
+
+ /* Need a modifiable copy of string */
+ rawstring = pstrdup(effval);
+
+ if (!SplitGUCList(rawstring, ',', &elemlist))
+ {
+ GUC_check_errdetail("Invalid list syntax in parameter \"%s\".",
+ "log_connections");
+ goto error;
+ }
+
+ foreach(l, elemlist)
+ {
+ char *item = (char *) lfirst(l);
+
+ if (pg_strcasecmp(item, "received") == 0)
+ flags |= LOG_CONNECTION_RECEIVED;
+ else if (pg_strcasecmp(item, "authenticated") == 0)
+ flags |= LOG_CONNECTION_AUTHENTICATED;
+ else if (pg_strcasecmp(item, "authorized") == 0)
+ flags |= LOG_CONNECTION_AUTHORIZED;
+ else if (pg_strcasecmp(item, "none") == 0 || pg_strcasecmp(item, "all") == 0)
+ {
+ GUC_check_errdetail("Cannot specify \"%s\" in a list of other log_connections options.", item);
+ goto error;
+ }
+ else
+ {
+ GUC_check_errdetail("Invalid option \"%s\".", item);
+ goto error;
+ }
+ }
+
+ pfree(rawstring);
+ list_free(elemlist);
+
+ /* Save the flags in *extra, for use by assign_log_connections */
+ *extra = guc_malloc(ERROR, sizeof(int));
+ *((int *) *extra) = flags;
+
+ return true;
+
+error:
+ pfree(rawstring);
+ list_free(elemlist);
+ return false;
+}
+
+void
+assign_log_connections(const char *newval, void *extra)
+{
+ log_connections = *((int *) extra);
+}
+
/*
* Determine how long should we let ServerLoop sleep, in milliseconds.
*
diff --git a/src/backend/tcop/backend_startup.c b/src/backend/tcop/backend_startup.c
index c70746fa562..2c208c25356 100644
--- a/src/backend/tcop/backend_startup.c
+++ b/src/backend/tcop/backend_startup.c
@@ -202,7 +202,7 @@ BackendInitialize(ClientSocket *client_sock, CAC_state cac)
port->remote_port = MemoryContextStrdup(TopMemoryContext, remote_port);
/* And now we can issue the Log_connections message, if wanted */
- if (Log_connections)
+ if (log_connections & LOG_CONNECTION_RECEIVED)
{
if (remote_port[0])
ereport(LOG,
diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index 318600d6d02..8811f2ba3e6 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -251,7 +251,7 @@ PerformAuthentication(Port *port)
*/
disable_timeout(STATEMENT_TIMEOUT, false);
- if (Log_connections)
+ if (log_connections & LOG_CONNECTION_AUTHORIZED)
{
StringInfoData logmsg;
diff --git a/src/backend/utils/misc/guc_tables.c b/src/backend/utils/misc/guc_tables.c
index ad25cbb39c5..7dfa11810a8 100644
--- a/src/backend/utils/misc/guc_tables.c
+++ b/src/backend/utils/misc/guc_tables.c
@@ -1219,15 +1219,6 @@ struct config_bool ConfigureNamesBool[] =
true,
NULL, NULL, NULL
},
- {
- {"log_connections", PGC_SU_BACKEND, LOGGING_WHAT,
- gettext_noop("Logs each successful connection."),
- NULL
- },
- &Log_connections,
- false,
- NULL, NULL, NULL
- },
{
{"trace_connection_negotiation", PGC_POSTMASTER, DEVELOPER_OPTIONS,
gettext_noop("Logs details of pre-authentication connection handshake."),
@@ -4850,6 +4841,17 @@ struct config_string ConfigureNamesString[] =
check_debug_io_direct, assign_debug_io_direct, NULL
},
+ {
+ {"log_connections", PGC_SU_BACKEND, LOGGING_WHAT,
+ gettext_noop("Logs information about successful connection."),
+ NULL,
+ GUC_LIST_INPUT
+ },
+ &log_connections_string,
+ "none",
+ check_log_connections, assign_log_connections, NULL
+ },
+
{
{"synchronized_standby_slots", PGC_SIGHUP, REPLICATION_PRIMARY,
gettext_noop("Lists streaming replication standby server replication slot "
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index 5362ff80519..4f54719dd9e 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -21,7 +21,7 @@
# require a server shutdown and restart to take effect.
#
# Any parameter can also be given as a command-line option to the server, e.g.,
-# "postgres -c log_connections=on". Some parameters can be changed at run time
+# "postgres -c log_connections='all'". Some parameters can be changed at run time
# with the "SET" SQL command.
#
# Memory units: B = bytes Time units: us = microseconds
@@ -578,7 +578,7 @@
# actions running at least this number
# of milliseconds.
#log_checkpoints = on
-#log_connections = off
+#log_connections = 'none'
#log_disconnections = off
#log_duration = off
#log_error_verbosity = default # terse, default, or verbose messages
diff --git a/src/include/postmaster/postmaster.h b/src/include/postmaster/postmaster.h
index b6a3f275a1b..adc693a6b2b 100644
--- a/src/include/postmaster/postmaster.h
+++ b/src/include/postmaster/postmaster.h
@@ -63,7 +63,8 @@ extern PGDLLIMPORT char *ListenAddresses;
extern PGDLLIMPORT bool ClientAuthInProgress;
extern PGDLLIMPORT int PreAuthDelay;
extern PGDLLIMPORT int AuthenticationTimeout;
-extern PGDLLIMPORT bool Log_connections;
+extern PGDLLIMPORT int log_connections;
+extern PGDLLIMPORT char *log_connections_string;
extern PGDLLIMPORT bool log_hostname;
extern PGDLLIMPORT bool enable_bonjour;
extern PGDLLIMPORT char *bonjour_name;
@@ -143,4 +144,11 @@ typedef enum DispatchOption
extern DispatchOption parse_dispatch_option(const char *name);
+typedef enum ConnectionLogType
+{
+ LOG_CONNECTION_RECEIVED,
+ LOG_CONNECTION_AUTHENTICATED,
+ LOG_CONNECTION_AUTHORIZED,
+} ConnectionLogType;
+
#endif /* _POSTMASTER_H */
diff --git a/src/include/utils/guc_hooks.h b/src/include/utils/guc_hooks.h
index 951451a9765..9a0d8ec85c7 100644
--- a/src/include/utils/guc_hooks.h
+++ b/src/include/utils/guc_hooks.h
@@ -51,6 +51,8 @@ extern bool check_datestyle(char **newval, void **extra, GucSource source);
extern void assign_datestyle(const char *newval, void *extra);
extern bool check_debug_io_direct(char **newval, void **extra, GucSource source);
extern void assign_debug_io_direct(const char *newval, void *extra);
+extern bool check_log_connections(char **newval, void **extra, GucSource source);
+extern void assign_log_connections(const char *newval, void *extra);
extern bool check_default_table_access_method(char **newval, void **extra,
GucSource source);
extern bool check_default_tablespace(char **newval, void **extra,
diff --git a/src/interfaces/libpq/t/005_negotiate_encryption.pl b/src/interfaces/libpq/t/005_negotiate_encryption.pl
index c834fa5149a..cb56e09d50b 100644
--- a/src/interfaces/libpq/t/005_negotiate_encryption.pl
+++ b/src/interfaces/libpq/t/005_negotiate_encryption.pl
@@ -107,7 +107,7 @@ $node->append_conf(
listen_addresses = '$hostaddr'
# Capturing the EVENTS that occur during tests requires these settings
-log_connections = on
+log_connections = 'all'
log_disconnections = on
trace_connection_negotiation = on
lc_messages = 'C'
diff --git a/src/test/authentication/t/001_password.pl b/src/test/authentication/t/001_password.pl
index 4ce22ccbdf2..72c187fbdc0 100644
--- a/src/test/authentication/t/001_password.pl
+++ b/src/test/authentication/t/001_password.pl
@@ -63,7 +63,7 @@ sub test_conn
# Initialize primary node
my $node = PostgreSQL::Test::Cluster->new('primary');
$node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
$node->start;
# could fail in FIPS mode
diff --git a/src/test/authentication/t/003_peer.pl b/src/test/authentication/t/003_peer.pl
index 69ba73bd2b9..8e1b0477d6b 100644
--- a/src/test/authentication/t/003_peer.pl
+++ b/src/test/authentication/t/003_peer.pl
@@ -71,7 +71,7 @@ sub test_role
my $node = PostgreSQL::Test::Cluster->new('node');
$node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
$node->start;
# Set pg_hba.conf with the peer authentication.
diff --git a/src/test/authentication/t/005_sspi.pl b/src/test/authentication/t/005_sspi.pl
index b480b702590..f9b61babcd7 100644
--- a/src/test/authentication/t/005_sspi.pl
+++ b/src/test/authentication/t/005_sspi.pl
@@ -18,7 +18,7 @@ if (!$windows_os || $use_unix_sockets)
# Initialize primary node
my $node = PostgreSQL::Test::Cluster->new('primary');
$node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
$node->start;
my $huge_pages_status =
diff --git a/src/test/kerberos/t/001_auth.pl b/src/test/kerberos/t/001_auth.pl
index 6748b109dec..afc3130e720 100644
--- a/src/test/kerberos/t/001_auth.pl
+++ b/src/test/kerberos/t/001_auth.pl
@@ -65,7 +65,7 @@ $node->append_conf(
'postgresql.conf', qq{
listen_addresses = '$hostaddr'
krb_server_keyfile = '$krb->{keytab}'
-log_connections = on
+log_connections = 'all'
lc_messages = 'C'
});
$node->start;
diff --git a/src/test/ldap/t/001_auth.pl b/src/test/ldap/t/001_auth.pl
index 352b0fc1fa7..b6ee386679d 100644
--- a/src/test/ldap/t/001_auth.pl
+++ b/src/test/ldap/t/001_auth.pl
@@ -47,7 +47,7 @@ note "setting up PostgreSQL instance";
my $node = PostgreSQL::Test::Cluster->new('node');
$node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
$node->start;
$node->safe_psql('postgres', 'CREATE USER test0;');
diff --git a/src/test/ldap/t/002_bindpasswd.pl b/src/test/ldap/t/002_bindpasswd.pl
index f8beba2b279..2acf96aeb6d 100644
--- a/src/test/ldap/t/002_bindpasswd.pl
+++ b/src/test/ldap/t/002_bindpasswd.pl
@@ -43,7 +43,7 @@ note "setting up PostgreSQL instance";
my $node = PostgreSQL::Test::Cluster->new('node');
$node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
$node->start;
$node->safe_psql('postgres', 'CREATE USER test0;');
diff --git a/src/test/modules/ldap_password_func/t/001_mutated_bindpasswd.pl b/src/test/modules/ldap_password_func/t/001_mutated_bindpasswd.pl
index 9b062e1c800..4591b5568a8 100644
--- a/src/test/modules/ldap_password_func/t/001_mutated_bindpasswd.pl
+++ b/src/test/modules/ldap_password_func/t/001_mutated_bindpasswd.pl
@@ -42,7 +42,7 @@ note "setting up PostgreSQL instance";
my $node = PostgreSQL::Test::Cluster->new('node');
$node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
$node->append_conf('postgresql.conf',
"shared_preload_libraries = 'ldap_password_func'");
$node->start;
diff --git a/src/test/modules/oauth_validator/t/001_server.pl b/src/test/modules/oauth_validator/t/001_server.pl
index 6fa59fbeb25..27829680439 100644
--- a/src/test/modules/oauth_validator/t/001_server.pl
+++ b/src/test/modules/oauth_validator/t/001_server.pl
@@ -43,7 +43,7 @@ if ($ENV{with_python} ne 'yes')
my $node = PostgreSQL::Test::Cluster->new('primary');
$node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
$node->append_conf('postgresql.conf',
"oauth_validator_libraries = 'validator'\n");
$node->start;
diff --git a/src/test/modules/oauth_validator/t/002_client.pl b/src/test/modules/oauth_validator/t/002_client.pl
index ab83258d736..aa944ba5f2f 100644
--- a/src/test/modules/oauth_validator/t/002_client.pl
+++ b/src/test/modules/oauth_validator/t/002_client.pl
@@ -26,7 +26,7 @@ if (!$ENV{PG_TEST_EXTRA} || $ENV{PG_TEST_EXTRA} !~ /\boauth\b/)
my $node = PostgreSQL::Test::Cluster->new('primary');
$node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
$node->append_conf('postgresql.conf',
"oauth_validator_libraries = 'validator'\n");
$node->start;
diff --git a/src/test/postmaster/t/002_connection_limits.pl b/src/test/postmaster/t/002_connection_limits.pl
index 8cfa6e0ced5..a221501c206 100644
--- a/src/test/postmaster/t/002_connection_limits.pl
+++ b/src/test/postmaster/t/002_connection_limits.pl
@@ -19,7 +19,7 @@ $node->init(
$node->append_conf('postgresql.conf', "max_connections = 6");
$node->append_conf('postgresql.conf', "reserved_connections = 2");
$node->append_conf('postgresql.conf', "superuser_reserved_connections = 1");
-$node->append_conf('postgresql.conf', "log_connections = on");
+$node->append_conf('postgresql.conf', "log_connections = 'all'");
$node->start;
$node->safe_psql(
diff --git a/src/test/postmaster/t/003_start_stop.pl b/src/test/postmaster/t/003_start_stop.pl
index 036b296f72b..08cd7a4857e 100644
--- a/src/test/postmaster/t/003_start_stop.pl
+++ b/src/test/postmaster/t/003_start_stop.pl
@@ -29,7 +29,7 @@ $node->append_conf('postgresql.conf', "max_connections = 5");
$node->append_conf('postgresql.conf', "max_wal_senders = 0");
$node->append_conf('postgresql.conf', "autovacuum_max_workers = 1");
$node->append_conf('postgresql.conf', "max_worker_processes = 1");
-$node->append_conf('postgresql.conf', "log_connections = on");
+$node->append_conf('postgresql.conf', "log_connections = 'all'");
$node->append_conf('postgresql.conf', "log_min_messages = debug2");
$node->append_conf('postgresql.conf',
"authentication_timeout = '$authentication_timeout s'");
diff --git a/src/test/recovery/t/013_crash_restart.pl b/src/test/recovery/t/013_crash_restart.pl
index cd848918d00..2b6ec94cd75 100644
--- a/src/test/recovery/t/013_crash_restart.pl
+++ b/src/test/recovery/t/013_crash_restart.pl
@@ -27,7 +27,7 @@ $node->start();
$node->safe_psql(
'postgres',
q[ALTER SYSTEM SET restart_after_crash = 1;
- ALTER SYSTEM SET log_connections = 1;
+ ALTER SYSTEM SET log_connections = 'all';
SELECT pg_reload_conf();]);
# Run psql, keeping session alive, so we have an alive backend to kill.
diff --git a/src/test/recovery/t/022_crash_temp_files.pl b/src/test/recovery/t/022_crash_temp_files.pl
index 483a416723f..5d4b695c193 100644
--- a/src/test/recovery/t/022_crash_temp_files.pl
+++ b/src/test/recovery/t/022_crash_temp_files.pl
@@ -26,7 +26,7 @@ $node->start();
$node->safe_psql(
'postgres',
q[ALTER SYSTEM SET remove_temp_files_after_crash = on;
- ALTER SYSTEM SET log_connections = 1;
+ ALTER SYSTEM SET log_connections = 'all';
ALTER SYSTEM SET work_mem = '64kB';
ALTER SYSTEM SET restart_after_crash = on;
SELECT pg_reload_conf();]);
diff --git a/src/test/recovery/t/032_relfilenode_reuse.pl b/src/test/recovery/t/032_relfilenode_reuse.pl
index ddb7223b337..388a50add7a 100644
--- a/src/test/recovery/t/032_relfilenode_reuse.pl
+++ b/src/test/recovery/t/032_relfilenode_reuse.pl
@@ -14,7 +14,7 @@ $node_primary->init(allows_streaming => 1);
$node_primary->append_conf(
'postgresql.conf', q[
allow_in_place_tablespaces = true
-log_connections=on
+log_connections='all'
# to avoid "repairing" corruption
full_page_writes=off
log_min_messages=debug2
diff --git a/src/test/recovery/t/037_invalid_database.pl b/src/test/recovery/t/037_invalid_database.pl
index bdf39397397..ea62650b767 100644
--- a/src/test/recovery/t/037_invalid_database.pl
+++ b/src/test/recovery/t/037_invalid_database.pl
@@ -15,7 +15,7 @@ $node->append_conf(
autovacuum = off
max_prepared_transactions=5
log_min_duration_statement=0
-log_connections=on
+log_connections='all'
log_disconnections=on
));
diff --git a/src/test/ssl/t/SSL/Server.pm b/src/test/ssl/t/SSL/Server.pm
index 447469d8937..7bc45ee7611 100644
--- a/src/test/ssl/t/SSL/Server.pm
+++ b/src/test/ssl/t/SSL/Server.pm
@@ -200,7 +200,7 @@ sub configure_test_server_for_ssl
$node->append_conf(
'postgresql.conf', <<EOF
fsync=off
-log_connections=on
+log_connections='all'
log_hostname=on
listen_addresses='$serverhost'
log_statement=all
diff --git a/src/tools/ci/pg_ci_base.conf b/src/tools/ci/pg_ci_base.conf
index d8faa9c26c1..5593827eb4f 100644
--- a/src/tools/ci/pg_ci_base.conf
+++ b/src/tools/ci/pg_ci_base.conf
@@ -8,7 +8,7 @@ max_prepared_transactions = 10
# Settings that make logs more useful
log_autovacuum_min_duration = 0
log_checkpoints = true
-log_connections = true
+log_connections = 'all'
log_disconnections = true
log_line_prefix = '%m [%p][%b] %q[%a][%v:%x] '
log_lock_waits = true
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index cfbab589d61..59839013d28 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -483,6 +483,7 @@ ConnCacheKey
ConnParams
ConnStatusType
ConnType
+ConnectionLogType
ConnectionStateEnum
ConsiderSplitContext
Const
--
2.34.1
^ permalink raw reply [nested|flat] 24+ messages in thread
* Re: Log connection establishment timings
2025-02-25 20:23 Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-25 21:36 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-26 04:46 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
2025-02-26 07:41 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-26 18:45 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-27 06:50 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-27 16:08 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-27 16:30 ` Re: Log connection establishment timings Andres Freund <[email protected]>
2025-02-27 22:55 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
@ 2025-02-28 05:54 ` Bertrand Drouvot <[email protected]>
2025-02-28 22:52 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
0 siblings, 1 reply; 24+ messages in thread
From: Bertrand Drouvot @ 2025-02-28 05:54 UTC (permalink / raw)
To: Melanie Plageman <[email protected]>; +Cc: Andres Freund <[email protected]>; Fujii Masao <[email protected]>; Guillaume Lelarge <[email protected]>; pgsql-hackers; Daniel Gustafsson <[email protected]>; [email protected]; Jelte Fennema-Nio <[email protected]>; Jacob Champion <[email protected]>
Hi,
On Thu, Feb 27, 2025 at 05:55:19PM -0500, Melanie Plageman wrote:
> On Thu, Feb 27, 2025 at 11:30 AM Andres Freund <[email protected]> wrote:
> >
> > On 2025-02-27 11:08:04 -0500, Melanie Plageman wrote:
> >
> > > However, since that is a bigger project (with more refactoring, etc),
> > > he suggested that we change log_connections to a GUC_LIST
> > > (ConfigureNamesString) with options like "none", "received,
> > > "authenticated", "authorized", "all".
> >
> > Yep.
>
> I've done a draft of this in attached v7 (see 0001).
Thanks for the patch!
> It still needs polishing (e.g. I need to figure out where to put the new guc hook
> functions and enums and such)
yeah, I wonder if it would make sense to create new dedicated "connection_logging"
file(s).
>, but I want to see if this is a viable direction forward.
>
> I'm worried the list of possible connection log messages could get
> unwieldy if we add many more.
Thinking out loud, I'm not sure we'd add "many more" but maybe what we could do
is to introduce some predefined groups like:
'basic' (that would be equivalent to 'received, + timings introduced in 0002')
'security' (equivalent to 'authenticated,authorized')
Not saying we need to create this kind of predefined groups now, just an idea
in case we'd add many more: that could "help" the user experience, or are you
more concerned about the code maintenance?
Just did a quick test, (did not look closely at the code), and it looks like
that:
'all': does not report the "received" (but does report authenticated and authorized)
'received': does not work?
'authenticated': works
'authorized': works
Regards,
--
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com
^ permalink raw reply [nested|flat] 24+ messages in thread
* Re: Log connection establishment timings
2025-02-25 20:23 Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-25 21:36 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-26 04:46 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
2025-02-26 07:41 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-26 18:45 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-27 06:50 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-27 16:08 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-27 16:30 ` Re: Log connection establishment timings Andres Freund <[email protected]>
2025-02-27 22:55 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-28 05:54 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
@ 2025-02-28 22:52 ` Melanie Plageman <[email protected]>
2025-03-04 04:45 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
0 siblings, 1 reply; 24+ messages in thread
From: Melanie Plageman @ 2025-02-28 22:52 UTC (permalink / raw)
To: Bertrand Drouvot <[email protected]>; +Cc: Andres Freund <[email protected]>; Fujii Masao <[email protected]>; Guillaume Lelarge <[email protected]>; pgsql-hackers; Daniel Gustafsson <[email protected]>; [email protected]; Jelte Fennema-Nio <[email protected]>; Jacob Champion <[email protected]>
On Fri, Feb 28, 2025 at 12:54 AM Bertrand Drouvot
<[email protected]> wrote:
>
> On Thu, Feb 27, 2025 at 05:55:19PM -0500, Melanie Plageman wrote:
> > It still needs polishing (e.g. I need to figure out where to put the new guc hook
> > functions and enums and such)
>
> yeah, I wonder if it would make sense to create new dedicated "connection_logging"
> file(s).
I think for now there isn't enough for a new file. I think these are
probably okay in postmaster.c since this has to do with postmaster
starting new connections.
> > I'm worried the list of possible connection log messages could get
> > unwieldy if we add many more.
>
> Thinking out loud, I'm not sure we'd add "many more" but maybe what we could do
> is to introduce some predefined groups like:
>
> 'basic' (that would be equivalent to 'received, + timings introduced in 0002')
> 'security' (equivalent to 'authenticated,authorized')
>
> Not saying we need to create this kind of predefined groups now, just an idea
> in case we'd add many more: that could "help" the user experience, or are you
> more concerned about the code maintenance?
I was more worried about the user having to provide very long lists.
But groupings could be a sensible solution in the future.
> Just did a quick test, (did not look closely at the code), and it looks like
> that:
>
> 'all': does not report the "received" (but does report authenticated and authorized)
> 'received': does not work?
> 'authenticated': works
> 'authorized': works
Thanks for testing! Ouch, there were many bugs in that prototype. My
enums were broken and a few other things.
I found some bugs in 0002 as well. Attached v8 fixes the issues I found so far.
We have to be really careful about when log_connections is actually
set before we use it -- I fixed some issues with that.
I decided to move the creation_time out of ClientSocket and into
BackendStartupData, but that meant I had to save it in the
ConnectionTiming because we don't have access to the
BackendStartupData anymore in PostgresMain(). That means
ConnectionTiming is now a mixture of times and durations. I think that
should be okay (i.e. not too confusing and gross), but I'm not sure.
It is called ConnectionTiming and not ConnectionDuration, after all.
- Melanie
Attachments:
[text/x-patch] v8-0001-Modularize-log_connections-output.patch (28.1K, ../../CAAKRu_ZcseVdWMz9vxfb9yavS+JE762cXFJjzWsPLjvEPMckNg@mail.gmail.com/2-v8-0001-Modularize-log_connections-output.patch)
download | inline diff:
From 0ee1cd306a4c27e5ec0d1860ce7cd219bb761fed Mon Sep 17 00:00:00 2001
From: Melanie Plageman <[email protected]>
Date: Thu, 27 Feb 2025 17:32:17 -0500
Subject: [PATCH v8 1/2] Modularize log_connections output
Convert the boolean log_connections GUC into a list GUC of the
connection stages to log. This obsoletes log_disconnections, as
'disconnected' is now a log_connections option.
The current log_connections options are 'received', 'authenticated',
'authorized', and 'disconnected'. The empty string disables all
connection logging. 'all' enables all available connection logging.
This gives users more control over the volume of connection logging.
This patch has the same behavior as [1] but was developed independently.
The idea to replace log_disconnections with a log_connections option
does, however, come from that thread.
[1] https://www.postgresql.org/message-id/flat/CAA8Fd-qCB96uwfgMKrzfNs32mqqysi53yZFNVaRNJ6xDthZEgA%40mail.gmail.com
Discussion: https://postgr.es/m/flat/Z8FPpJPDLHWNuV2c%40ip-10-97-1-34.eu-west-3.compute.internal#35525b4425c5f8ecfe52ec6ad859ef9a
---
doc/src/sgml/config.sgml | 48 +++++-------
src/backend/libpq/auth.c | 8 +-
src/backend/postmaster/postmaster.c | 77 ++++++++++++++++++-
src/backend/tcop/backend_startup.c | 4 +-
src/backend/tcop/postgres.c | 13 +---
src/backend/utils/init/postinit.c | 2 +-
src/backend/utils/misc/guc_tables.c | 29 +++----
src/backend/utils/misc/postgresql.conf.sample | 5 +-
src/include/postmaster/postmaster.h | 16 +++-
src/include/tcop/tcopprot.h | 1 -
src/include/utils/guc_hooks.h | 2 +
.../libpq/t/005_negotiate_encryption.pl | 3 +-
src/test/authentication/t/001_password.pl | 2 +-
src/test/authentication/t/003_peer.pl | 2 +-
src/test/authentication/t/005_sspi.pl | 2 +-
src/test/kerberos/t/001_auth.pl | 2 +-
src/test/ldap/t/001_auth.pl | 2 +-
src/test/ldap/t/002_bindpasswd.pl | 2 +-
.../t/001_mutated_bindpasswd.pl | 2 +-
.../modules/oauth_validator/t/001_server.pl | 2 +-
.../modules/oauth_validator/t/002_client.pl | 2 +-
.../postmaster/t/002_connection_limits.pl | 2 +-
src/test/postmaster/t/003_start_stop.pl | 2 +-
src/test/recovery/t/013_crash_restart.pl | 2 +-
src/test/recovery/t/022_crash_temp_files.pl | 2 +-
src/test/recovery/t/032_relfilenode_reuse.pl | 2 +-
src/test/recovery/t/037_invalid_database.pl | 3 +-
src/test/ssl/t/SSL/Server.pm | 2 +-
src/tools/ci/pg_ci_base.conf | 3 +-
src/tools/pgindent/typedefs.list | 1 +
30 files changed, 155 insertions(+), 90 deletions(-)
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index e55700f35b8..4d2bbb3f720 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -140,7 +140,7 @@
An example of what this file might look like is:
<programlisting>
# This is a comment
-log_connections = yes
+log_connections = 'all'
log_destination = 'syslog'
search_path = '"$user", public'
shared_buffers = 128MB
@@ -337,7 +337,7 @@ UPDATE pg_settings SET setting = reset_val WHERE name = 'configuration_parameter
<option>-c name=value</option> command-line parameter, or its equivalent
<option>--name=value</option> variation. For example,
<programlisting>
-postgres -c log_connections=yes --log-destination='syslog'
+postgres -c log_connections='all' --log-destination='syslog'
</programlisting>
Settings provided in this way override those set via
<filename>postgresql.conf</filename> or <command>ALTER SYSTEM</command>,
@@ -7315,20 +7315,28 @@ local0.* /var/log/postgresql
</varlistentry>
<varlistentry id="guc-log-connections" xreflabel="log_connections">
- <term><varname>log_connections</varname> (<type>boolean</type>)
+ <term><varname>log_connections</varname> (<type>string</type>)
<indexterm>
<primary><varname>log_connections</varname> configuration parameter</primary>
</indexterm>
</term>
<listitem>
<para>
- Causes each attempted connection to the server to be logged,
- as well as successful completion of both client authentication (if
- necessary) and authorization.
- Only superusers and users with the appropriate <literal>SET</literal>
- privilege can change this parameter at session start,
- and it cannot be changed at all within a session.
- The default is <literal>off</literal>.
+ Causes the specified stages of each connection attempt to the server to
+ be logged. Only superusers and users with the appropriate
+ <literal>SET</literal> privilege can change this parameter at session
+ start, and it cannot be changed at all within a session. The default is
+ <literal>''</literal> which causes no connection logging messages to be
+ emitted.
+ </para>
+
+ <para>
+ May be set to <literal>''</literal> to disable connection logging,
+ <literal>'all'</literal> to log all available connection stages, or a
+ comma-separated list of specific connection stages to log. The valid
+ options are <literal>received</literal>,
+ <literal>authenticated</literal>, <literal>authorized</literal>, and
+ <literal>disconnected</literal>.
</para>
<note>
@@ -7342,26 +7350,6 @@ local0.* /var/log/postgresql
</listitem>
</varlistentry>
- <varlistentry id="guc-log-disconnections" xreflabel="log_disconnections">
- <term><varname>log_disconnections</varname> (<type>boolean</type>)
- <indexterm>
- <primary><varname>log_disconnections</varname> configuration parameter</primary>
- </indexterm>
- </term>
- <listitem>
- <para>
- Causes session terminations to be logged. The log output
- provides information similar to <varname>log_connections</varname>,
- plus the duration of the session.
- Only superusers and users with the appropriate <literal>SET</literal>
- privilege can change this parameter at session start,
- and it cannot be changed at all within a session.
- The default is <literal>off</literal>.
- </para>
- </listitem>
- </varlistentry>
-
-
<varlistentry id="guc-log-duration" xreflabel="log_duration">
<term><varname>log_duration</varname> (<type>boolean</type>)
<indexterm>
diff --git a/src/backend/libpq/auth.c b/src/backend/libpq/auth.c
index 81e2f8184e3..da7b46720d4 100644
--- a/src/backend/libpq/auth.c
+++ b/src/backend/libpq/auth.c
@@ -317,7 +317,8 @@ auth_failed(Port *port, int status, const char *logdetail)
/*
* Sets the authenticated identity for the current user. The provided string
* will be stored into MyClientConnectionInfo, alongside the current HBA
- * method in use. The ID will be logged if log_connections is enabled.
+ * method in use. The ID will be logged if log_connections has the
+ * 'authenticated' option specified.
*
* Auth methods should call this routine exactly once, as soon as the user is
* successfully authenticated, even if they have reasons to know that
@@ -349,7 +350,7 @@ set_authn_id(Port *port, const char *id)
MyClientConnectionInfo.authn_id = MemoryContextStrdup(TopMemoryContext, id);
MyClientConnectionInfo.auth_method = port->hba->auth_method;
- if (Log_connections)
+ if (log_connections & LOG_CONNECTION_AUTHENTICATED)
{
ereport(LOG,
errmsg("connection authenticated: identity=\"%s\" method=%s "
@@ -633,7 +634,8 @@ ClientAuthentication(Port *port)
#endif
}
- if (Log_connections && status == STATUS_OK &&
+ if ((log_connections & LOG_CONNECTION_AUTHENTICATED) &&
+ status == STATUS_OK &&
!MyClientConnectionInfo.authn_id)
{
/*
diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index 5dd3b6a4fd4..315f5a55a34 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -118,6 +118,7 @@
#include "utils/pidfile.h"
#include "utils/timestamp.h"
#include "utils/varlena.h"
+#include "utils/guc_hooks.h"
#ifdef EXEC_BACKEND
#include "common/file_utils.h"
@@ -237,7 +238,8 @@ int PreAuthDelay = 0;
int AuthenticationTimeout = 60;
bool log_hostname; /* for ps display and logging */
-bool Log_connections = false;
+char *log_connections_string = NULL;
+int log_connections = 0;
bool enable_bonjour = false;
char *bonjour_name;
@@ -1517,6 +1519,79 @@ checkControlFile(void)
FreeFile(fp);
}
+/*
+ * Validate the input for the log_connections GUC.
+ */
+bool
+check_log_connections(char **newval, void **extra, GucSource source)
+{
+ int flags = 0;
+ char *rawstring = NULL;
+ List *elemlist;
+ ListCell *l;
+
+ char *effval = *newval;
+
+ /*
+ * log_connections can be 'all', '', or a list of comma-separated options.
+ */
+ if (pg_strcasecmp(*newval, "all") == 0)
+ effval = "received, authenticated, authorized, disconnected";
+
+ /* Need a modifiable copy of string */
+ rawstring = pstrdup(effval);
+
+ if (!SplitGUCList(rawstring, ',', &elemlist))
+ {
+ GUC_check_errdetail("Invalid list syntax in parameter \"log_connections\".");
+ goto log_connections_error;
+ }
+
+ foreach(l, elemlist)
+ {
+ char *item = (char *) lfirst(l);
+
+ if (pg_strcasecmp(item, "received") == 0)
+ flags |= LOG_CONNECTION_RECEIVED;
+ else if (pg_strcasecmp(item, "authenticated") == 0)
+ flags |= LOG_CONNECTION_AUTHENTICATED;
+ else if (pg_strcasecmp(item, "authorized") == 0)
+ flags |= LOG_CONNECTION_AUTHORIZED;
+ else if (pg_strcasecmp(item, "disconnected") == 0)
+ flags |= LOG_CONNECTION_DISCONNECTED;
+ else if (pg_strcasecmp(item, "all") == 0)
+ {
+ GUC_check_errdetail("Must specify \"all\" alone with no additional options, whitespace, or characters.");
+ goto log_connections_error;
+ }
+ else
+ {
+ GUC_check_errdetail("Invalid option \"%s\".", item);
+ goto log_connections_error;
+ }
+ }
+
+ pfree(rawstring);
+ list_free(elemlist);
+
+ /* Save the flags in *extra, for use by assign_log_connections */
+ *extra = guc_malloc(ERROR, sizeof(int));
+ *((int *) *extra) = flags;
+
+ return true;
+
+log_connections_error:
+ pfree(rawstring);
+ list_free(elemlist);
+ return false;
+}
+
+void
+assign_log_connections(const char *newval, void *extra)
+{
+ log_connections = *((int *) extra);
+}
+
/*
* Determine how long should we let ServerLoop sleep, in milliseconds.
*
diff --git a/src/backend/tcop/backend_startup.c b/src/backend/tcop/backend_startup.c
index c70746fa562..887c2f177ef 100644
--- a/src/backend/tcop/backend_startup.c
+++ b/src/backend/tcop/backend_startup.c
@@ -201,8 +201,8 @@ BackendInitialize(ClientSocket *client_sock, CAC_state cac)
port->remote_host = MemoryContextStrdup(TopMemoryContext, remote_host);
port->remote_port = MemoryContextStrdup(TopMemoryContext, remote_port);
- /* And now we can issue the Log_connections message, if wanted */
- if (Log_connections)
+ /* And now we can log that the connection was received, if enabled */
+ if (log_connections & LOG_CONNECTION_RECEIVED)
{
if (remote_port[0])
ereport(LOG,
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index f2f75aa0f88..8b403a6cc3d 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -89,9 +89,6 @@ const char *debug_query_string; /* client-supplied query string */
/* Note: whereToSendOutput is initialized for the bootstrap/standalone case */
CommandDest whereToSendOutput = DestDebug;
-/* flag for logging end of session */
-bool Log_disconnections = false;
-
int log_statement = LOGSTMT_NONE;
/* wait N seconds to allow attach from a debugger */
@@ -3653,10 +3650,7 @@ set_debug_options(int debug_flag, GucContext context, GucSource source)
SetConfigOption("log_min_messages", "notice", context, source);
if (debug_flag >= 1 && context == PGC_POSTMASTER)
- {
- SetConfigOption("log_connections", "true", context, source);
- SetConfigOption("log_disconnections", "true", context, source);
- }
+ SetConfigOption("log_connections", "all", context, source);
if (debug_flag >= 2)
SetConfigOption("log_statement", "all", context, source);
if (debug_flag >= 3)
@@ -4271,9 +4265,10 @@ PostgresMain(const char *dbname, const char *username)
/*
* Also set up handler to log session end; we have to wait till now to be
- * sure Log_disconnections has its final value.
+ * sure log_connections has its final value.
*/
- if (IsUnderPostmaster && Log_disconnections)
+ if (IsUnderPostmaster &&
+ (log_connections & LOG_CONNECTION_DISCONNECTED))
on_proc_exit(log_disconnections, 0);
pgstat_report_connect(MyDatabaseId);
diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index 318600d6d02..8811f2ba3e6 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -251,7 +251,7 @@ PerformAuthentication(Port *port)
*/
disable_timeout(STATEMENT_TIMEOUT, false);
- if (Log_connections)
+ if (log_connections & LOG_CONNECTION_AUTHORIZED)
{
StringInfoData logmsg;
diff --git a/src/backend/utils/misc/guc_tables.c b/src/backend/utils/misc/guc_tables.c
index ad25cbb39c5..5b73270c8a9 100644
--- a/src/backend/utils/misc/guc_tables.c
+++ b/src/backend/utils/misc/guc_tables.c
@@ -1219,15 +1219,6 @@ struct config_bool ConfigureNamesBool[] =
true,
NULL, NULL, NULL
},
- {
- {"log_connections", PGC_SU_BACKEND, LOGGING_WHAT,
- gettext_noop("Logs each successful connection."),
- NULL
- },
- &Log_connections,
- false,
- NULL, NULL, NULL
- },
{
{"trace_connection_negotiation", PGC_POSTMASTER, DEVELOPER_OPTIONS,
gettext_noop("Logs details of pre-authentication connection handshake."),
@@ -1238,15 +1229,6 @@ struct config_bool ConfigureNamesBool[] =
false,
NULL, NULL, NULL
},
- {
- {"log_disconnections", PGC_SU_BACKEND, LOGGING_WHAT,
- gettext_noop("Logs end of a session, including duration."),
- NULL
- },
- &Log_disconnections,
- false,
- NULL, NULL, NULL
- },
{
{"log_replication_commands", PGC_SUSET, LOGGING_WHAT,
gettext_noop("Logs each replication command."),
@@ -4850,6 +4832,17 @@ struct config_string ConfigureNamesString[] =
check_debug_io_direct, assign_debug_io_direct, NULL
},
+ {
+ {"log_connections", PGC_SU_BACKEND, LOGGING_WHAT,
+ gettext_noop("Logs information about events during connection establishment."),
+ NULL,
+ GUC_LIST_INPUT
+ },
+ &log_connections_string,
+ "",
+ check_log_connections, assign_log_connections, NULL
+ },
+
{
{"synchronized_standby_slots", PGC_SIGHUP, REPLICATION_PRIMARY,
gettext_noop("Lists streaming replication standby server replication slot "
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index 5362ff80519..bf611317b3f 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -21,7 +21,7 @@
# require a server shutdown and restart to take effect.
#
# Any parameter can also be given as a command-line option to the server, e.g.,
-# "postgres -c log_connections=on". Some parameters can be changed at run time
+# "postgres -c log_connections='all'". Some parameters can be changed at run time
# with the "SET" SQL command.
#
# Memory units: B = bytes Time units: us = microseconds
@@ -578,8 +578,7 @@
# actions running at least this number
# of milliseconds.
#log_checkpoints = on
-#log_connections = off
-#log_disconnections = off
+#log_connections = ''
#log_duration = off
#log_error_verbosity = default # terse, default, or verbose messages
#log_hostname = off
diff --git a/src/include/postmaster/postmaster.h b/src/include/postmaster/postmaster.h
index b6a3f275a1b..ffa30e94aff 100644
--- a/src/include/postmaster/postmaster.h
+++ b/src/include/postmaster/postmaster.h
@@ -63,7 +63,8 @@ extern PGDLLIMPORT char *ListenAddresses;
extern PGDLLIMPORT bool ClientAuthInProgress;
extern PGDLLIMPORT int PreAuthDelay;
extern PGDLLIMPORT int AuthenticationTimeout;
-extern PGDLLIMPORT bool Log_connections;
+extern PGDLLIMPORT int log_connections;
+extern PGDLLIMPORT char *log_connections_string;
extern PGDLLIMPORT bool log_hostname;
extern PGDLLIMPORT bool enable_bonjour;
extern PGDLLIMPORT char *bonjour_name;
@@ -143,4 +144,17 @@ typedef enum DispatchOption
extern DispatchOption parse_dispatch_option(const char *name);
+/*
+ * These flags correspond to the various stages of connection establishment
+ * which may be logged. check_log_connections() converts the options specified
+ * in the log_connections GUC to some combination of these values.
+ */
+typedef enum ConnectionLogOption
+{
+ LOG_CONNECTION_RECEIVED = (1 << 0),
+ LOG_CONNECTION_AUTHENTICATED = (1 << 1),
+ LOG_CONNECTION_AUTHORIZED = (1 << 2),
+ LOG_CONNECTION_DISCONNECTED = (1 << 3),
+} ConnectionLogOption;
+
#endif /* _POSTMASTER_H */
diff --git a/src/include/tcop/tcopprot.h b/src/include/tcop/tcopprot.h
index a62367f7793..dde9b7e9b59 100644
--- a/src/include/tcop/tcopprot.h
+++ b/src/include/tcop/tcopprot.h
@@ -36,7 +36,6 @@ typedef enum
LOGSTMT_ALL, /* log all statements */
} LogStmtLevel;
-extern PGDLLIMPORT bool Log_disconnections;
extern PGDLLIMPORT int log_statement;
/* Flags for restrict_nonsystem_relation_kind value */
diff --git a/src/include/utils/guc_hooks.h b/src/include/utils/guc_hooks.h
index 951451a9765..9a0d8ec85c7 100644
--- a/src/include/utils/guc_hooks.h
+++ b/src/include/utils/guc_hooks.h
@@ -51,6 +51,8 @@ extern bool check_datestyle(char **newval, void **extra, GucSource source);
extern void assign_datestyle(const char *newval, void *extra);
extern bool check_debug_io_direct(char **newval, void **extra, GucSource source);
extern void assign_debug_io_direct(const char *newval, void *extra);
+extern bool check_log_connections(char **newval, void **extra, GucSource source);
+extern void assign_log_connections(const char *newval, void *extra);
extern bool check_default_table_access_method(char **newval, void **extra,
GucSource source);
extern bool check_default_tablespace(char **newval, void **extra,
diff --git a/src/interfaces/libpq/t/005_negotiate_encryption.pl b/src/interfaces/libpq/t/005_negotiate_encryption.pl
index c834fa5149a..d488aa1f1e2 100644
--- a/src/interfaces/libpq/t/005_negotiate_encryption.pl
+++ b/src/interfaces/libpq/t/005_negotiate_encryption.pl
@@ -107,8 +107,7 @@ $node->append_conf(
listen_addresses = '$hostaddr'
# Capturing the EVENTS that occur during tests requires these settings
-log_connections = on
-log_disconnections = on
+log_connections = 'all'
trace_connection_negotiation = on
lc_messages = 'C'
});
diff --git a/src/test/authentication/t/001_password.pl b/src/test/authentication/t/001_password.pl
index 4ce22ccbdf2..72c187fbdc0 100644
--- a/src/test/authentication/t/001_password.pl
+++ b/src/test/authentication/t/001_password.pl
@@ -63,7 +63,7 @@ sub test_conn
# Initialize primary node
my $node = PostgreSQL::Test::Cluster->new('primary');
$node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
$node->start;
# could fail in FIPS mode
diff --git a/src/test/authentication/t/003_peer.pl b/src/test/authentication/t/003_peer.pl
index 69ba73bd2b9..8e1b0477d6b 100644
--- a/src/test/authentication/t/003_peer.pl
+++ b/src/test/authentication/t/003_peer.pl
@@ -71,7 +71,7 @@ sub test_role
my $node = PostgreSQL::Test::Cluster->new('node');
$node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
$node->start;
# Set pg_hba.conf with the peer authentication.
diff --git a/src/test/authentication/t/005_sspi.pl b/src/test/authentication/t/005_sspi.pl
index b480b702590..f9b61babcd7 100644
--- a/src/test/authentication/t/005_sspi.pl
+++ b/src/test/authentication/t/005_sspi.pl
@@ -18,7 +18,7 @@ if (!$windows_os || $use_unix_sockets)
# Initialize primary node
my $node = PostgreSQL::Test::Cluster->new('primary');
$node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
$node->start;
my $huge_pages_status =
diff --git a/src/test/kerberos/t/001_auth.pl b/src/test/kerberos/t/001_auth.pl
index 6748b109dec..afc3130e720 100644
--- a/src/test/kerberos/t/001_auth.pl
+++ b/src/test/kerberos/t/001_auth.pl
@@ -65,7 +65,7 @@ $node->append_conf(
'postgresql.conf', qq{
listen_addresses = '$hostaddr'
krb_server_keyfile = '$krb->{keytab}'
-log_connections = on
+log_connections = 'all'
lc_messages = 'C'
});
$node->start;
diff --git a/src/test/ldap/t/001_auth.pl b/src/test/ldap/t/001_auth.pl
index 352b0fc1fa7..b6ee386679d 100644
--- a/src/test/ldap/t/001_auth.pl
+++ b/src/test/ldap/t/001_auth.pl
@@ -47,7 +47,7 @@ note "setting up PostgreSQL instance";
my $node = PostgreSQL::Test::Cluster->new('node');
$node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
$node->start;
$node->safe_psql('postgres', 'CREATE USER test0;');
diff --git a/src/test/ldap/t/002_bindpasswd.pl b/src/test/ldap/t/002_bindpasswd.pl
index f8beba2b279..2acf96aeb6d 100644
--- a/src/test/ldap/t/002_bindpasswd.pl
+++ b/src/test/ldap/t/002_bindpasswd.pl
@@ -43,7 +43,7 @@ note "setting up PostgreSQL instance";
my $node = PostgreSQL::Test::Cluster->new('node');
$node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
$node->start;
$node->safe_psql('postgres', 'CREATE USER test0;');
diff --git a/src/test/modules/ldap_password_func/t/001_mutated_bindpasswd.pl b/src/test/modules/ldap_password_func/t/001_mutated_bindpasswd.pl
index 9b062e1c800..4591b5568a8 100644
--- a/src/test/modules/ldap_password_func/t/001_mutated_bindpasswd.pl
+++ b/src/test/modules/ldap_password_func/t/001_mutated_bindpasswd.pl
@@ -42,7 +42,7 @@ note "setting up PostgreSQL instance";
my $node = PostgreSQL::Test::Cluster->new('node');
$node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
$node->append_conf('postgresql.conf',
"shared_preload_libraries = 'ldap_password_func'");
$node->start;
diff --git a/src/test/modules/oauth_validator/t/001_server.pl b/src/test/modules/oauth_validator/t/001_server.pl
index 6fa59fbeb25..27829680439 100644
--- a/src/test/modules/oauth_validator/t/001_server.pl
+++ b/src/test/modules/oauth_validator/t/001_server.pl
@@ -43,7 +43,7 @@ if ($ENV{with_python} ne 'yes')
my $node = PostgreSQL::Test::Cluster->new('primary');
$node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
$node->append_conf('postgresql.conf',
"oauth_validator_libraries = 'validator'\n");
$node->start;
diff --git a/src/test/modules/oauth_validator/t/002_client.pl b/src/test/modules/oauth_validator/t/002_client.pl
index ab83258d736..aa944ba5f2f 100644
--- a/src/test/modules/oauth_validator/t/002_client.pl
+++ b/src/test/modules/oauth_validator/t/002_client.pl
@@ -26,7 +26,7 @@ if (!$ENV{PG_TEST_EXTRA} || $ENV{PG_TEST_EXTRA} !~ /\boauth\b/)
my $node = PostgreSQL::Test::Cluster->new('primary');
$node->init;
-$node->append_conf('postgresql.conf', "log_connections = on\n");
+$node->append_conf('postgresql.conf', "log_connections = 'all'\n");
$node->append_conf('postgresql.conf',
"oauth_validator_libraries = 'validator'\n");
$node->start;
diff --git a/src/test/postmaster/t/002_connection_limits.pl b/src/test/postmaster/t/002_connection_limits.pl
index 8cfa6e0ced5..a221501c206 100644
--- a/src/test/postmaster/t/002_connection_limits.pl
+++ b/src/test/postmaster/t/002_connection_limits.pl
@@ -19,7 +19,7 @@ $node->init(
$node->append_conf('postgresql.conf', "max_connections = 6");
$node->append_conf('postgresql.conf', "reserved_connections = 2");
$node->append_conf('postgresql.conf', "superuser_reserved_connections = 1");
-$node->append_conf('postgresql.conf', "log_connections = on");
+$node->append_conf('postgresql.conf', "log_connections = 'all'");
$node->start;
$node->safe_psql(
diff --git a/src/test/postmaster/t/003_start_stop.pl b/src/test/postmaster/t/003_start_stop.pl
index 036b296f72b..08cd7a4857e 100644
--- a/src/test/postmaster/t/003_start_stop.pl
+++ b/src/test/postmaster/t/003_start_stop.pl
@@ -29,7 +29,7 @@ $node->append_conf('postgresql.conf', "max_connections = 5");
$node->append_conf('postgresql.conf', "max_wal_senders = 0");
$node->append_conf('postgresql.conf', "autovacuum_max_workers = 1");
$node->append_conf('postgresql.conf', "max_worker_processes = 1");
-$node->append_conf('postgresql.conf', "log_connections = on");
+$node->append_conf('postgresql.conf', "log_connections = 'all'");
$node->append_conf('postgresql.conf', "log_min_messages = debug2");
$node->append_conf('postgresql.conf',
"authentication_timeout = '$authentication_timeout s'");
diff --git a/src/test/recovery/t/013_crash_restart.pl b/src/test/recovery/t/013_crash_restart.pl
index cd848918d00..2b6ec94cd75 100644
--- a/src/test/recovery/t/013_crash_restart.pl
+++ b/src/test/recovery/t/013_crash_restart.pl
@@ -27,7 +27,7 @@ $node->start();
$node->safe_psql(
'postgres',
q[ALTER SYSTEM SET restart_after_crash = 1;
- ALTER SYSTEM SET log_connections = 1;
+ ALTER SYSTEM SET log_connections = 'all';
SELECT pg_reload_conf();]);
# Run psql, keeping session alive, so we have an alive backend to kill.
diff --git a/src/test/recovery/t/022_crash_temp_files.pl b/src/test/recovery/t/022_crash_temp_files.pl
index 483a416723f..5d4b695c193 100644
--- a/src/test/recovery/t/022_crash_temp_files.pl
+++ b/src/test/recovery/t/022_crash_temp_files.pl
@@ -26,7 +26,7 @@ $node->start();
$node->safe_psql(
'postgres',
q[ALTER SYSTEM SET remove_temp_files_after_crash = on;
- ALTER SYSTEM SET log_connections = 1;
+ ALTER SYSTEM SET log_connections = 'all';
ALTER SYSTEM SET work_mem = '64kB';
ALTER SYSTEM SET restart_after_crash = on;
SELECT pg_reload_conf();]);
diff --git a/src/test/recovery/t/032_relfilenode_reuse.pl b/src/test/recovery/t/032_relfilenode_reuse.pl
index ddb7223b337..388a50add7a 100644
--- a/src/test/recovery/t/032_relfilenode_reuse.pl
+++ b/src/test/recovery/t/032_relfilenode_reuse.pl
@@ -14,7 +14,7 @@ $node_primary->init(allows_streaming => 1);
$node_primary->append_conf(
'postgresql.conf', q[
allow_in_place_tablespaces = true
-log_connections=on
+log_connections='all'
# to avoid "repairing" corruption
full_page_writes=off
log_min_messages=debug2
diff --git a/src/test/recovery/t/037_invalid_database.pl b/src/test/recovery/t/037_invalid_database.pl
index bdf39397397..e03b963f917 100644
--- a/src/test/recovery/t/037_invalid_database.pl
+++ b/src/test/recovery/t/037_invalid_database.pl
@@ -15,8 +15,7 @@ $node->append_conf(
autovacuum = off
max_prepared_transactions=5
log_min_duration_statement=0
-log_connections=on
-log_disconnections=on
+log_connections='all'
));
$node->start;
diff --git a/src/test/ssl/t/SSL/Server.pm b/src/test/ssl/t/SSL/Server.pm
index 447469d8937..7bc45ee7611 100644
--- a/src/test/ssl/t/SSL/Server.pm
+++ b/src/test/ssl/t/SSL/Server.pm
@@ -200,7 +200,7 @@ sub configure_test_server_for_ssl
$node->append_conf(
'postgresql.conf', <<EOF
fsync=off
-log_connections=on
+log_connections='all'
log_hostname=on
listen_addresses='$serverhost'
log_statement=all
diff --git a/src/tools/ci/pg_ci_base.conf b/src/tools/ci/pg_ci_base.conf
index d8faa9c26c1..b05a4844b26 100644
--- a/src/tools/ci/pg_ci_base.conf
+++ b/src/tools/ci/pg_ci_base.conf
@@ -8,7 +8,6 @@ max_prepared_transactions = 10
# Settings that make logs more useful
log_autovacuum_min_duration = 0
log_checkpoints = true
-log_connections = true
-log_disconnections = true
+log_connections = 'all'
log_line_prefix = '%m [%p][%b] %q[%a][%v:%x] '
log_lock_waits = true
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index 56989aa0b84..d155dcff036 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -483,6 +483,7 @@ ConnCacheKey
ConnParams
ConnStatusType
ConnType
+ConnectionLogOption
ConnectionStateEnum
ConsiderSplitContext
Const
--
2.34.1
[text/x-patch] v8-0002-Add-connection-establishment-duration-logging.patch (15.6K, ../../CAAKRu_ZcseVdWMz9vxfb9yavS+JE762cXFJjzWsPLjvEPMckNg@mail.gmail.com/3-v8-0002-Add-connection-establishment-duration-logging.patch)
download | inline diff:
From 22584b57cda98058d2a1d714cc8d45c676935d9d Mon Sep 17 00:00:00 2001
From: Melanie Plageman <[email protected]>
Date: Thu, 27 Feb 2025 17:33:38 -0500
Subject: [PATCH v8 2/2] Add connection establishment duration logging
Add log_connections option 'timings' which logs durations for several
key parts of connection establishment when specified.
For a new 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. Provide visibility into
authentication and fork duration as well as the end-to-end connection
establishment and initialization time with logging.
To make this portable, the timings captured in the postmaster (socket
creation time, fork initiation time) are passed through the ClientSocket
and BackendStartupData structures instead of simply saved in backend
local memory inherited by the child process.
Reviewed-by: Bertrand Drouvot <[email protected]>
Reviewed-by: Fujii Masao <[email protected]>
Reviewed-by: Jelte Fennema-Nio <[email protected]>
Reviewed-by: Jacob Champion <[email protected]>
Reviewed-by: Guillaume Lelarge <[email protected]>
Discussion: https://postgr.es/m/flat/CAAKRu_b_smAHK0ZjrnL5GRxnAVWujEXQWpLXYzGbmpcZd3nLYw%40mail.gmail.com
---
doc/src/sgml/config.sgml | 15 +++++----
src/backend/postmaster/launch_backend.c | 45 +++++++++++++++++++++++++
src/backend/postmaster/postmaster.c | 10 +++++-
src/backend/tcop/postgres.c | 21 ++++++++++++
src/backend/utils/init/globals.c | 2 ++
src/backend/utils/init/postinit.c | 10 ++++++
src/include/libpq/libpq-be.h | 1 +
src/include/miscadmin.h | 2 ++
src/include/portability/instr_time.h | 9 +++++
src/include/postmaster/postmaster.h | 23 +++++++++++++
src/include/tcop/backend_startup.h | 14 ++++++++
src/tools/pgindent/typedefs.list | 1 +
12 files changed, 146 insertions(+), 7 deletions(-)
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 4d2bbb3f720..b1f38b99ee0 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -7331,12 +7331,15 @@ local0.* /var/log/postgresql
</para>
<para>
- May be set to <literal>''</literal> to disable connection logging,
- <literal>'all'</literal> to log all available connection stages, or a
- comma-separated list of specific connection stages to log. The valid
- options are <literal>received</literal>,
- <literal>authenticated</literal>, <literal>authorized</literal>, and
- <literal>disconnected</literal>.
+ May be set to <literal>''</literal> to disable this logging,
+ <literal>'all'</literal> to enable all connection log message types, or
+ a comma-separated list of the specific connection log message types to
+ emit. The valid options are <literal>received</literal>,
+ <literal>authenticated</literal>, <literal>authorized</literal>,
+ <literal>disconnected</literal>, and <literal>timings</literal>. When
+ <literal>timings</literal> is specified, a message is logged the first
+ time the connection is ready for query containing connection
+ establishment durations.
</para>
<note>
diff --git a/src/backend/postmaster/launch_backend.c b/src/backend/postmaster/launch_backend.c
index 47375e5bfaa..67fdad55414 100644
--- a/src/backend/postmaster/launch_backend.c
+++ b/src/backend/postmaster/launch_backend.c
@@ -232,6 +232,11 @@ postmaster_child_launch(BackendType child_type, int child_slot,
Assert(IsPostmasterEnvironment && !IsUnderPostmaster);
+ /* Capture time Postmaster initiates fork for logging */
+ if ((log_connections & LOG_CONNECTION_TIMINGS) &&
+ (child_type == B_BACKEND || child_type == B_WAL_SENDER))
+ INSTR_TIME_SET_CURRENT(((BackendStartupData *) startup_data)->fork_started);
+
#ifdef EXEC_BACKEND
pid = internal_forkexec(child_process_kinds[child_type].name, child_slot,
startup_data, startup_data_len, client_sock);
@@ -240,6 +245,22 @@ postmaster_child_launch(BackendType child_type, int child_slot,
pid = fork_process();
if (pid == 0) /* child */
{
+ /*
+ * Transfer over any log_connections 'timings' data we need that was
+ * collected by the postmaster. We save the time the socket was
+ * created to later log the total connection establishment and setup
+ * time. Calculate the total fork duration now since we have the start
+ * and end times.
+ */
+ if ((log_connections & LOG_CONNECTION_TIMINGS) &&
+ (child_type == B_BACKEND || child_type == B_WAL_SENDER))
+ {
+ BackendStartupData *data = (BackendStartupData *) startup_data;
+
+ conn_timing.fork_duration = INSTR_TIME_GET_DURATION_SINCE(data->fork_started);
+ conn_timing.creation_time = data->socket_created;
+ }
+
/* Close the postmaster's sockets */
ClosePostmasterPorts(child_type == B_LOGGER);
@@ -586,6 +607,7 @@ SubPostmasterMain(int argc, char *argv[])
char *child_kind;
BackendType child_type;
bool found = false;
+ instr_time fork_ended;
/* In EXEC_BACKEND case we will not have inherited these settings */
IsPostmasterEnvironment = true;
@@ -598,6 +620,13 @@ SubPostmasterMain(int argc, char *argv[])
if (argc != 3)
elog(FATAL, "invalid subpostmaster invocation");
+ /*
+ * Set the fork end time. We haven't read the GUC file yet, so we don't
+ * know if we will use this value for logging, but getting the time is
+ * relatively little overhead.
+ */
+ INSTR_TIME_SET_CURRENT(fork_ended);
+
/* Find the entry in child_process_kinds */
if (strncmp(argv[1], "--forkchild=", 12) != 0)
elog(FATAL, "invalid subpostmaster invocation (--forkchild argument missing)");
@@ -648,6 +677,22 @@ SubPostmasterMain(int argc, char *argv[])
/* Read in remaining GUC variables */
read_nondefault_variables();
+ /*
+ * Transfer over any log_connections 'timings' data we need that was
+ * collected by the postmaster. We save the time the socket was created to
+ * later log the total connection establishment and setup time. Calculate
+ * the total fork duration now since we have the start and end times.
+ */
+ if ((log_connections & LOG_CONNECTION_TIMINGS) &&
+ (child_type == B_BACKEND || child_type == B_WAL_SENDER))
+ {
+ BackendStartupData *data = (BackendStartupData *) startup_data;
+
+ conn_timing.fork_duration = fork_ended;
+ INSTR_TIME_SUBTRACT(conn_timing.fork_duration, data->fork_started);
+ conn_timing.creation_time = data->socket_created;
+ }
+
/*
* Check that the data directory looks valid, which will also check the
* privileges on the data directory and update our umask and file/group
diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index 315f5a55a34..67d388ff2d5 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -1536,7 +1536,7 @@ check_log_connections(char **newval, void **extra, GucSource source)
* log_connections can be 'all', '', or a list of comma-separated options.
*/
if (pg_strcasecmp(*newval, "all") == 0)
- effval = "received, authenticated, authorized, disconnected";
+ effval = "received, authenticated, authorized, disconnected, timings";
/* Need a modifiable copy of string */
rawstring = pstrdup(effval);
@@ -1559,6 +1559,8 @@ check_log_connections(char **newval, void **extra, GucSource source)
flags |= LOG_CONNECTION_AUTHORIZED;
else if (pg_strcasecmp(item, "disconnected") == 0)
flags |= LOG_CONNECTION_DISCONNECTED;
+ else if (pg_strcasecmp(item, "timings") == 0)
+ flags |= LOG_CONNECTION_TIMINGS;
else if (pg_strcasecmp(item, "all") == 0)
{
GUC_check_errdetail("Must specify \"all\" alone with no additional options, whitespace, or characters.");
@@ -3553,6 +3555,12 @@ BackendStartup(ClientSocket *client_sock)
BackendStartupData startup_data;
CAC_state cac;
+ /*
+ * Capture time that Postmaster got a socket from accept (for logging
+ * connection establishment duration).
+ */
+ INSTR_TIME_SET_CURRENT(startup_data.socket_created);
+
/*
* Allocate and assign the child slot. Note we must do this before
* forking, so that we can handle failures (out of memory or child-process
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 8b403a6cc3d..8c6fdf4bc9d 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -4147,6 +4147,7 @@ PostgresMain(const char *dbname, const char *username)
volatile bool send_ready_for_query = true;
volatile bool idle_in_transaction_timeout_enabled = false;
volatile bool idle_session_timeout_enabled = false;
+ bool reported_first_ready_for_query = false;
Assert(dbname != NULL);
Assert(username != NULL);
@@ -4602,6 +4603,26 @@ 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.
+ */
+ if (!reported_first_ready_for_query &&
+ (log_connections & LOG_CONNECTION_TIMINGS) &&
+ (AmRegularBackendProcess() || AmWalSenderProcess()))
+ {
+ instr_time total_duration =
+ INSTR_TIME_GET_DURATION_SINCE(conn_timing.creation_time);
+
+ ereport(LOG,
+ errmsg("connection establishment times (ms): total: %ld, fork: %ld, authentication: %ld",
+ (long int) INSTR_TIME_GET_MILLISEC(total_duration),
+ (long int) INSTR_TIME_GET_MILLISEC(conn_timing.fork_duration),
+ (long int) INSTR_TIME_GET_MILLISEC(conn_timing.auth_duration)));
+
+ reported_first_ready_for_query = true;
+ }
ReadyForQuery(whereToSendOutput);
send_ready_for_query = false;
}
diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c
index b844f9fdaef..3c7b14dd57d 100644
--- a/src/backend/utils/init/globals.c
+++ b/src/backend/utils/init/globals.c
@@ -43,6 +43,8 @@ volatile uint32 InterruptHoldoffCount = 0;
volatile uint32 QueryCancelHoldoffCount = 0;
volatile uint32 CritSectionCount = 0;
+ConnectionTiming conn_timing = {0};
+
int MyProcPid;
pg_time_t MyStartTime;
TimestampTz MyStartTimestamp;
diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index 8811f2ba3e6..6d39acffb27 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -190,9 +190,15 @@ GetDatabaseTupleByOid(Oid dboid)
static void
PerformAuthentication(Port *port)
{
+ instr_time auth_start_time;
+
/* This should be set already, but let's make sure */
ClientAuthInProgress = true; /* limit visibility of log messages */
+ /* Capture authentication start time for logging */
+ if (log_connections & LOG_CONNECTION_TIMINGS)
+ INSTR_TIME_SET_CURRENT(auth_start_time);
+
/*
* In EXEC_BACKEND case, we didn't inherit the contents of pg_hba.conf
* etcetera from the postmaster, and have to load them ourselves.
@@ -251,6 +257,10 @@ PerformAuthentication(Port *port)
*/
disable_timeout(STATEMENT_TIMEOUT, false);
+ /* Calculate authentication duration for logging */
+ if (log_connections & LOG_CONNECTION_TIMINGS)
+ conn_timing.auth_duration = INSTR_TIME_GET_DURATION_SINCE(auth_start_time);
+
if (log_connections & LOG_CONNECTION_AUTHORIZED)
{
StringInfoData logmsg;
diff --git a/src/include/libpq/libpq-be.h b/src/include/libpq/libpq-be.h
index 7fe92b15477..7579d96563e 100644
--- a/src/include/libpq/libpq-be.h
+++ b/src/include/libpq/libpq-be.h
@@ -58,6 +58,7 @@ typedef struct
#include "datatype/timestamp.h"
#include "libpq/hba.h"
#include "libpq/pqcomm.h"
+#include "portability/instr_time.h"
/*
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index a2b63495eec..9dd18a2c74f 100644
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -178,6 +178,8 @@ extern PGDLLIMPORT int MaxConnections;
extern PGDLLIMPORT int max_worker_processes;
extern PGDLLIMPORT int max_parallel_workers;
+extern PGDLLIMPORT struct ConnectionTiming conn_timing;
+
extern PGDLLIMPORT int commit_timestamp_buffers;
extern PGDLLIMPORT int multixact_member_buffers;
extern PGDLLIMPORT int multixact_offset_buffers;
diff --git a/src/include/portability/instr_time.h b/src/include/portability/instr_time.h
index f71a851b18d..48d7ff1bfad 100644
--- a/src/include/portability/instr_time.h
+++ b/src/include/portability/instr_time.h
@@ -184,6 +184,15 @@ GetTimerFrequency(void)
#define INSTR_TIME_ACCUM_DIFF(x,y,z) \
((x).ticks += (y).ticks - (z).ticks)
+static inline instr_time
+INSTR_TIME_GET_DURATION_SINCE(instr_time start_time)
+{
+ instr_time now;
+
+ INSTR_TIME_SET_CURRENT(now);
+ INSTR_TIME_SUBTRACT(now, start_time);
+ return now;
+}
#define INSTR_TIME_GET_DOUBLE(t) \
((double) INSTR_TIME_GET_NANOSEC(t) / NS_PER_S)
diff --git a/src/include/postmaster/postmaster.h b/src/include/postmaster/postmaster.h
index ffa30e94aff..70818e70d2a 100644
--- a/src/include/postmaster/postmaster.h
+++ b/src/include/postmaster/postmaster.h
@@ -15,6 +15,7 @@
#include "lib/ilist.h"
#include "miscadmin.h"
+#include "portability/instr_time.h"
/*
* A struct representing an active postmaster child process. This is used
@@ -127,6 +128,27 @@ extern PMChild *AllocDeadEndChild(void);
extern bool ReleasePostmasterChildSlot(PMChild *pmchild);
extern PMChild *FindPostmasterChildByPid(int pid);
+/*
+ * A collection of timings and durations of various stages of connection
+ * establishment and setup for client backends and WAL senders. Used for
+ * log_connections 'timings' option.
+ */
+typedef struct ConnectionTiming
+{
+ /*
+ * The time at which the client socket is created. This is used to log the
+ * total connection establishment and setup time from accept() to first
+ * being ready for query.
+ */
+ instr_time creation_time;
+
+ /* How long it took the backend to be forked. */
+ instr_time fork_duration;
+
+ /* How long authentication took */
+ instr_time auth_duration;
+} ConnectionTiming;
+
/*
* These values correspond to the special must-be-first options for dispatching
* to various subprograms. parse_dispatch_option() can be used to convert an
@@ -155,6 +177,7 @@ typedef enum ConnectionLogOption
LOG_CONNECTION_AUTHENTICATED = (1 << 1),
LOG_CONNECTION_AUTHORIZED = (1 << 2),
LOG_CONNECTION_DISCONNECTED = (1 << 3),
+ LOG_CONNECTION_TIMINGS = (1 << 4),
} ConnectionLogOption;
#endif /* _POSTMASTER_H */
diff --git a/src/include/tcop/backend_startup.h b/src/include/tcop/backend_startup.h
index 73285611203..03192e21387 100644
--- a/src/include/tcop/backend_startup.h
+++ b/src/include/tcop/backend_startup.h
@@ -14,6 +14,8 @@
#ifndef BACKEND_STARTUP_H
#define BACKEND_STARTUP_H
+#include "portability/instr_time.h"
+
/* GUCs */
extern PGDLLIMPORT bool Trace_connection_negotiation;
@@ -37,6 +39,18 @@ typedef enum CAC_state
typedef struct BackendStartupData
{
CAC_state canAcceptConnections;
+
+ /*
+ * Time at which the postmaster initiates a fork of a backend process Only
+ * used for client and wal sender connections.
+ */
+ instr_time fork_started;
+
+ /*
+ * Time at which the connection client socket is created Only used for
+ * client and wal sender connections.
+ */
+ instr_time socket_created;
} BackendStartupData;
extern void BackendMain(const void *startup_data, size_t startup_data_len) pg_attribute_noreturn();
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index d155dcff036..c030047a107 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -485,6 +485,7 @@ ConnStatusType
ConnType
ConnectionLogOption
ConnectionStateEnum
+ConnectionTiming
ConsiderSplitContext
Const
ConstrCheck
--
2.34.1
^ permalink raw reply [nested|flat] 24+ messages in thread
* Re: Log connection establishment timings
2025-02-25 20:23 Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-25 21:36 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-26 04:46 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
2025-02-26 07:41 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-26 18:45 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-27 06:50 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-27 16:08 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-27 16:30 ` Re: Log connection establishment timings Andres Freund <[email protected]>
2025-02-27 22:55 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-28 05:54 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-28 22:52 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
@ 2025-03-04 04:45 ` Fujii Masao <[email protected]>
2025-03-04 23:34 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
0 siblings, 1 reply; 24+ messages in thread
From: Fujii Masao @ 2025-03-04 04:45 UTC (permalink / raw)
To: Melanie Plageman <[email protected]>; Bertrand Drouvot <[email protected]>; +Cc: Andres Freund <[email protected]>; Guillaume Lelarge <[email protected]>; pgsql-hackers; Daniel Gustafsson <[email protected]>; [email protected]; Jelte Fennema-Nio <[email protected]>; Jacob Champion <[email protected]>
On 2025/03/01 7:52, Melanie Plageman wrote:
> On Fri, Feb 28, 2025 at 12:54 AM Bertrand Drouvot
> <[email protected]> wrote:
>>
>> On Thu, Feb 27, 2025 at 05:55:19PM -0500, Melanie Plageman wrote:
>>> It still needs polishing (e.g. I need to figure out where to put the new guc hook
>>> functions and enums and such)
>>
>> yeah, I wonder if it would make sense to create new dedicated "connection_logging"
>> file(s).
>
> I think for now there isn't enough for a new file. I think these are
> probably okay in postmaster.c since this has to do with postmaster
> starting new connections.
>
>>> I'm worried the list of possible connection log messages could get
>>> unwieldy if we add many more.
>>
>> Thinking out loud, I'm not sure we'd add "many more" but maybe what we could do
>> is to introduce some predefined groups like:
>>
>> 'basic' (that would be equivalent to 'received, + timings introduced in 0002')
>> 'security' (equivalent to 'authenticated,authorized')
>>
>> Not saying we need to create this kind of predefined groups now, just an idea
>> in case we'd add many more: that could "help" the user experience, or are you
>> more concerned about the code maintenance?
>
> I was more worried about the user having to provide very long lists.
> But groupings could be a sensible solution in the future.
>
>> Just did a quick test, (did not look closely at the code), and it looks like
>> that:
>>
>> 'all': does not report the "received" (but does report authenticated and authorized)
>> 'received': does not work?
>> 'authenticated': works
>> 'authorized': works
>
> Thanks for testing! Ouch, there were many bugs in that prototype. My
> enums were broken and a few other things.
>
> I found some bugs in 0002 as well. Attached v8 fixes the issues I found so far.
>
> We have to be really careful about when log_connections is actually
> set before we use it -- I fixed some issues with that.
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
Regards,
--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION
^ permalink raw reply [nested|flat] 24+ messages in thread
* Re: Log connection establishment timings
2025-02-25 20:23 Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-25 21:36 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-26 04:46 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
2025-02-26 07:41 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-26 18:45 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-27 06:50 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-27 16:08 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-27 16:30 ` Re: Log connection establishment timings Andres Freund <[email protected]>
2025-02-27 22:55 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-28 05:54 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-28 22:52 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-03-04 04:45 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
@ 2025-03-04 23:34 ` Melanie Plageman <[email protected]>
0 siblings, 0 replies; 24+ messages in thread
From: Melanie Plageman @ 2025-03-04 23:34 UTC (permalink / raw)
To: Fujii Masao <[email protected]>; +Cc: Bertrand Drouvot <[email protected]>; Andres Freund <[email protected]>; Guillaume Lelarge <[email protected]>; pgsql-hackers; Daniel Gustafsson <[email protected]>; [email protected]; Jelte Fennema-Nio <[email protected]>; Jacob Champion <[email protected]>
On Mon, Mar 3, 2025 at 11:45 PM Fujii Masao <[email protected]> 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.gma...
^ permalink raw reply [nested|flat] 24+ messages in thread
* Re: Log connection establishment timings
2025-02-25 20:23 Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-25 21:36 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-26 04:46 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
2025-02-26 07:41 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-26 18:45 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-27 06:50 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-27 16:08 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
@ 2025-02-28 05:16 ` Bertrand Drouvot <[email protected]>
2025-02-28 22:42 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
1 sibling, 1 reply; 24+ messages in thread
From: Bertrand Drouvot @ 2025-02-28 05:16 UTC (permalink / raw)
To: Melanie Plageman <[email protected]>; +Cc: Fujii Masao <[email protected]>; Guillaume Lelarge <[email protected]>; pgsql-hackers; Daniel Gustafsson <[email protected]>; [email protected]; Jelte Fennema-Nio <[email protected]>; Jacob Champion <[email protected]>
Hi,
On Thu, Feb 27, 2025 at 11:08:04AM -0500, Melanie Plageman wrote:
> I was just talking to Andres off-list and he mentioned that the volume
> of log_connections messages added in recent releases can really be a
> problem for users. He said ideally we would emit one message which
> consolidated these (and make sure we did so for failed connections too
> detailing the successfully completed stages).
>
> However, since that is a bigger project (with more refactoring, etc),
> he suggested that we change log_connections to a GUC_LIST
> (ConfigureNamesString) with options like "none", "received,
> "authenticated", "authorized", "all".
>
> Then we could add one like "established" for the final message and
> timings my patch set adds. I think the overhead of an additional log
> message being emitted probably outweighs the overhead of taking those
> additional timings.
>
> String GUCs are a lot more work than enum GUCs, so I was thinking if
> there is a way to do it as an enum.
>
> I think we want the user to be able to specify a list of all the log
> messages they want included, not just have each one include the
> previous ones. So, then it probably has to be a list right? There is
> no good design that would fit as an enum.
Interesting idea... Yeah, that would sound weird with an enum. I could think
about providing an enum per possible combination but I think that would
generate things like 2^N enum and won't be really user friendly (also that would
double each time we'd want to add a new possible "value" becoming quickly
unmanageable).
So yeah, I can't think of anything better than GUC_LIST.
> > I think that's somehow also around code maintenance (not only LOC), say for example
> > if we want to add more "child_type" in the check (no need to remember to update both
> > locations).
>
> I didn't include checking the child_type in that function since it is
> unrelated to instr_time, so it sadly wouldn't help with that. We could
> macro-ize the child_type check were we to add another child_type.
Yup but my idea was to put all those line:
"
if (Log_connections &&
(child_type == B_BACKEND || child_type == B_WAL_SENDER))
{
instr_time fork_time = ((BackendStartupData *) startup_data)->fork_time;
conn_timing.fork_duration = INSTR_TIME_GET_DURATION_SINCE(fork_time);
}
"
into a dedicated helper function.
Regards,
--
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com
^ permalink raw reply [nested|flat] 24+ messages in thread
* Re: Log connection establishment timings
2025-02-25 20:23 Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-25 21:36 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-26 04:46 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
2025-02-26 07:41 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-26 18:45 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-27 06:50 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-27 16:08 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-28 05:16 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
@ 2025-02-28 22:42 ` Melanie Plageman <[email protected]>
2025-03-03 14:07 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
0 siblings, 1 reply; 24+ messages in thread
From: Melanie Plageman @ 2025-02-28 22:42 UTC (permalink / raw)
To: Bertrand Drouvot <[email protected]>; +Cc: Fujii Masao <[email protected]>; Guillaume Lelarge <[email protected]>; pgsql-hackers; Daniel Gustafsson <[email protected]>; [email protected]; Jelte Fennema-Nio <[email protected]>; Jacob Champion <[email protected]>
On Fri, Feb 28, 2025 at 12:16 AM Bertrand Drouvot
<[email protected]> wrote:
>
> Yup but my idea was to put all those line:
>
> "
> if (Log_connections &&
> (child_type == B_BACKEND || child_type == B_WAL_SENDER))
> {
> instr_time fork_time = ((BackendStartupData *) startup_data)->fork_time;
>
> conn_timing.fork_duration = INSTR_TIME_GET_DURATION_SINCE(fork_time);
> }
> "
>
> into a dedicated helper function.
I ended up finding a bug that means that that exact code isn't
duplicated twice now. For EXEC_BACKEND, I have to wait to calculate
the duration until after reading the GUC values but I need to get the
fork end time before that.
I tried coming up with an inline helper to replace this and most
things I tried felt awkward. It has to have backend type and start
time as parameters. And all of these places we have to be super
careful that the GUCs have already been read before using
log_connections, so it seems a bit unsafe to check log_connections
(the global variable) in a function. Someone could call the function
in a different place and maybe not know that log_connections won't be
set there.
Also, I also wasn't sure if it would be weird to call a function like
"LogConnectionTiming()" which in many cases doesn't log the connection
timing (because it is a different backend type).
But maybe I'm not thinking about it correctly. What were you imagining?
- Melanie
^ permalink raw reply [nested|flat] 24+ messages in thread
* Re: Log connection establishment timings
2025-02-25 20:23 Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-25 21:36 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-26 04:46 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
2025-02-26 07:41 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-26 18:45 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-27 06:50 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-27 16:08 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-28 05:16 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-28 22:42 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
@ 2025-03-03 14:07 ` Bertrand Drouvot <[email protected]>
2025-03-04 22:47 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
0 siblings, 1 reply; 24+ messages in thread
From: Bertrand Drouvot @ 2025-03-03 14:07 UTC (permalink / raw)
To: Melanie Plageman <[email protected]>; +Cc: Fujii Masao <[email protected]>; Guillaume Lelarge <[email protected]>; pgsql-hackers; Daniel Gustafsson <[email protected]>; [email protected]; Jelte Fennema-Nio <[email protected]>; Jacob Champion <[email protected]>
Hi,
On Fri, Feb 28, 2025 at 05:42:37PM -0500, Melanie Plageman wrote:
> And all of these places we have to be super
> careful that the GUCs have already been read before using
> log_connections, so it seems a bit unsafe to check log_connections
> (the global variable) in a function.
Yeah, that could be checking before calling the function (the caller would be
responsible for checking log_connections)
> Also, I also wasn't sure if it would be weird to call a function like
> "LogConnectionTiming()" which in many cases doesn't log the connection
> timing (because it is a different backend type).
>
> But maybe I'm not thinking about it correctly. What were you imagining?
I did not imagine that much ;-) I was just seeing this code being duplicated
and just thought about to avoid the duplication. But now that I read your comments
above then I think we could just macro-ize the child_type check (as you mentioned
up-thread). That would avoid the risk to forget to update the 3 locations doing the
exact same check should we add a new child type in the game.
Regards,
--
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com
^ permalink raw reply [nested|flat] 24+ messages in thread
* Re: Log connection establishment timings
2025-02-25 20:23 Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-25 21:36 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-26 04:46 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
2025-02-26 07:41 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-26 18:45 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-27 06:50 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-27 16:08 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-28 05:16 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-28 22:42 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-03-03 14:07 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
@ 2025-03-04 22:47 ` Melanie Plageman <[email protected]>
2025-03-05 08:53 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
0 siblings, 1 reply; 24+ messages in thread
From: Melanie Plageman @ 2025-03-04 22:47 UTC (permalink / raw)
To: Bertrand Drouvot <[email protected]>; +Cc: Fujii Masao <[email protected]>; Guillaume Lelarge <[email protected]>; pgsql-hackers; Daniel Gustafsson <[email protected]>; [email protected]; Jelte Fennema-Nio <[email protected]>; Jacob Champion <[email protected]>
On Mon, Mar 3, 2025 at 9:07 AM Bertrand Drouvot
<[email protected]> wrote:
>
> I did not imagine that much ;-) I was just seeing this code being duplicated
> and just thought about to avoid the duplication. But now that I read your comments
> above then I think we could just macro-ize the child_type check (as you mentioned
> up-thread). That would avoid the risk to forget to update the 3 locations doing the
> exact same check should we add a new child type in the game.
Is there a word we could use to describe what B_BACKEND and
B_WAL_SENDER have in common? They are the only backend types that will
go through the kind of external connection establishment steps (I
think), but I don't know a very accurate way to make that distinction
(which is required to come up with a useful macro name).
- Melanie
^ permalink raw reply [nested|flat] 24+ messages in thread
* Re: Log connection establishment timings
2025-02-25 20:23 Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-25 21:36 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-26 04:46 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
2025-02-26 07:41 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-26 18:45 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-27 06:50 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-27 16:08 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-28 05:16 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-28 22:42 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-03-03 14:07 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-03-04 22:47 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
@ 2025-03-05 08:53 ` Bertrand Drouvot <[email protected]>
0 siblings, 0 replies; 24+ messages in thread
From: Bertrand Drouvot @ 2025-03-05 08:53 UTC (permalink / raw)
To: Melanie Plageman <[email protected]>; +Cc: Fujii Masao <[email protected]>; Guillaume Lelarge <[email protected]>; pgsql-hackers; Daniel Gustafsson <[email protected]>; [email protected]; Jelte Fennema-Nio <[email protected]>; Jacob Champion <[email protected]>
Hi,
On Tue, Mar 04, 2025 at 05:47:26PM -0500, Melanie Plageman wrote:
> On Mon, Mar 3, 2025 at 9:07 AM Bertrand Drouvot
> <[email protected]> wrote:
> >
> > I did not imagine that much ;-) I was just seeing this code being duplicated
> > and just thought about to avoid the duplication. But now that I read your comments
> > above then I think we could just macro-ize the child_type check (as you mentioned
> > up-thread). That would avoid the risk to forget to update the 3 locations doing the
> > exact same check should we add a new child type in the game.
>
> Is there a word we could use to describe what B_BACKEND and
> B_WAL_SENDER have in common? They are the only backend types that will
> go through the kind of external connection establishment steps (I
> think), but I don't know a very accurate way to make that distinction
> (which is required to come up with a useful macro name).
Yeah, what about IS_CONNECTION_TIMED_BACKEND?
Regards,
--
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com
^ permalink raw reply [nested|flat] 24+ messages in thread
* Re: Log connection establishment timings
2025-02-25 20:23 Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-25 21:36 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-26 04:46 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
2025-02-26 07:41 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-26 18:45 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-27 06:50 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
@ 2025-02-27 16:14 ` Andres Freund <[email protected]>
2025-02-28 05:14 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
1 sibling, 1 reply; 24+ messages in thread
From: Andres Freund @ 2025-02-27 16:14 UTC (permalink / raw)
To: Bertrand Drouvot <[email protected]>; +Cc: Melanie Plageman <[email protected]>; Fujii Masao <[email protected]>; Guillaume Lelarge <[email protected]>; pgsql-hackers; Daniel Gustafsson <[email protected]>; [email protected]; Jelte Fennema-Nio <[email protected]>; Jacob Champion <[email protected]>
Hi,
On 2025-02-27 06:50:41 +0000, Bertrand Drouvot wrote:
> On Wed, Feb 26, 2025 at 01:45:39PM -0500, Melanie Plageman wrote:
> > Thanks for the continued review!
> >
> > On Wed, Feb 26, 2025 at 2:41 AM Bertrand Drouvot
> > <[email protected]> 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).
>
> Agree. IIUC, I think that Fujii-san's idea was to extend log_connections with
> a new option "timing" (i.e move it from ConfigureNamesBool to say
> ConfigureNamesEnum with say on, off and timing?). I think that's a good idea.
I don't think the timing overhead is a relevant factor here - compared to the
fork of a new connection or performing authentication the cost of taking a few
timestamps is neglegible. A timestamp costs 10s to 100s of cycles, a fork many
many millions. Even if you have a really slow timestamp function, it's still
going to be way way cheaper.
Greetings,
Andres Freund
^ permalink raw reply [nested|flat] 24+ messages in thread
* Re: Log connection establishment timings
2025-02-25 20:23 Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-25 21:36 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-26 04:46 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
2025-02-26 07:41 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-26 18:45 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-27 06:50 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-27 16:14 ` Re: Log connection establishment timings Andres Freund <[email protected]>
@ 2025-02-28 05:14 ` Bertrand Drouvot <[email protected]>
0 siblings, 0 replies; 24+ messages in thread
From: Bertrand Drouvot @ 2025-02-28 05:14 UTC (permalink / raw)
To: Andres Freund <[email protected]>; +Cc: Melanie Plageman <[email protected]>; Fujii Masao <[email protected]>; Guillaume Lelarge <[email protected]>; pgsql-hackers; Daniel Gustafsson <[email protected]>; [email protected]; Jelte Fennema-Nio <[email protected]>; Jacob Champion <[email protected]>
Hi,
On Thu, Feb 27, 2025 at 11:14:56AM -0500, Andres Freund wrote:
> I don't think the timing overhead is a relevant factor here - compared to the
> fork of a new connection or performing authentication the cost of taking a few
> timestamps is neglegible. A timestamp costs 10s to 100s of cycles, a fork many
> many millions. Even if you have a really slow timestamp function, it's still
> going to be way way cheaper.
That's a very good point, it has to be put in perspective. The difference in
scale is so significant that the timing collection shouldn't be a concern.
Fair point!
Now I'm thinking what about "if" the connection was on a multi-threaded model?
I think we could reach the same conclusion as thread creation overhead is
still substantial (allocating stack space, initializing thread state, and other
kernel-level operations) as compare to a really slow timestamp function.
Regards,
--
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com
^ permalink raw reply [nested|flat] 24+ messages in thread
* Re: Log connection establishment timings
2025-02-25 20:23 Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-25 21:36 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-26 04:46 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
@ 2025-02-26 18:37 ` Melanie Plageman <[email protected]>
1 sibling, 0 replies; 24+ messages in thread
From: Melanie Plageman @ 2025-02-26 18:37 UTC (permalink / raw)
To: Fujii Masao <[email protected]>; +Cc: Bertrand Drouvot <[email protected]>; Guillaume Lelarge <[email protected]>; pgsql-hackers; Daniel Gustafsson <[email protected]>; [email protected]; Jelte Fennema-Nio <[email protected]>; Jacob Champion <[email protected]>
Thanks for the review!
On Tue, Feb 25, 2025 at 11:46 PM Fujii Masao
<[email protected]> wrote:
>
> On 2025/02/26 6:36, Melanie Plageman wrote:
> > On Tue, Feb 25, 2025 at 3:23 PM Melanie Plageman
> > <[email protected]> wrote:
>
> + /* 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?
Ah, great point. It was not intentional. I've added a check for wal
sender to the attached v5.
Are these the only backend types that establish connections from outside?
This makes me wonder if I don't need these checks (for backend type)
before capturing the current time in PerformAuthentication() -- that
is, if they are performing authentication, aren't they inherently one
of these backend types?
> 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?
Ah yes, I did this intentionally originally because I thought someone
might change the value of log_connections in between the start and end
of the duration. I now see you cannot change log_connections after
connection start. So, I can guard these behind log_connections (done
in attached v5).
I hesitate to have a separate guc controlling whether or not we log
connection timing. If we add far more instances of getting the current
time, then perhaps it makes sense. But, as it is, we are adding six
system calls that take on the order of nanoseconds (esp if using
clock_gettime()), whereas emitting each log message -- which
log_connections allows -- will take on the order of micro or even
milliseconds.
> + 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.
I originally included the socket fd because I thought we might end up
printing the times instead of the durations and then users would have
to parse them to get the durations and would need a way to uniquely
identify a connection. This would ideally be a combination of client
address, client port, server address, server port -- but those are
harder to print out (due to IP versions, etc) and harder to parse.
Also, I did notice other places printing the socket (like
BackendStartup() after forking).
Since this version is just printing one message, I have removed the socket fd.
> Including the PID seems unnecessary since it's already available via log_line_prefix with %p?
Ah, great point. I've removed that from the log message in the attached version
- Melanie
Attachments:
[text/x-patch] v5-0001-Add-connection-establishment-duration-logging.patch (11.3K, ../../CAAKRu_Y9sgZAWCiQoHtpwx6Mv28fBGav5ztrWyeSrx+B=ACN6g@mail.gmail.com/2-v5-0001-Add-connection-establishment-duration-logging.patch)
download | inline diff:
From 743d488161758ff923573cc65f3ac437feafd738 Mon Sep 17 00:00:00 2001
From: Melanie Plageman <[email protected]>
Date: Tue, 25 Feb 2025 13:08:48 -0500
Subject: [PATCH v5] Add connection establishment duration logging
Add durations for several key parts of connection establishment when
log_connections is enabled.
For a new 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. Provide visibility into
authentication and fork duration as well as the end-to-end connection
establishment time with logging.
To make this portable, the timestamps captured in the postmaster (socket
creation time, fork initiation time) are passed through the ClientSocket
and BackendStartupData structures instead of simply saved in backend
local memory inherited by the child process.
Reviewed-by: Bertrand Drouvot <[email protected]>
Reviewed-by: Fujii Masao <[email protected]>
Reviewed-by: Jelte Fennema-Nio <[email protected]>
Reviewed-by: Jacob Champion <[email protected]>
Reviewed-by: Guillaume Lelarge <[email protected]>
Discussion: https://postgr.es/m/flat/CAAKRu_b_smAHK0ZjrnL5GRxnAVWujEXQWpLXYzGbmpcZd3nLYw%40mail.gmail.com
---
src/backend/postmaster/launch_backend.c | 23 +++++++++++++++++++++++
src/backend/postmaster/postmaster.c | 8 ++++++++
src/backend/tcop/postgres.c | 21 +++++++++++++++++++++
src/backend/utils/init/globals.c | 2 ++
src/backend/utils/init/postinit.c | 12 ++++++++++++
src/include/libpq/libpq-be.h | 2 ++
src/include/miscadmin.h | 2 ++
src/include/portability/instr_time.h | 9 +++++++++
src/include/postmaster/postmaster.h | 7 +++++++
src/include/tcop/backend_startup.h | 5 +++++
src/tools/pgindent/typedefs.list | 1 +
11 files changed, 92 insertions(+)
diff --git a/src/backend/postmaster/launch_backend.c b/src/backend/postmaster/launch_backend.c
index 47375e5bfaa..c482cb299f7 100644
--- a/src/backend/postmaster/launch_backend.c
+++ b/src/backend/postmaster/launch_backend.c
@@ -232,6 +232,11 @@ postmaster_child_launch(BackendType child_type, int child_slot,
Assert(IsPostmasterEnvironment && !IsUnderPostmaster);
+ /* Capture time Postmaster initiates fork for logging */
+ if (Log_connections &&
+ (child_type == B_BACKEND || child_type == B_WAL_SENDER))
+ INSTR_TIME_SET_CURRENT(((BackendStartupData *) startup_data)->fork_time);
+
#ifdef EXEC_BACKEND
pid = internal_forkexec(child_process_kinds[child_type].name, child_slot,
startup_data, startup_data_len, client_sock);
@@ -240,6 +245,15 @@ postmaster_child_launch(BackendType child_type, int child_slot,
pid = fork_process();
if (pid == 0) /* child */
{
+ /* Calculate total fork duration in child backend for logging */
+ if (Log_connections &&
+ (child_type == B_BACKEND || child_type == B_WAL_SENDER))
+ {
+ instr_time fork_time = ((BackendStartupData *) startup_data)->fork_time;
+
+ conn_timing.fork_duration = INSTR_TIME_GET_DURATION_SINCE(fork_time);
+ }
+
/* Close the postmaster's sockets */
ClosePostmasterPorts(child_type == B_LOGGER);
@@ -618,6 +632,15 @@ 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 (Log_connections &&
+ (child_type == B_BACKEND || child_type == B_WAL_SENDER))
+ {
+ instr_time fork_time = ((BackendStartupData *) startup_data)->fork_time;
+
+ conn_timing.fork_duration = INSTR_TIME_GET_DURATION_SINCE(fork_time);
+ }
+
/* Close the postmaster's sockets (as soon as we know them) */
ClosePostmasterPorts(child_type == B_LOGGER);
diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index 5dd3b6a4fd4..880f491a9f7 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -1685,7 +1685,14 @@ ServerLoop(void)
ClientSocket s;
if (AcceptConnection(events[i].fd, &s) == STATUS_OK)
+ {
+ /*
+ * Capture time that Postmaster got a socket from accept
+ * (for logging connection establishment duration)
+ */
+ INSTR_TIME_SET_CURRENT(s.creation_time);
BackendStartup(&s);
+ }
/* We no longer need the open socket in this process */
if (s.sock != PGINVALID_SOCKET)
@@ -3511,6 +3518,7 @@ BackendStartup(ClientSocket *client_sock)
/* Pass down canAcceptConnections state */
startup_data.canAcceptConnections = cac;
+ INSTR_TIME_SET_ZERO(startup_data.fork_time);
bn->rw = NULL;
/* Hasn't asked to be notified about any bgworkers yet */
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index f2f75aa0f88..61d4ae2474d 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -4153,6 +4153,7 @@ PostgresMain(const char *dbname, const char *username)
volatile bool send_ready_for_query = true;
volatile bool idle_in_transaction_timeout_enabled = false;
volatile bool idle_session_timeout_enabled = false;
+ bool reported_first_ready_for_query = false;
Assert(dbname != NULL);
Assert(username != NULL);
@@ -4607,6 +4608,26 @@ 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.
+ */
+ if (!reported_first_ready_for_query &&
+ Log_connections &&
+ (AmRegularBackendProcess() || AmWalSenderProcess()))
+ {
+ instr_time total_duration =
+ INSTR_TIME_GET_DURATION_SINCE(MyClientSocket->creation_time);
+
+ ereport(LOG,
+ errmsg("connection establishment times (ms): total: %ld, fork: %ld, authentication: %ld",
+ (long int) INSTR_TIME_GET_MILLISEC(total_duration),
+ (long int) INSTR_TIME_GET_MILLISEC(conn_timing.fork_duration),
+ (long int) INSTR_TIME_GET_MILLISEC(conn_timing.auth_duration)));
+
+ reported_first_ready_for_query = true;
+ }
ReadyForQuery(whereToSendOutput);
send_ready_for_query = false;
}
diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c
index b844f9fdaef..3c7b14dd57d 100644
--- a/src/backend/utils/init/globals.c
+++ b/src/backend/utils/init/globals.c
@@ -43,6 +43,8 @@ volatile uint32 InterruptHoldoffCount = 0;
volatile uint32 QueryCancelHoldoffCount = 0;
volatile uint32 CritSectionCount = 0;
+ConnectionTiming conn_timing = {0};
+
int MyProcPid;
pg_time_t MyStartTime;
TimestampTz MyStartTimestamp;
diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index 318600d6d02..30eed2e85f7 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -190,9 +190,16 @@ GetDatabaseTupleByOid(Oid dboid)
static void
PerformAuthentication(Port *port)
{
+ instr_time auth_start_time;
+
/* This should be set already, but let's make sure */
ClientAuthInProgress = true; /* limit visibility of log messages */
+ /* Capture authentication start time for logging */
+ if (Log_connections &&
+ (AmRegularBackendProcess() || AmWalSenderProcess()))
+ INSTR_TIME_SET_CURRENT(auth_start_time);
+
/*
* In EXEC_BACKEND case, we didn't inherit the contents of pg_hba.conf
* etcetera from the postmaster, and have to load them ourselves.
@@ -251,6 +258,11 @@ PerformAuthentication(Port *port)
*/
disable_timeout(STATEMENT_TIMEOUT, false);
+ /* Calculate authentication duration for logging */
+ if (Log_connections &&
+ (AmRegularBackendProcess() || AmWalSenderProcess()))
+ conn_timing.auth_duration = INSTR_TIME_GET_DURATION_SINCE(auth_start_time);
+
if (Log_connections)
{
StringInfoData logmsg;
diff --git a/src/include/libpq/libpq-be.h b/src/include/libpq/libpq-be.h
index 7fe92b15477..b16ad69efff 100644
--- a/src/include/libpq/libpq-be.h
+++ b/src/include/libpq/libpq-be.h
@@ -58,6 +58,7 @@ typedef struct
#include "datatype/timestamp.h"
#include "libpq/hba.h"
#include "libpq/pqcomm.h"
+#include "portability/instr_time.h"
/*
@@ -252,6 +253,7 @@ typedef struct ClientSocket
{
pgsocket sock; /* File descriptor */
SockAddr raddr; /* remote addr (client) */
+ instr_time creation_time;
} ClientSocket;
#ifdef USE_SSL
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index a2b63495eec..9dd18a2c74f 100644
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -178,6 +178,8 @@ extern PGDLLIMPORT int MaxConnections;
extern PGDLLIMPORT int max_worker_processes;
extern PGDLLIMPORT int max_parallel_workers;
+extern PGDLLIMPORT struct ConnectionTiming conn_timing;
+
extern PGDLLIMPORT int commit_timestamp_buffers;
extern PGDLLIMPORT int multixact_member_buffers;
extern PGDLLIMPORT int multixact_offset_buffers;
diff --git a/src/include/portability/instr_time.h b/src/include/portability/instr_time.h
index f71a851b18d..48d7ff1bfad 100644
--- a/src/include/portability/instr_time.h
+++ b/src/include/portability/instr_time.h
@@ -184,6 +184,15 @@ GetTimerFrequency(void)
#define INSTR_TIME_ACCUM_DIFF(x,y,z) \
((x).ticks += (y).ticks - (z).ticks)
+static inline instr_time
+INSTR_TIME_GET_DURATION_SINCE(instr_time start_time)
+{
+ instr_time now;
+
+ INSTR_TIME_SET_CURRENT(now);
+ INSTR_TIME_SUBTRACT(now, start_time);
+ return now;
+}
#define INSTR_TIME_GET_DOUBLE(t) \
((double) INSTR_TIME_GET_NANOSEC(t) / NS_PER_S)
diff --git a/src/include/postmaster/postmaster.h b/src/include/postmaster/postmaster.h
index b6a3f275a1b..71a3f5f644d 100644
--- a/src/include/postmaster/postmaster.h
+++ b/src/include/postmaster/postmaster.h
@@ -15,6 +15,7 @@
#include "lib/ilist.h"
#include "miscadmin.h"
+#include "portability/instr_time.h"
/*
* A struct representing an active postmaster child process. This is used
@@ -126,6 +127,12 @@ extern PMChild *AllocDeadEndChild(void);
extern bool ReleasePostmasterChildSlot(PMChild *pmchild);
extern PMChild *FindPostmasterChildByPid(int pid);
+typedef struct ConnectionTiming
+{
+ instr_time fork_duration;
+ instr_time auth_duration;
+} ConnectionTiming;
+
/*
* These values correspond to the special must-be-first options for dispatching
* to various subprograms. parse_dispatch_option() can be used to convert an
diff --git a/src/include/tcop/backend_startup.h b/src/include/tcop/backend_startup.h
index 73285611203..7d9c43ce77b 100644
--- a/src/include/tcop/backend_startup.h
+++ b/src/include/tcop/backend_startup.h
@@ -14,6 +14,8 @@
#ifndef BACKEND_STARTUP_H
#define BACKEND_STARTUP_H
+#include "portability/instr_time.h"
+
/* GUCs */
extern PGDLLIMPORT bool Trace_connection_negotiation;
@@ -37,6 +39,9 @@ typedef enum CAC_state
typedef struct BackendStartupData
{
CAC_state canAcceptConnections;
+
+ /* Time at which the postmaster initiates a fork of a backend process */
+ instr_time fork_time;
} BackendStartupData;
extern void BackendMain(const void *startup_data, size_t startup_data_len) pg_attribute_noreturn();
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index cfbab589d61..566b0d8d73b 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -484,6 +484,7 @@ ConnParams
ConnStatusType
ConnType
ConnectionStateEnum
+ConnectionTiming
ConsiderSplitContext
Const
ConstrCheck
--
2.34.1
^ permalink raw reply [nested|flat] 24+ messages in thread
end of thread, other threads:[~2025-03-05 08:53 UTC | newest]
Thread overview: 24+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2023-08-09 07:56 [PATCH v4 5/7] Row pattern recognition patch (docs). Tatsuo Ishii <[email protected]>
2025-02-25 20:23 Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-25 21:36 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-26 04:46 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
2025-02-26 07:41 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-26 13:22 ` Re: Log connection establishment timings Guillaume Lelarge <[email protected]>
2025-02-26 18:45 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-26 19:29 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-27 06:50 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-27 16:08 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-27 16:30 ` Re: Log connection establishment timings Andres Freund <[email protected]>
2025-02-27 22:55 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-28 05:54 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-28 22:52 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-03-04 04:45 ` Re: Log connection establishment timings Fujii Masao <[email protected]>
2025-03-04 23:34 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-02-28 05:16 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-28 22:42 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-03-03 14:07 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-03-04 22:47 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
2025-03-05 08:53 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-27 16:14 ` Re: Log connection establishment timings Andres Freund <[email protected]>
2025-02-28 05:14 ` Re: Log connection establishment timings Bertrand Drouvot <[email protected]>
2025-02-26 18:37 ` Re: Log connection establishment timings Melanie Plageman <[email protected]>
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox