From 00d5542eb8b31505957bad0bd4822ece59e5847c Mon Sep 17 00:00:00 2001 From: Marko Kreen Date: Wed, 14 Mar 2007 19:29:37 +0000 Subject: [PATCH] Couple hotfixes. * More debugging in console, new command SHOW SOCKETS. * unsigned usec_t + cached vs. uncached time created spurious query_timeout errors. * Fair queueing by giving a released server immidiately to waiting server. * slog_*() print also socket pointer to make tracking possible. * Sync test.sh with released code. --- doc/todo.txt | 9 ++-- src/admin.c | 132 ++++++++++++++++++++++++++++++++------------------ src/bouncer.h | 5 +- src/client.c | 2 +- src/janitor.c | 12 +---- src/main.c | 2 +- src/objects.c | 7 +++ src/sbuf.h | 3 +- src/server.c | 2 +- src/stats.c | 2 +- src/util.c | 8 +-- src/util.h | 1 - test/test.ini | 6 --- test/test.sh | 11 +++-- 14 files changed, 118 insertions(+), 84 deletions(-) diff --git a/doc/todo.txt b/doc/todo.txt index 9e576de..bd17041 100644 --- a/doc/todo.txt +++ b/doc/todo.txt @@ -10,12 +10,13 @@ * log_connects, log_disconnects settings + * Split CL_IDLE from CL_ACTIVE. Does not give functional + advantage, but makes monitoring easier. + + * SHOW POOLS should give time a client has waited for connection. + == Bugs == * Bouncer can get into situation where SUSPEND wont work (stalls), thus making reboot impossible. - * Light load with small server_check_delay creates situation where - some clients may never get server connection. Applied a hack to - fix this, needs more analysis. - diff --git a/src/admin.c b/src/admin.c index b6fd1a0..e61c2f2 100644 --- a/src/admin.c +++ b/src/admin.c @@ -351,24 +351,60 @@ static bool admin_show_users(PgSocket *admin) return true; } +#define SKF_STD "sssssiTT" +#define SKF_DBG "sssssiTTiiiiiiiss" + +static void socket_header(PktBuf *buf, bool debug) +{ + pktbuf_write_RowDescription(buf, debug ? SKF_DBG : SKF_STD, + "type", "user", "database", "state", + "addr", "port", + "connect_time", "request_time", + "recv_pos", "pkt_pos", "pkt_remain", + "send_pos", "send_remain", + "pkt_avail", "send_avail", + "ptr", "link"); +} + +static void socket_row(PktBuf *buf, PgSocket *sk, const char *state, bool debug) +{ + const char *addr = sk->addr.is_unix ? "unix" + : inet_ntoa(sk->addr.ip_addr); + int pkt_avail = sk->sbuf.recv_pos - sk->sbuf.pkt_pos; + int send_avail = sk->sbuf.recv_pos - sk->sbuf.send_pos; + char ptrbuf[128], linkbuf[128]; + + snprintf(ptrbuf, sizeof(ptrbuf), "%p", sk); + if (sk->link) + snprintf(linkbuf, sizeof(linkbuf), "%p", sk->link); + else + linkbuf[0] = 0; + + pktbuf_write_DataRow(buf, debug ? SKF_DBG : SKF_STD, + is_server_socket(sk) ? "S" :"C", + sk->auth_user->name, + sk->pool->db->name, + state, addr, sk->addr.port, + sk->connect_time, + sk->request_time, + sk->sbuf.recv_pos, + sk->sbuf.pkt_pos, + sk->sbuf.pkt_remain, + sk->sbuf.send_pos, + sk->sbuf.send_remain, + pkt_avail, send_avail, + ptrbuf, linkbuf); +} + /* Helper for SHOW CLIENTS */ -static void show_client_list(PktBuf *buf, StatList *list, const char *state) +static void show_socket_list(PktBuf *buf, StatList *list, const char *state, bool debug) { List *item; - PgSocket *client; - const char *addr; + PgSocket *sk; statlist_for_each(item, list) { - client = container_of(item, PgSocket, head); - addr = client->addr.is_unix ? "unix" - : inet_ntoa(client->addr.ip_addr); - - pktbuf_write_DataRow(buf, "ssssiTT", - client->auth_user->name, - client->pool->db->name, - state, addr, client->addr.port, - client->connect_time, - client->request_time); + sk = container_of(item, PgSocket, head); + socket_row(buf, sk, state, debug); } } @@ -383,46 +419,47 @@ static bool admin_show_clients(PgSocket *admin) admin_error(admin, "no mem"); return true; } - pktbuf_write_RowDescription(buf, "ssssiTT", - "user", "database", "state", - "addr", "port", "connect_time", "request_time"); - /* todo: age? query stats? */ + socket_header(buf, false); statlist_for_each(item, &pool_list) { pool = container_of(item, PgPool, head); - show_client_list(buf, &pool->active_client_list, "active"); - show_client_list(buf, &pool->waiting_client_list, "waiting"); + show_socket_list(buf, &pool->active_client_list, "active", false); + show_socket_list(buf, &pool->waiting_client_list, "waiting", false); } admin_flush(admin, buf, "SHOW"); return true; } -/* Helper for SHOW SERVERS */ -static void show_server_list(PktBuf *buf, StatList *list, const char *state) +/* Command: SHOW SERVERS */ +static bool admin_show_servers(PgSocket *admin) { List *item; - PgSocket *server; - const char *addr; + PgPool *pool; + PktBuf *buf; - statlist_for_each(item, list) { - server = container_of(item, PgSocket, head); - addr = server->addr.is_unix ? "unix" - : inet_ntoa(server->addr.ip_addr); - - pktbuf_write_DataRow(buf, "ssssiTT", - server->auth_user->name, - server->pool->db->name, - state, addr, server->addr.port, - server->connect_time, - server->request_time - ); + buf = pktbuf_dynamic(256); + if (!buf) { + admin_error(admin, "no mem"); + return true; + } + + socket_header(buf, false); + statlist_for_each(item, &pool_list) { + pool = container_of(item, PgPool, head); + show_socket_list(buf, &pool->active_server_list, "active", false); + show_socket_list(buf, &pool->idle_server_list, "idle", false); + show_socket_list(buf, &pool->used_server_list, "used", false); + show_socket_list(buf, &pool->tested_server_list, "tested", false); + show_socket_list(buf, &pool->new_server_list, "new", false); } + admin_flush(admin, buf, "SHOW"); + return true; } -/* Command: SHOW SERVERS */ -static bool admin_show_servers(PgSocket *admin) +/* Command: SHOW SOCKETS */ +static bool admin_show_sockets(PgSocket *admin) { List *item; PgPool *pool; @@ -433,17 +470,18 @@ static bool admin_show_servers(PgSocket *admin) admin_error(admin, "no mem"); return true; } - pktbuf_write_RowDescription(buf, "ssssiTT", - "database", "user", "state", - "addr", "port", "connect_time", "request_time"); - /* todo: age? query stats */ + socket_header(buf, true); statlist_for_each(item, &pool_list) { pool = container_of(item, PgPool, head); - show_server_list(buf, &pool->active_server_list, "active"); - show_server_list(buf, &pool->idle_server_list, "idle"); - show_server_list(buf, &pool->used_server_list, "used"); - show_server_list(buf, &pool->tested_server_list, "tested"); + show_socket_list(buf, &pool->active_client_list, "active", true); + show_socket_list(buf, &pool->waiting_client_list, "waiting", true); + + show_socket_list(buf, &pool->active_server_list, "active", true); + show_socket_list(buf, &pool->idle_server_list, "idle", true); + show_socket_list(buf, &pool->used_server_list, "used", true); + show_socket_list(buf, &pool->tested_server_list, "tested", true); + show_socket_list(buf, &pool->new_server_list, "login", true); } admin_flush(admin, buf, "SHOW"); return true; @@ -626,7 +664,7 @@ static bool admin_show_help(PgSocket *admin) "sssss", "SNOTICE", "C00000", "MConsole usage", "D\n\tSHOW [HELP|CONFIG|DATABASES|FDS" - "|POOLS|CLIENTS|SERVERS|LISTS|VERSION]\n" + "|POOLS|CLIENTS|SERVERS|SOCKETS|LISTS|VERSION]\n" "\tSET key = arg\n" "\tRELOAD\n" "\tPAUSE\n" @@ -677,6 +715,8 @@ static bool admin_parse_query(PgSocket *admin, const char *q) res = admin_show_servers(admin); } else if (strcasecmp(key, "lists") == 0) { res = admin_show_lists(admin); + } else if (strcasecmp(key, "sockets") == 0) { + res = admin_show_sockets(admin); } else if (strcasecmp(key, "fds") == 0) { res = admin_show_fds(admin); } else if (strcasecmp(key, "version") == 0) { diff --git a/src/bouncer.h b/src/bouncer.h index b0af276..264ccec 100644 --- a/src/bouncer.h +++ b/src/bouncer.h @@ -281,11 +281,8 @@ pop_socket(StatList *slist) static inline PgSocket * first_socket(StatList *slist) { - if (statlist_empty(slist)) { - log_debug("first_socket: statlist_empty"); + if (statlist_empty(slist)) return NULL; - } - log_debug("first_socket: next=%p", slist->head.next); return container_of(slist->head.next, PgSocket, head); } diff --git a/src/client.c b/src/client.c index ee55c6c..bf48d71 100644 --- a/src/client.c +++ b/src/client.c @@ -303,7 +303,7 @@ static bool handle_client_work(PgSocket *client, MBuf *pkt) /* update stats */ if (!client->query_start) { client->pool->stats.request_count++; - client->query_start = get_time_usec(); + client->query_start = get_cached_time(); } if (client->pool->admin) diff --git a/src/janitor.c b/src/janitor.c index 9d2d554..1cde69f 100644 --- a/src/janitor.c +++ b/src/janitor.c @@ -47,7 +47,7 @@ static int suspend_socket_list(StatList *list) statlist_for_each(item, list) { sk = container_of(item, PgSocket, head); if (!sk->suspended) { - if (sbuf_empty(&sk->sbuf)) { + if (sbuf_has_no_state(&sk->sbuf)) { sbuf_pause(&sk->sbuf); sk->suspended = 1; } else @@ -151,16 +151,10 @@ static void per_loop_activate(PgPool *pool) activate_client(client); } else if (!statlist_empty(&pool->tested_server_list)) { /* some connections are in testing process */ - - /* not enough connections? (X) */ - launch_new_connection(pool); break; } else if (!statlist_empty(&pool->used_server_list)) { /* ask for more connections to be tested */ launch_recheck(pool); - - /* not enough connections? (X) */ - launch_new_connection(pool); break; } else { /* not enough connections */ @@ -169,10 +163,6 @@ static void per_loop_activate(PgPool *pool) } } } -/* - * (X) - theres some problem in light load with small server_check_timeout - * where waiting connection wont ever get server connection. - */ /* * pause active clients diff --git a/src/main.c b/src/main.c index 7841c53..fadd008 100644 --- a/src/main.c +++ b/src/main.c @@ -31,7 +31,7 @@ static bool set_auth(ConfElem *elem, const char *val, PgSocket *console); static const char *get_auth(ConfElem *elem); static const char *usage_str = -"usage: pgbouncer [-d] [-v] [-h|-V] config.ini\n"; +"usage: pgbouncer [-d] [-R] [-v] [-h|-V] config.ini\n"; static void usage(int err) { diff --git a/src/objects.c b/src/objects.c index e84445e..7131d81 100644 --- a/src/objects.c +++ b/src/objects.c @@ -556,6 +556,13 @@ void release_server(PgSocket *server) log_debug("release_server: new state=%d", newstate); change_server_state(server, newstate); + + /* immidiately process waiters, to give fair chance */ + if (newstate == SV_IDLE) { + PgSocket *client = first_socket(&pool->waiting_client_list); + if (client) + activate_client(client); + } } /* drop server connection */ diff --git a/src/sbuf.h b/src/sbuf.h index 56d553b..6c1b11c 100644 --- a/src/sbuf.h +++ b/src/sbuf.h @@ -83,7 +83,8 @@ bool sbuf_answer(SBuf *sbuf, const void *buf, int len); void sbuf_continue_with_callback(SBuf *sbuf, sbuf_libevent_cb cb); -static inline bool sbuf_empty(SBuf *sbuf) +/* returns true if SBuf is suspendable */ +static inline bool sbuf_has_no_state(SBuf *sbuf) { return sbuf->send_pos == sbuf->recv_pos && sbuf->pkt_remain == 0; diff --git a/src/server.c b/src/server.c index c89341e..e09abc7 100644 --- a/src/server.c +++ b/src/server.c @@ -190,7 +190,7 @@ static bool handle_server_work(PgSocket *server, MBuf *pkt) usec_t total; Assert(client->query_start != 0); - total = get_time_usec() - client->query_start; + 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); diff --git a/src/stats.c b/src/stats.c index c891ff2..737c42f 100644 --- a/src/stats.c +++ b/src/stats.c @@ -157,7 +157,7 @@ void stats_setup(void) { struct timeval period = { cf_stats_period, 0 }; - new_stamp = get_time_usec(); + new_stamp = get_cached_time(); old_stamp = new_stamp - USEC; /* launch maintenance */ diff --git a/src/util.c b/src/util.c index 920f0bc..a7a2637 100644 --- a/src/util.c +++ b/src/util.c @@ -169,9 +169,9 @@ slog_level(const char *pfx, const PgSocket *sock, const char *fmt, ...) vsnprintf(buf1, sizeof(buf1), fmt, ap); va_end(ap); - snprintf(buf2, sizeof(buf2), "%c: %s/%s@%s:%d %s", + snprintf(buf2, sizeof(buf2), "%c-%p: %s/%s@%s:%d %s", is_server_socket(sock) ? 'S' : 'C', - db, user, host, port, buf1); + sock, db, user, host, port, buf1); _log_write(pfx, buf2); } @@ -378,7 +378,7 @@ bool get_random_bytes(uint8 *dest, int len) * high-precision time */ -usec_t get_time_usec(void) +static usec_t get_time_usec(void) { struct timeval tv; gettimeofday(&tv, NULL); @@ -569,7 +569,7 @@ const char *format_date(usec_t uval) { static char buf[128]; time_t tval = uval / USEC; - strftime(buf, sizeof(buf), "%Y-%m-%d %H:%M", localtime(&tval)); + strftime(buf, sizeof(buf), "%Y-%m-%d %H:%M:%S", localtime(&tval)); return buf; } diff --git a/src/util.h b/src/util.h index 359fa19..89ddd45 100644 --- a/src/util.h +++ b/src/util.h @@ -22,7 +22,6 @@ typedef uint64_t usec_t; usec_t get_cached_time(void); void reset_time_cache(void); -usec_t get_time_usec(void); /* * load file into malloced buffer diff --git a/test/test.ini b/test/test.ini index fa85fa7..dad9250 100644 --- a/test/test.ini +++ b/test/test.ini @@ -128,9 +128,3 @@ tcp_keepidle = 0 ; The time between individual keepalive probes. tcp_keepintvl = 0 - -; By default, max tcp packet cannot be larger than pkt_buf. -; If this is set, then bouncer tells to kernel to queue packets. -; Then max pkt length is tcp_socket_buffer. -tcp_buffer_more = 0 - diff --git a/test/test.sh b/test/test.sh index ed2a4c1..64443c6 100755 --- a/test/test.sh +++ b/test/test.sh @@ -26,6 +26,8 @@ pgctl() { pg_ctl -o "-p $PG_PORT" -D $PGDATA $@ >>$PG_LOG 2>&1 } +ulimit -c unlimited + mkdir -p $LOGDIR rm -f $BOUNCER_LOG $PG_LOG # rm -r $PGDATA @@ -188,7 +190,6 @@ test_server_connect_timeout_establish() { } # server_connect_timeout - block with iptables -# XXX: for some reason bouncer says 'connect failed' not 'connect timeout' test_server_connect_timeout_reject() { test -z $CAN_SUDO && return 1 admin "set query_timeout=5" @@ -268,9 +269,13 @@ test_pool_size() { # test online restart while clients running test_online_restart() { +# max_client_conn=10 +# default_pool_size=5 for i in `seq 1 5`; do - for j in `seq 1 10`; do - psql -c "select now() as sleeping from pg_sleep(0.2)" p0 & + echo "`date` attempt $i" + + for j in `seq 1 5`; do + psql -c "select now() as sleeping from pg_sleep(2)" p1 & done pid1=`cat $BOUNCER_PID` -- 2.39.5