Movatterモバイル変換

[0]ホーム
URL:

Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly

 Sign up
Appearance settings

Commit18cd15e

Browse files
Add connection establishment duration logging
Add log_connections option 'setup_durations' which logs durations ofseveral key parts of connection establishment and backend setup.For an incoming connection, starting from when the postmaster gets asocket from accept() and ending when the forked child backend is firstready for query, there are multiple steps that could each take longerthan expected due to external factors. This logging provides visibilityinto authentication and fork duration as well as the end-to-endconnection establishment and backend initialization time.To make this portable, the timings captured in the postmaster (socketcreation time, fork initiation time) are passed through theBackendStartupData.Author: Melanie Plageman <melanieplageman@gmail.com>Reviewed-by: Bertrand Drouvot <bertranddrouvot.pg@gmail.com>Reviewed-by: Fujii Masao <masao.fujii@oss.nttdata.com>Reviewed-by: Daniel Gustafsson <daniel@yesql.se>Reviewed-by: Jacob Champion <jacob.champion@enterprisedb.com>Reviewed-by: Jelte Fennema-Nio <postgres@jeltef.nl>Reviewed-by: Guillaume Lelarge <guillaume.lelarge@dalibo.com>Discussion:https://postgr.es/m/flat/CAAKRu_b_smAHK0ZjrnL5GRxnAVWujEXQWpLXYzGbmpcZd3nLYw%40mail.gmail.com
1 parent9219093 commit18cd15e

File tree

12 files changed

+189
-6
lines changed

12 files changed

+189
-6
lines changed

‎doc/src/sgml/config.sgml

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -7369,6 +7369,19 @@ local0.* /var/log/postgresql
73697369
</entry>
73707370
</row>
73717371

7372+
<row>
7373+
<entry><literal>setup_durations</literal></entry>
7374+
<entry>
7375+
Logs the time spent establishing the connection and setting up the
7376+
backend at the time the connection is ready to execute its first
7377+
query. The log message includes the total setup duration, starting
7378+
from the postmaster accepting the incoming connection and ending
7379+
when the connection is ready for query. It also includes the time
7380+
it took to fork the new backend and the time it took to
7381+
authenticate the user.
7382+
</entry>
7383+
</row>
7384+
73727385
<row>
73737386
<entry><literal>all</literal></entry>
73747387
<entry>

‎src/backend/postmaster/launch_backend.c

