From: Tomas Vondra Date: Wed, 20 Sep 2017 21:22:39 +0000 (+0200) Subject: Track total time spent waiting for server X-Git-Tag: pgbouncer_1_8~17^2~1 X-Git-Url: https://granicus.if.org/sourcecode?a=commitdiff_plain;h=350a0b575e6c0edc30db61f48d99a7524259f9e6;p=pgbouncer Track total time spent waiting for server There already is maxwait column in pool details, showing how long the oldest client is currently waiting. Which is useful, but it does not allow us to easily break client time into the three basic categories: busy, idle and waiting. This adds tracking of total time spent waiting for a server, and adds it as wait_time into SHOW STATS. The total value is simply accumulated over time, the average value is 'per second' value. The value is only updated when a client acquires a server, so if a client is waiting indefinitely, the wait time won't be reflected in the value. That would require inspecting the the list of waiting clients, which seems like overkill. Moreover, that's what maxwait is good for. --- diff --git a/doc/usage.rst b/doc/usage.rst index 6e3561a..266b8c8 100644 --- a/doc/usage.rst +++ b/doc/usage.rst @@ -195,6 +195,9 @@ total_query_time Total number of microseconds spent by **pgbouncer** when actively connected to PostgreSQL, executing queries. +total_wait_time + Time spent by clients waiting for a server in microseconds. + avg_xact_count Average transactions per second in last stat period. @@ -213,6 +216,10 @@ avg_xact_time avg_query_time Average query duration in microseconds. +avg_wait_time + Time spent by clients waiting for a server in microseconds (average + per second). + SHOW SERVERS; ------------- diff --git a/include/bouncer.h b/include/bouncer.h index b792d0b..409a82c 100644 --- a/include/bouncer.h +++ b/include/bouncer.h @@ -194,6 +194,7 @@ struct PgStats { uint64_t client_bytes; usec_t xact_time; /* total transaction time in us */ usec_t query_time; /* total query time in us */ + usec_t wait_time; /* total time clients had to wait */ }; /* @@ -359,6 +360,7 @@ struct PgSocket { usec_t request_time; /* last activity time */ usec_t query_start; /* query start moment */ usec_t xact_start; /* xact start moment */ + usec_t wait_start; /* waiting start moment */ uint8_t cancel_key[BACKENDKEY_LEN]; /* client: generated, server: remote */ PgAddr remote_addr; /* ip:port for remote endpoint */ diff --git a/src/objects.c b/src/objects.c index 1606373..f375ad8 100644 --- a/src/objects.c +++ b/src/objects.c @@ -185,6 +185,7 @@ void change_client_state(PgSocket *client, SocketState newstate) statlist_append(&login_client_list, &client->head); break; case CL_WAITING: + client->wait_start = get_cached_time(); case CL_WAITING_LOGIN: statlist_append(&pool->waiting_client_list, &client->head); break; @@ -560,6 +561,11 @@ void activate_client(PgSocket *client) { Assert(client->state == CL_WAITING || client->state == CL_WAITING_LOGIN); + Assert(client->wait_start > 0); + + /* acount for time client spent waiting for server */ + client->pool->stats.wait_time += (get_cached_time() - client->wait_start); + slog_debug(client, "activate_client"); change_client_state(client, CL_ACTIVE); sbuf_continue(&client->sbuf); @@ -608,6 +614,9 @@ bool find_server(PgSocket *client) Assert(client->state == CL_ACTIVE || client->state == CL_LOGIN); + /* no wait by default */ + client->wait_start = 0; + if (client->link) return true; diff --git a/src/stats.c b/src/stats.c index 1ae702d..ba27e49 100644 --- a/src/stats.c +++ b/src/stats.c @@ -29,6 +29,7 @@ static void reset_stats(PgStats *stat) stat->query_time = 0; stat->xact_count = 0; stat->xact_time = 0; + stat->wait_time = 0; } static void stat_add(PgStats *total, PgStats *stat) @@ -39,6 +40,7 @@ static void stat_add(PgStats *total, PgStats *stat) total->query_time += stat->query_time; total->xact_count += stat->xact_count; total->xact_time += stat->xact_time; + total->wait_time += stat->wait_time; } static void calc_average(PgStats *avg, PgStats *cur, PgStats *old) @@ -67,19 +69,23 @@ static void calc_average(PgStats *avg, PgStats *cur, PgStats *old) if (xact_count > 0) avg->xact_time = (cur->xact_time - old->xact_time) / xact_count; + + avg->wait_time = USEC * (cur->wait_time - old->wait_time) / dur; } static void write_stats(PktBuf *buf, PgStats *stat, PgStats *old, char *dbname) { PgStats avg; calc_average(&avg, stat, old); - pktbuf_write_DataRow(buf, "sqqqqqqqqqqqq", dbname, + pktbuf_write_DataRow(buf, "sqqqqqqqqqqqqqq", dbname, stat->xact_count, stat->query_count, stat->client_bytes, stat->server_bytes, stat->xact_time, stat->query_time, + stat->wait_time, avg.xact_count, avg.query_count, avg.client_bytes, avg.server_bytes, - avg.xact_time, avg.query_time); + avg.xact_time, avg.query_time, + avg.wait_time); } bool admin_database_stats(PgSocket *client, struct StatList *pool_list) @@ -102,13 +108,15 @@ bool admin_database_stats(PgSocket *client, struct StatList *pool_list) return true; } - pktbuf_write_RowDescription(buf, "sqqqqqqqqqqqq", "database", + pktbuf_write_RowDescription(buf, "sqqqqqqqqqqqqqq", "database", "total_xact_count", "total_query_count", "total_received", "total_sent", "total_xact_time", "total_query_time", + "total_wait_time", "avg_xact_count", "avg_query_count", "avg_recv", "avg_sent", - "avg_xact_time", "avg_query_time"); + "avg_xact_time", "avg_query_time", + "avg_wait_time"); statlist_for_each(item, pool_list) { pool = container_of(item, PgPool, head); @@ -176,12 +184,14 @@ bool show_stat_totals(PgSocket *client, struct StatList *pool_list) WTOTAL(server_bytes); WTOTAL(xact_time); WTOTAL(query_time); + WTOTAL(wait_time); WAVG(xact_count); WAVG(query_count); WAVG(client_bytes); WAVG(server_bytes); WAVG(xact_time); WAVG(query_time); + WAVG(wait_time); admin_flush(client, buf, "SHOW"); return true; @@ -215,10 +225,12 @@ static void refresh_stats(int s, short flags, void *arg) " in %" PRIu64 " B/s," " out %" PRIu64 " B/s," " xact %" PRIu64 " us," - " query %" PRIu64 " us", + " query %" PRIu64 " us" + " wait time %" PRIu64 " us", avg.xact_count, avg.query_count, avg.client_bytes, avg.server_bytes, - avg.xact_time, avg.query_time); + avg.xact_time, avg.query_time, + avg.wait_time); safe_evtimer_add(&ev_stats, &period); }