From: Tomas Vondra Date: Wed, 20 Sep 2017 19:00:17 +0000 (+0200) Subject: Track separate stats for queries and transactions X-Git-Tag: pgbouncer_1_8~17^2~2 X-Git-Url: https://granicus.if.org/sourcecode?a=commitdiff_plain;h=876d8a5379e99ca385bb288eac03683717c423d1;p=pgbouncer Track separate stats for queries and transactions The documentation claimed avg_query tracks average query duration, but it was only updated when switching into 'idle' state. So in transaction or session pooling modes, it was actually the duration of the whole transaction, including 'idle in transaction' time and time spen executing (multiple) queries. This was causing confusion, e.g. when the application was keeping transactions open without executing any queries. In that case the avg_query metric was increasing although the database was handling queries just fine (without any slow-down). Instead of just fixing the avg_query metric, it seems quite useful to have timing data both for queries and transactions. So this patch replaces - total_query_time - avg_query with - total_xact_time - total_query_time - avg_xact_time - avg_query_time This is also related to the definition of 'request' which was used to compute the avg_query, and so it equal to a transaction. This patch replaces the counter with two - one for transactions and one for queries. As we also computed avg_req, the patch replaces - total_requests - avg_req with - total_xact_count - total_query_time - avg_xact_count - avg_query_count Note: This is likely to affect monitoring solutions, as the column names in SHOW STATS change. --- diff --git a/doc/usage.rst b/doc/usage.rst index f29e9b8..6e3561a 100644 --- a/doc/usage.rst +++ b/doc/usage.rst @@ -174,8 +174,11 @@ Shows statistics. database Statistics are presented per database. -total_requests - Total number of SQL requests pooled by **pgbouncer**. +total_xact_count + Total number of SQL transactions pooled by **pgbouncer**. + +total_query_count + Total number of SQL queries pooled by **pgbouncer**. total_received Total volume in bytes of network traffic received by **pgbouncer**. @@ -183,12 +186,20 @@ total_received total_sent Total volume in bytes of network traffic sent by **pgbouncer**. +total_xact_time + Total number of microseconds spent by **pgbouncer** when connected + to PostgreSQL in a transaction, either idle in transaction or + executing queries. + total_query_time Total number of microseconds spent by **pgbouncer** when actively - connected to PostgreSQL. + connected to PostgreSQL, executing queries. -avg_req - Average requests per second in last stat period. +avg_xact_count + Average transactions per second in last stat period. + +avg_query_count + Average queries per second in last stat period. avg_recv Average received (from clients) bytes per second. @@ -196,7 +207,10 @@ avg_recv avg_sent Average sent (to clients) bytes per second. -avg_query +avg_xact_time + Average transaction duration in microseconds. + +avg_query_time Average query duration in microseconds. SHOW SERVERS; diff --git a/include/bouncer.h b/include/bouncer.h index 8990573..b792d0b 100644 --- a/include/bouncer.h +++ b/include/bouncer.h @@ -188,10 +188,12 @@ int pga_cmp_addr(const PgAddr *a, const PgAddr *b); * Stats, kept per-pool. */ struct PgStats { - uint64_t request_count; + uint64_t xact_count; + uint64_t query_count; uint64_t server_bytes; uint64_t client_bytes; - usec_t query_time; /* total req time in us */ + usec_t xact_time; /* total transaction time in us */ + usec_t query_time; /* total query time in us */ }; /* @@ -356,6 +358,7 @@ struct PgSocket { usec_t connect_time; /* when connection was made */ usec_t request_time; /* last activity time */ usec_t query_start; /* query start moment */ + usec_t xact_start; /* xact start moment */ uint8_t cancel_key[BACKENDKEY_LEN]; /* client: generated, server: remote */ PgAddr remote_addr; /* ip:port for remote endpoint */ diff --git a/src/client.c b/src/client.c index 0dfa102..245dc5c 100644 --- a/src/client.c +++ b/src/client.c @@ -661,10 +661,16 @@ static bool handle_client_work(PgSocket *client, PktHdr *pkt) /* update stats */ if (!client->query_start) { - client->pool->stats.request_count++; + client->pool->stats.query_count++; client->query_start = get_cached_time(); } + /* remember timestamp of the first query in a transaction */ + if (!client->xact_start) { + client->pool->stats.xact_count++; + client->xact_start = client->query_start; + } + if (client->pool->db->admin) return admin_handle_client(client, pkt); diff --git a/src/server.c b/src/server.c index 48ebe6d..bf39f5c 100644 --- a/src/server.c +++ b/src/server.c @@ -343,15 +343,28 @@ static bool handle_server_work(PgSocket *server, PktHdr *pkt) return handle_auth_response(client, pkt); } else { sbuf_prepare_send(sbuf, &client->sbuf, pkt->len); - if (ready && client->query_start) { + + /* every statement (independent or in a transaction) counts as a query */ + if ((ready || idle_tx) && client->query_start) { usec_t total; total = get_cached_time() - client->query_start; client->query_start = 0; server->pool->stats.query_time += total; slog_debug(client, "query time: %d us", (int)total); - } else if (ready) { + } else if (ready || idle_tx) { slog_warning(client, "FIXME: query end, but query_start == 0"); } + + /* statement ending in "idle" ends a transaction */ + if (ready && client->xact_start) { + usec_t total; + total = get_cached_time() - client->xact_start; + client->xact_start = 0; + server->pool->stats.xact_time += total; + slog_debug(client, "transaction time: %d us", (int)total); + } else if (ready) { + slog_warning(client, "FIXME: transaction end, but xact_start == 0"); + } } } else { if (server->state != SV_TESTED) diff --git a/src/stats.c b/src/stats.c index c4e0027..1ae702d 100644 --- a/src/stats.c +++ b/src/stats.c @@ -25,21 +25,27 @@ static void reset_stats(PgStats *stat) { stat->server_bytes = 0; stat->client_bytes = 0; - stat->request_count = 0; + stat->query_count = 0; stat->query_time = 0; + stat->xact_count = 0; + stat->xact_time = 0; } static void stat_add(PgStats *total, PgStats *stat) { total->server_bytes += stat->server_bytes; total->client_bytes += stat->client_bytes; - total->request_count += stat->request_count; + total->query_count += stat->query_count; total->query_time += stat->query_time; + total->xact_count += stat->xact_count; + total->xact_time += stat->xact_time; } static void calc_average(PgStats *avg, PgStats *cur, PgStats *old) { - uint64_t qcount; + uint64_t query_count; + uint64_t xact_count; + usec_t dur = get_cached_time() - old_stamp; reset_stats(avg); @@ -47,23 +53,33 @@ static void calc_average(PgStats *avg, PgStats *cur, PgStats *old) if (dur <= 0) return; - avg->request_count = USEC * (cur->request_count - old->request_count) / dur; + query_count = cur->query_count - old->query_count; + xact_count = cur->xact_count - old->xact_count; + + avg->query_count = USEC * query_count / dur; + avg->xact_count = USEC * xact_count / dur; + avg->client_bytes = USEC * (cur->client_bytes - old->client_bytes) / dur; avg->server_bytes = USEC * (cur->server_bytes - old->server_bytes) / dur; - qcount = cur->request_count - old->request_count; - if (qcount > 0) - avg->query_time = (cur->query_time - old->query_time) / qcount; + + if (query_count > 0) + avg->query_time = (cur->query_time - old->query_time) / query_count; + + if (xact_count > 0) + avg->xact_time = (cur->xact_time - old->xact_time) / xact_count; } static void write_stats(PktBuf *buf, PgStats *stat, PgStats *old, char *dbname) { PgStats avg; calc_average(&avg, stat, old); - pktbuf_write_DataRow(buf, "sqqqqqqqq", dbname, - stat->request_count, stat->client_bytes, - stat->server_bytes, stat->query_time, - avg.request_count, avg.client_bytes, - avg.server_bytes, avg.query_time); + pktbuf_write_DataRow(buf, "sqqqqqqqqqqqq", dbname, + stat->xact_count, stat->query_count, + stat->client_bytes, stat->server_bytes, + stat->xact_time, stat->query_time, + avg.xact_count, avg.query_count, + avg.client_bytes, avg.server_bytes, + avg.xact_time, avg.query_time); } bool admin_database_stats(PgSocket *client, struct StatList *pool_list) @@ -86,11 +102,13 @@ bool admin_database_stats(PgSocket *client, struct StatList *pool_list) return true; } - pktbuf_write_RowDescription(buf, "sqqqqqqqq", "database", - "total_requests", "total_received", - "total_sent", "total_query_time", - "avg_req", "avg_recv", "avg_sent", - "avg_query"); + pktbuf_write_RowDescription(buf, "sqqqqqqqqqqqq", "database", + "total_xact_count", "total_query_count", + "total_received", "total_sent", + "total_xact_time", "total_query_time", + "avg_xact_count", "avg_query_count", + "avg_recv", "avg_sent", + "avg_xact_time", "avg_query_time"); statlist_for_each(item, pool_list) { pool = container_of(item, PgPool, head); @@ -152,13 +170,17 @@ bool show_stat_totals(PgSocket *client, struct StatList *pool_list) #define WTOTAL(name) pktbuf_write_DataRow(buf, "sq", "total_" #name, st_total.name) #define WAVG(name) pktbuf_write_DataRow(buf, "sq", "avg_" #name, avg.name) - WTOTAL(request_count); + WTOTAL(xact_count); + WTOTAL(query_count); WTOTAL(client_bytes); WTOTAL(server_bytes); + WTOTAL(xact_time); WTOTAL(query_time); - WAVG(request_count); + WAVG(xact_count); + WAVG(query_count); WAVG(client_bytes); WAVG(server_bytes); + WAVG(xact_time); WAVG(query_time); admin_flush(client, buf, "SHOW"); @@ -188,12 +210,15 @@ static void refresh_stats(int s, short flags, void *arg) } calc_average(&avg, &cur_total, &old_total); /* send totals to logfile */ - log_info("Stats: %" PRIu64 " req/s," + log_info("Stats: %" PRIu64 " xacts/s," + " %" PRIu64 " queries/s," " in %" PRIu64 " B/s," " out %" PRIu64 " B/s," + " xact %" PRIu64 " us," " query %" PRIu64 " us", - avg.request_count, avg.client_bytes, - avg.server_bytes, avg.query_time); + avg.xact_count, avg.query_count, + avg.client_bytes, avg.server_bytes, + avg.xact_time, avg.query_time); safe_evtimer_add(&ev_stats, &period); }