Lines changed: 31 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -232,6 +232,10 @@ postmaster_child_launch(BackendType child_type, int child_slot,
232232

233233
Assert(IsPostmasterEnvironment&& !IsUnderPostmaster);
234234

235+
/* Capture time Postmaster initiates process creation for logging */
236+
if (IsExternalConnectionBackend(child_type))
237+
((BackendStartupData*)startup_data)->fork_started=GetCurrentTimestamp();
238+
235239
#ifdefEXEC_BACKEND
236240
pid=internal_forkexec(child_process_kinds[child_type].name,child_slot,
237241
startup_data,startup_data_len,client_sock);
@@ -240,6 +244,16 @@ postmaster_child_launch(BackendType child_type, int child_slot,
240244
pid=fork_process();
241245
if (pid==0)/* child */
242246
{
247+
/* Capture and transfer timings that may be needed for logging */
248+
if (IsExternalConnectionBackend(child_type))
249+
{
250+
conn_timing.socket_create=
251+
((BackendStartupData*)startup_data)->socket_created;
252+
conn_timing.fork_start=
253+
((BackendStartupData*)startup_data)->fork_started;
254+
conn_timing.fork_end=GetCurrentTimestamp();
255+
}
256+
243257
/* Close the postmaster's sockets */
244258
ClosePostmasterPorts(child_type==B_LOGGER);
245259

@@ -586,11 +600,18 @@ SubPostmasterMain(int argc, char *argv[])
586600
char*child_kind;
587601
BackendTypechild_type;
588602
boolfound= false;
603+
TimestampTzfork_end;
589604

590605
/* In EXEC_BACKEND case we will not have inherited these settings */
591606
IsPostmasterEnvironment= true;
592607
whereToSendOutput=DestNone;
593608

609+
/*
610+
* Capture the end of process creation for logging. We don't include the
611+
* time spent copying data from shared memory and setting up the backend.
612+
*/
613+
fork_end=GetCurrentTimestamp();
614+
594615
/* Setup essential subsystems (to ensure elog() behaves sanely) */
595616
InitializeGUCOptions();
596617

@@ -648,6 +669,16 @@ SubPostmasterMain(int argc, char *argv[])
648669
/* Read in remaining GUC variables */
649670
read_nondefault_variables();
650671

672+
/* Capture and transfer timings that may be needed for log_connections */
673+
if (IsExternalConnectionBackend(child_type))
674+
{
675+
conn_timing.socket_create=
676+
((BackendStartupData*)startup_data)->socket_created;
677+
conn_timing.fork_start=
678+
((BackendStartupData*)startup_data)->fork_started;
679+
conn_timing.fork_end=fork_end;
680+
}
681+
651682
/*
652683
* Check that the data directory looks valid, which will also check the
653684
* privileges on the data directory and update our umask and file/group

‎src/backend/postmaster/postmaster.c

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3477,6 +3477,12 @@ BackendStartup(ClientSocket *client_sock)
34773477
BackendStartupDatastartup_data;
34783478
CAC_statecac;
34793479

3480+
/*
3481+
* Capture time that Postmaster got a socket from accept (for logging
3482+
* connection establishment and setup total duration).
3483+
*/
3484+
startup_data.socket_created=GetCurrentTimestamp();
3485+
34803486
/*
34813487
* Allocate and assign the child slot. Note we must do this before
34823488
* forking, so that we can handle failures (out of memory or child-process

‎src/backend/tcop/backend_startup.c

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -46,6 +46,16 @@ boolTrace_connection_negotiation = false;
4646
uint32log_connections=0;
4747
char*log_connections_string=NULL;
4848

49+
/* Other globals */
50+
51+
/*
52+
* ConnectionTiming stores timestamps of various points in connection
53+
* establishment and setup.
54+
* ready_for_use is initialized to a special value here so we can check if
55+
* we've already set it before doing so in PostgresMain().
56+
*/
57+
ConnectionTimingconn_timing= {.ready_for_use=TIMESTAMP_MINUS_INFINITY};
58+
4959
staticvoidBackendInitialize(ClientSocket*client_sock,CAC_statecac);
5060
staticintProcessSSLStartup(Port*port);
5161
staticintProcessStartupPacket(Port*port,boolssl_done,boolgss_done);
@@ -1006,6 +1016,7 @@ validate_log_connections_options(List *elemlist, uint32 *flags)
10061016
{"receipt",LOG_CONNECTION_RECEIPT},
10071017
{"authentication",LOG_CONNECTION_AUTHENTICATION},
10081018
{"authorization",LOG_CONNECTION_AUTHORIZATION},
1019+
{"setup_durations",LOG_CONNECTION_SETUP_DURATIONS},
10091020
{"all",LOG_CONNECTION_ALL},
10101021
};
10111022

‎src/backend/tcop/postgres.c

Lines changed: 33 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -66,6 +66,7 @@
6666
#include"storage/proc.h"
6767
#include"storage/procsignal.h"
6868
#include"storage/sinval.h"
69+
#include"tcop/backend_startup.h"
6970
#include"tcop/fastpath.h"
7071
#include"tcop/pquery.h"
7172
#include"tcop/tcopprot.h"
@@ -4607,6 +4608,38 @@ PostgresMain(const char *dbname, const char *username)
46074608
/* Report any recently-changed GUC options */
46084609
ReportChangedGUCOptions();
46094610

4611+
/*
4612+
* The first time this backend is ready for query, log the
4613+
* durations of the different components of connection
4614+
* establishment and setup.
4615+
*/
4616+
if (conn_timing.ready_for_use==TIMESTAMP_MINUS_INFINITY&&
4617+
(log_connections&LOG_CONNECTION_SETUP_DURATIONS)&&
4618+
IsExternalConnectionBackend(MyBackendType))
4619+
{
4620+
uint64total_duration,
4621+
fork_duration,
4622+
auth_duration;
4623+
4624+
conn_timing.ready_for_use=GetCurrentTimestamp();
4625+
4626+
total_duration=
4627+
TimestampDifferenceMicroseconds(conn_timing.socket_create,
4628+
conn_timing.ready_for_use);
4629+
fork_duration=
4630+
TimestampDifferenceMicroseconds(conn_timing.fork_start,
4631+
conn_timing.fork_end);
4632+
auth_duration=
4633+
TimestampDifferenceMicroseconds(conn_timing.auth_start,
4634+
conn_timing.auth_end);
4635+
4636+
ereport(LOG,
4637+
errmsg("connection ready: setup total=%.3f ms, fork=%.3f ms, authentication=%.3f ms",
4638+
(double)total_duration /NS_PER_US,
4639+
(double)fork_duration /NS_PER_US,
4640+
(double)auth_duration /NS_PER_US));
4641+
}
4642+
46104643
ReadyForQuery(whereToSendOutput);
46114644
send_ready_for_query= false;
46124645
}

‎src/backend/utils/init/postinit.c

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -235,6 +235,9 @@ PerformAuthentication(Port *port)
235235
}
236236
#endif
237237

