Keep more statistics about connection establishment times

When DEBUG4 enabled, Citus now prints per connection establishment
time.
pull/4892/head
Onder Kalaci 2021-04-01 15:33:02 +02:00
parent 0a060b327b
commit 5482d5822f
3 changed files with 34 additions and 14 deletions

View File

@ -940,8 +940,7 @@ FinishConnectionListEstablishment(List *multiConnectionList)
*/ */
if (connectionState->phase == MULTI_CONNECTION_PHASE_CONNECTED) if (connectionState->phase == MULTI_CONNECTION_PHASE_CONNECTED)
{ {
connectionState->connection->connectionState = MarkConnectionConnected(connectionState->connection);
MULTI_CONNECTION_CONNECTED;
} }
} }
} }
@ -1142,7 +1141,7 @@ StartConnectionEstablishment(MultiConnection *connection, ConnectionHashKey *key
connection->pgConn = PQconnectStartParams((const char **) entry->keywords, connection->pgConn = PQconnectStartParams((const char **) entry->keywords,
(const char **) entry->values, (const char **) entry->values,
false); false);
connection->connectionStart = GetCurrentTimestamp(); INSTR_TIME_SET_CURRENT(connection->connectionEstablishmentStart);
connection->connectionId = connectionId++; connection->connectionId = connectionId++;
/* /*
@ -1344,8 +1343,8 @@ ShouldShutdownConnection(MultiConnection *connection, const int cachedConnection
PQstatus(connection->pgConn) != CONNECTION_OK || PQstatus(connection->pgConn) != CONNECTION_OK ||
!RemoteTransactionIdle(connection) || !RemoteTransactionIdle(connection) ||
(MaxCachedConnectionLifetime >= 0 && (MaxCachedConnectionLifetime >= 0 &&
TimestampDifferenceExceeds(connection->connectionStart, GetCurrentTimestamp(), MillisecondsToTimeout(connection->connectionEstablishmentStart,
MaxCachedConnectionLifetime)); MaxCachedConnectionLifetime) <= 0);
} }
@ -1400,3 +1399,20 @@ RemoteTransactionIdle(MultiConnection *connection)
return PQtransactionStatus(connection->pgConn) == PQTRANS_IDLE; 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);
}
}

View File

@ -2945,8 +2945,6 @@ ConnectionStateMachine(WorkerSession *session)
HandleMultiConnectionSuccess(session); HandleMultiConnectionSuccess(session);
UpdateConnectionWaitFlags(session, UpdateConnectionWaitFlags(session,
WL_SOCKET_READABLE | WL_SOCKET_WRITEABLE); WL_SOCKET_READABLE | WL_SOCKET_WRITEABLE);
connection->connectionState = MULTI_CONNECTION_CONNECTED;
break; break;
} }
else if (status == CONNECTION_BAD) else if (status == CONNECTION_BAD)
@ -2988,8 +2986,6 @@ ConnectionStateMachine(WorkerSession *session)
UpdateConnectionWaitFlags(session, UpdateConnectionWaitFlags(session,
WL_SOCKET_READABLE | WL_SOCKET_WRITEABLE); WL_SOCKET_READABLE | WL_SOCKET_WRITEABLE);
connection->connectionState = MULTI_CONNECTION_CONNECTED;
/* we should have a valid socket */ /* we should have a valid socket */
Assert(PQsocket(connection->pgConn) != -1); 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 static void
HandleMultiConnectionSuccess(WorkerSession *session) HandleMultiConnectionSuccess(WorkerSession *session)
@ -3124,10 +3121,15 @@ HandleMultiConnectionSuccess(WorkerSession *session)
MultiConnection *connection = session->connection; MultiConnection *connection = session->connection;
WorkerPool *workerPool = session->workerPool; WorkerPool *workerPool = session->workerPool;
MarkConnectionConnected(connection);
ereport(DEBUG4, (errmsg("established connection to %s:%d for " ereport(DEBUG4, (errmsg("established connection to %s:%d for "
"session %ld", "session %ld in %ld msecs",
connection->hostname, connection->port, connection->hostname, connection->port,
session->sessionId))); session->sessionId,
MillisecondsBetweenTimestamps(
connection->connectionEstablishmentStart,
connection->connectionEstablishmentEnd))));
workerPool->activeConnectionCount++; workerPool->activeConnectionCount++;
workerPool->idleConnectionCount++; workerPool->idleConnectionCount++;

View File

@ -133,8 +133,9 @@ typedef struct MultiConnection
/* is the connection currently in use, and shouldn't be used by anything else */ /* is the connection currently in use, and shouldn't be used by anything else */
bool claimedExclusively; bool claimedExclusively;
/* time connection establishment was started, for timeout */ /* time connection establishment was started, for timeout and executor stats */
TimestampTz connectionStart; instr_time connectionEstablishmentStart;
instr_time connectionEstablishmentEnd;
/* membership in list of list of connections in ConnectionHashEntry */ /* membership in list of list of connections in ConnectionHashEntry */
dlist_node connectionNode; dlist_node connectionNode;
@ -256,6 +257,7 @@ extern void FinishConnectionEstablishment(MultiConnection *connection);
extern void ClaimConnectionExclusively(MultiConnection *connection); extern void ClaimConnectionExclusively(MultiConnection *connection);
extern void UnclaimConnection(MultiConnection *connection); extern void UnclaimConnection(MultiConnection *connection);
extern bool IsCitusInitiatedRemoteBackend(void); extern bool IsCitusInitiatedRemoteBackend(void);
extern void MarkConnectionConnected(MultiConnection *connection);
/* time utilities */ /* time utilities */
extern double MillisecondsPassedSince(instr_time moment); extern double MillisecondsPassedSince(instr_time moment);