From 5482d5822f26cf9b503ed94eb49e6615e522ecdb Mon Sep 17 00:00:00 2001 From: Onder Kalaci Date: Thu, 1 Apr 2021 15:33:02 +0200 Subject: [PATCH] Keep more statistics about connection establishment times When DEBUG4 enabled, Citus now prints per connection establishment time. --- .../connection/connection_management.c | 26 +++++++++++++++---- .../distributed/executor/adaptive_executor.c | 16 +++++++----- .../distributed/connection_management.h | 6 +++-- 3 files changed, 34 insertions(+), 14 deletions(-) diff --git a/src/backend/distributed/connection/connection_management.c b/src/backend/distributed/connection/connection_management.c index 1d307e950..612453ef9 100644 --- a/src/backend/distributed/connection/connection_management.c +++ b/src/backend/distributed/connection/connection_management.c @@ -940,8 +940,7 @@ FinishConnectionListEstablishment(List *multiConnectionList) */ if (connectionState->phase == MULTI_CONNECTION_PHASE_CONNECTED) { - connectionState->connection->connectionState = - MULTI_CONNECTION_CONNECTED; + MarkConnectionConnected(connectionState->connection); } } } @@ -1142,7 +1141,7 @@ StartConnectionEstablishment(MultiConnection *connection, ConnectionHashKey *key connection->pgConn = PQconnectStartParams((const char **) entry->keywords, (const char **) entry->values, false); - connection->connectionStart = GetCurrentTimestamp(); + INSTR_TIME_SET_CURRENT(connection->connectionEstablishmentStart); connection->connectionId = connectionId++; /* @@ -1344,8 +1343,8 @@ ShouldShutdownConnection(MultiConnection *connection, const int cachedConnection PQstatus(connection->pgConn) != CONNECTION_OK || !RemoteTransactionIdle(connection) || (MaxCachedConnectionLifetime >= 0 && - TimestampDifferenceExceeds(connection->connectionStart, GetCurrentTimestamp(), - MaxCachedConnectionLifetime)); + MillisecondsToTimeout(connection->connectionEstablishmentStart, + MaxCachedConnectionLifetime) <= 0); } @@ -1400,3 +1399,20 @@ RemoteTransactionIdle(MultiConnection *connection) return PQtransactionStatus(connection->pgConn) == PQTRANS_IDLE; } + + +/* + * MarkConnectionConnected is a helper function which sets the connection + * connectionState to MULTI_CONNECTION_CONNECTED, and also updates connection + * establishment time when necessary. + */ +void +MarkConnectionConnected(MultiConnection *connection) +{ + connection->connectionState = MULTI_CONNECTION_CONNECTED; + + if (INSTR_TIME_IS_ZERO(connection->connectionEstablishmentEnd)) + { + INSTR_TIME_SET_CURRENT(connection->connectionEstablishmentEnd); + } +} diff --git a/src/backend/distributed/executor/adaptive_executor.c b/src/backend/distributed/executor/adaptive_executor.c index 5ebdd642d..270cb7e80 100644 --- a/src/backend/distributed/executor/adaptive_executor.c +++ b/src/backend/distributed/executor/adaptive_executor.c @@ -2945,8 +2945,6 @@ ConnectionStateMachine(WorkerSession *session) HandleMultiConnectionSuccess(session); UpdateConnectionWaitFlags(session, WL_SOCKET_READABLE | WL_SOCKET_WRITEABLE); - - connection->connectionState = MULTI_CONNECTION_CONNECTED; break; } else if (status == CONNECTION_BAD) @@ -2988,8 +2986,6 @@ ConnectionStateMachine(WorkerSession *session) UpdateConnectionWaitFlags(session, WL_SOCKET_READABLE | WL_SOCKET_WRITEABLE); - connection->connectionState = MULTI_CONNECTION_CONNECTED; - /* we should have a valid socket */ Assert(PQsocket(connection->pgConn) != -1); } @@ -3116,7 +3112,8 @@ ConnectionStateMachine(WorkerSession *session) /* - * HandleMultiConnectionSuccess logs the established connection and updates connection's state. + * HandleMultiConnectionSuccess logs the established connection and updates + * connection's state. */ static void HandleMultiConnectionSuccess(WorkerSession *session) @@ -3124,10 +3121,15 @@ HandleMultiConnectionSuccess(WorkerSession *session) MultiConnection *connection = session->connection; WorkerPool *workerPool = session->workerPool; + MarkConnectionConnected(connection); + ereport(DEBUG4, (errmsg("established connection to %s:%d for " - "session %ld", + "session %ld in %ld msecs", connection->hostname, connection->port, - session->sessionId))); + session->sessionId, + MillisecondsBetweenTimestamps( + connection->connectionEstablishmentStart, + connection->connectionEstablishmentEnd)))); workerPool->activeConnectionCount++; workerPool->idleConnectionCount++; diff --git a/src/include/distributed/connection_management.h b/src/include/distributed/connection_management.h index 34e7e4b67..5ce5b4835 100644 --- a/src/include/distributed/connection_management.h +++ b/src/include/distributed/connection_management.h @@ -133,8 +133,9 @@ typedef struct MultiConnection /* is the connection currently in use, and shouldn't be used by anything else */ bool claimedExclusively; - /* time connection establishment was started, for timeout */ - TimestampTz connectionStart; + /* time connection establishment was started, for timeout and executor stats */ + instr_time connectionEstablishmentStart; + instr_time connectionEstablishmentEnd; /* membership in list of list of connections in ConnectionHashEntry */ dlist_node connectionNode; @@ -256,6 +257,7 @@ extern void FinishConnectionEstablishment(MultiConnection *connection); extern void ClaimConnectionExclusively(MultiConnection *connection); extern void UnclaimConnection(MultiConnection *connection); extern bool IsCitusInitiatedRemoteBackend(void); +extern void MarkConnectionConnected(MultiConnection *connection); /* time utilities */ extern double MillisecondsPassedSince(instr_time moment);