238+
/* Capture authentication start time for logging */
239+
conn_timing.auth_start=GetCurrentTimestamp();
240+
238241
/*
239242
* Set up a timeout in case a buggy or malicious client fails to respond
240243
* during authentication. Since we're inside a transaction and might do
@@ -253,6 +256,9 @@ PerformAuthentication(Port *port)
253256
*/
254257
disable_timeout(STATEMENT_TIMEOUT, false);
255258

259+
/* Capture authentication end time for logging */
260+
conn_timing.auth_end=GetCurrentTimestamp();
261+
256262
if (log_connections&LOG_CONNECTION_AUTHORIZATION)
257263
{
258264
StringInfoDatalogmsg;

‎src/backend/utils/misc/postgresql.conf.sample

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -580,7 +580,7 @@
580580
#log_checkpoints = on
581581
#log_connections = '' # log aspects of connection setup
582582
# options include receipt, authentication, authorization,
583-
# and all to log all of these aspects
583+
#setup_durations,and all to log all of these aspects
584584
#log_disconnections = off
585585
#log_duration = off # log statement duration
586586
#log_error_verbosity = default# terse, default, or verbose messages

‎src/include/miscadmin.h

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -394,6 +394,14 @@ extern PGDLLIMPORT BackendType MyBackendType;
394394
(AmAutoVacuumLauncherProcess() || \
395395
AmLogicalSlotSyncWorkerProcess())
396396

397+
/*
398+
* Backend types that are spawned by the postmaster to serve a client or
399+
* replication connection. These backend types have in common that they are
400+
* externally initiated.
401+
*/
402+
#defineIsExternalConnectionBackend(backend_type) \
403+
(backend_type == B_BACKEND || backend_type == B_WAL_SENDER)
404+
397405
externconstchar*GetBackendTypeDesc(BackendTypebackendType);
398406

399407
externvoidSetDatabasePath(constchar*path);

‎src/include/tcop/backend_startup.h

Lines changed: 53 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -14,11 +14,16 @@
1414
#ifndefBACKEND_STARTUP_H
1515
#defineBACKEND_STARTUP_H
1616

17+
#include"utils/timestamp.h"
18+
1719
/* GUCs */
1820
externPGDLLIMPORTboolTrace_connection_negotiation;
1921
externPGDLLIMPORTuint32log_connections;
2022
externPGDLLIMPORTchar*log_connections_string;
2123

24+
/* Other globals */
25+
externPGDLLIMPORTstructConnectionTimingconn_timing;
26+
2227
/*
2328
* CAC_state is passed from postmaster to the backend process, to indicate
2429
* whether the connection should be accepted, or if the process should just
@@ -39,14 +44,27 @@ typedef enum CAC_state
3944
typedefstructBackendStartupData
4045
{
4146
CAC_statecanAcceptConnections;
47+
48+
/*
49+
* Time at which the connection client socket is created. Only used for
50+
* client and wal sender connections.
51+
*/
52+
TimestampTzsocket_created;
53+
54+
/*
55+
* Time at which the postmaster initiates process creation -- either
56+
* through fork or otherwise. Only used for client and wal sender
57+
* connections.
58+
*/
59+
TimestampTzfork_started;
4260
}BackendStartupData;
4361

