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 6e3561adf5a8091ea482a84555f94869b4b042dc..266b8c839d2b883073b5a63940e65404903a43b7 100644 (file)
--- 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 b792d0bc649d43f16908b2d34fa792923bdddec3..409a82c6efae0ccbb7e783db8f468b78d772be44 100644 (file)
--- 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 16063733b3154122b365fce50e52422bd6a35255..f375ad82cbe84836dc213428ef35970439a5612f 100644 (file)
--- 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 1ae702de900096138a4196c8f2263f78efe5b74d..ba27e49c862c1f5535b7b1044b3b758d6d18bf82 100644 (file)
--- 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);
 }