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.

diff --git a/doc/todo.txt b/doc/todo.txt
index 9e576de3d5826d18a14d1880eb6767543df0e6fe..bd17041dd37d98165c5265f4d7fbd9dff90fc9b7 100644 (file)
--- 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 b6fd1a0c566d898c7bf96c35e9893f3a50a4c26e..e61c2f2dfc318e99241e12b7118c1dba72383ac8 100644 (file)
--- 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 b0af2762c24917015abfcc192e5ffc08d4418d91..264ccec05c277c0e52a4f2e428e150007165edfd 100644 (file)
--- 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 ee55c6c47f616295d14331c11e446c19c89715cf..bf48d712f0ee0bbbdac7b56b4edc71a1002d1cd6 100644 (file)
--- 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 9d2d554eda4cf1248efd5d22173bdb94bc20e953..1cde69f8a3d5200dcad60e60a9baca09be7a1187 100644 (file)
--- 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 7841c532c997225fdb97f889b13ec9809c336ca4..fadd00846cc366e2d65f7a0e02b5ec619ac070bc 100644 (file)
--- 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 e84445e9cc72d5646645c3a2b3abdc1d42d671c5..7131d81c4db5e1fdce571ed3436b328d22157967 100644 (file)
--- 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 56d553b78291e9f03f7d07471bf507175d53b816..6c1b11c02a13a6fca8d2d71f45a097ad86e65690 100644 (file)
--- 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 c89341ebacbbda5c0634b6024653db353e89c9ab..e09abc7ff9b96841acd8e7302e7e10d7a45ece24 100644 (file)
--- 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 c891ff27f4bde146c0c376b48b128ccd600450ea..737c42f67264904689d6a2f184ca73fc74396705 100644 (file)
--- 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 920f0bce9c650fb1dc516009156ce6e682f2292b..a7a26370b02f5722cad7245cb19d795802eca018 100644 (file)
--- 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 359fa199e4268c0ed7c6b69073f0a9688dce59b3..89ddd4536b0edc749d149f27a1d00de3f976ace6 100644 (file)
--- 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 fa85fa76536c7443b4963e530110966f16a8b181..dad9250a5bc31295aa6577aa1b17428bd8ec1b08 100644 (file)
--- 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 ed2a4c16fda417c0590409731939e6b7bb578678..64443c630d1064cc330e7ecd093013ec9b6164ba 100755 (executable)
--- 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`