4462
/*
4563
* Granular control over which messages to log for the log_connections GUC.
4664
*
47-
* RECEIPT, AUTHENTICATION, andAUTHORIZATION are different aspects of
48-
* connection establishment and backend setup for which we may emit a log
49-
* message.
65+
* RECEIPT, AUTHENTICATION,AUTHORIZATION,andSETUP_DURATIONS are different
66+
*aspects ofconnection establishment and backend setup for which we may emit
67+
*a logmessage.
5068
*
5169
* ALL is a convenience alias equivalent to all of the above aspects.
5270
*
@@ -58,16 +76,47 @@ typedef enum LogConnectionOption
5876
LOG_CONNECTION_RECEIPT= (1 <<0),
5977
LOG_CONNECTION_AUTHENTICATION= (1 <<1),
6078
LOG_CONNECTION_AUTHORIZATION= (1 <<2),
79+
LOG_CONNECTION_SETUP_DURATIONS= (1 <<3),
6180
LOG_CONNECTION_ON=
6281
LOG_CONNECTION_RECEIPT |
6382
LOG_CONNECTION_AUTHENTICATION |
6483
LOG_CONNECTION_AUTHORIZATION,
6584
LOG_CONNECTION_ALL=
6685
LOG_CONNECTION_RECEIPT |
6786
LOG_CONNECTION_AUTHENTICATION |
68-
LOG_CONNECTION_AUTHORIZATION,
87+
LOG_CONNECTION_AUTHORIZATION |
88+
LOG_CONNECTION_SETUP_DURATIONS,
6989
}LogConnectionOption;
7090

91+
/*
92+
* A collection of timings of various stages of connection establishment and
93+
* setup for client backends and WAL senders.
94+
*
95+
* Used to emit the setup_durations log message for the log_connections GUC.
96+
*/
97+
typedefstructConnectionTiming
98+
{
99+
/*
100+
* The time at which the client socket is created and the time at which
101+
* the connection is fully set up and first ready for query. Together
102+
* these represent the total connection establishment and setup time.
103+
*/
104+
TimestampTzsocket_create;
105+
TimestampTzready_for_use;
106+
107+
/* Time at which process creation was initiated */
108+
TimestampTzfork_start;
109+
110+
/* Time at which process creation was completed */
111+
TimestampTzfork_end;
112+
113+
/* Time at which authentication started */
114+
TimestampTzauth_start;
115+
116+
/* Time at which authentication was finished */
117+
TimestampTzauth_end;
118+
}ConnectionTiming;
119+
71120
externvoidBackendMain(constvoid*startup_data,size_tstartup_data_len)pg_attribute_noreturn();
72121

73122
#endif/* BACKEND_STARTUP_H */

‎src/include/utils/timestamp.h

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -85,6 +85,15 @@ IntervalPGetDatum(const Interval *X)
8585
#defineTimestampTzPlusMilliseconds(tz,ms) ((tz) + ((ms) * (int64) 1000))
8686
#defineTimestampTzPlusSeconds(tz,s) ((tz) + ((s) * (int64) 1000000))
8787

88+
/* Helper for simple subtraction between two timestamps */
89+
staticinlineuint64
90+
TimestampDifferenceMicroseconds(TimestampTzstart_time,
91+
TimestampTzstop_time)
92+
{
93+
if (start_time >=stop_time)
94+
return0;
95+
return (uint64)stop_time-start_time;
96+
}
8897

8998
/* Set at postmaster start */
9099
externPGDLLIMPORTTimestampTzPgStartTime;

‎src/test/authentication/t/001_password.pl

Lines changed: 17 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -77,15 +77,30 @@ sub test_conn
7777
# other tests are added to this file in the future
7878
$node->safe_psql('postgres',"CREATE DATABASE test_log_connections");
7979

80+
my$log_connections =$node->safe_psql('test_log_connections',q(SHOW log_connections;));
81+
is($log_connections,'on',qq(check log connections has expected value 'on'));
82+
83+
$node->connect_ok('test_log_connections',
84+
qq(log_connections 'on' works as expected for backwards compatibility),
85+
log_like=> [
86+
qr/connection received/,
87+
qr/connection authenticated/,
88+
qr/connection authorized: user=\S+ database=test_log_connections/,
89+
],
90+
log_unlike=> [
91+
qr/connection ready/,
92+
],);
93+
8094
$node->safe_psql('test_log_connections',
81-
q[ALTER SYSTEM SET log_connections = receipt,authorization;
95+
q[ALTER SYSTEM SET log_connections = receipt,authorization,setup_durations;
8296
SELECT pg_reload_conf();]);
8397

8498
$node->connect_ok('test_log_connections',
8599
q(log_connections with subset of specified options logs only those aspects),
86100
log_like=> [
87101
qr/connection received/,
88102
qr/connection authorized: user=\S+ database=test_log_connections/,
103+
qr/connection ready/,
89104
],
90105
log_unlike=> [
91106
qr/connection authenticated/,
@@ -100,6 +115,7 @@ sub test_conn
100115
qr/connection received/,
101116
qr/connection authenticated/,
102117
qr/connection authorized: user=\S+ database=test_log_connections/,
118+
qr/connection ready/,
103119
],);
104120

105121
# Authentication tests

‎src/tools/pgindent/typedefs.list

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -484,6 +484,7 @@ ConnParams
484484
ConnStatusType
485485
ConnType
486486
ConnectionStateEnum
487+
ConnectionTiming
487488
ConsiderSplitContext
488489
Const
489490
ConstrCheck

0 commit comments

Comments
 (0)
[8]ページ先頭
©2009-2025 Movatter.jp