{"action":"created","issue":{"url":"https://api.github.com/repos/pgbouncer/pgbouncer/issues/300","repository_url":"https://api.github.com/repos/pgbouncer/pgbouncer","labels_url":"https://api.github.com/repos/pgbouncer/pgbouncer/issues/300/labels{/name}","comments_url":"https://api.github.com/repos/pgbouncer/pgbouncer/issues/300/comments","events_url":"https://api.github.com/repos/pgbouncer/pgbouncer/issues/300/events","html_url":"https://github.com/pgbouncer/pgbouncer/issues/300","id":328138185,"node_id":"MDU6SXNzdWUzMjgxMzgxODU=","number":300,"title":"pgBouncer taking connections from reserve_pool at an enormous rate","user":{"login":"gonguinguen","id":3819939,"node_id":"MDQ6VXNlcjM4MTk5Mzk=","avatar_url":"https://avatars2.githubusercontent.com/u/3819939?v=4","gravatar_id":"","url":"https://api.github.com/users/gonguinguen","html_url":"https://github.com/gonguinguen","followers_url":"https://api.github.com/users/gonguinguen/followers","following_url":"https://api.github.com/users/gonguinguen/following{/other_user}","gists_url":"https://api.github.com/users/gonguinguen/gists{/gist_id}","starred_url":"https://api.github.com/users/gonguinguen/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/gonguinguen/subscriptions","organizations_url":"https://api.github.com/users/gonguinguen/orgs","repos_url":"https://api.github.com/users/gonguinguen/repos","events_url":"https://api.github.com/users/gonguinguen/events{/privacy}","received_events_url":"https://api.github.com/users/gonguinguen/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":3,"created_at":"2018-05-31T13:27:16Z","updated_at":"2018-06-05T16:05:44Z","closed_at":null,"author_association":"NONE","body":"Hi there!\r\nI recently moved my apps from Ubuntu to CentOS, and I'm seeing some strage behaviour in pgbouncer.log. \r\nThe pgbouncer version I'm using is 1.8.1, the same version I was using in the old server. Configuration hasn't changed, and the load is pretty much the same. \r\n\r\nThis is what I normally see in pgbouncer.log:\r\n\r\n```\r\n2018-05-30 13:08:01.294 1686 LOG Stats: 23 xacts/s, 1423 queries/s, in 725531 B/s, out 4489904 B/s, xact 277289 us, query 1030 us wait time 16008 us\r\n2018-05-30 13:09:01.294 1686 LOG Stats: 22 xacts/s, 1197 queries/s, in 609964 B/s, out 3904297 B/s, xact 246209 us, query 1215 us wait time 30493 us\r\n2018-05-30 13:10:01.294 1686 LOG Stats: 21 xacts/s, 1246 queries/s, in 635027 B/s, out 4081362 B/s, xact 295812 us, query 1007 us wait time 12728 us\r\n2018-05-30 13:11:01.294 1686 LOG Stats: 21 xacts/s, 1310 queries/s, in 675424 B/s, out 4131956 B/s, xact 230614 us, query 896 us wait time 11688 us\r\n2018-05-30 13:12:01.294 1686 LOG Stats: 22 xacts/s, 1416 queries/s, in 728592 B/s, out 4702683 B/s, xact 322066 us, query 999 us wait time 13361 us\r\n2018-05-30 13:13:01.295 1686 LOG Stats: 21 xacts/s, 1232 queries/s, in 624768 B/s, out 4007642 B/s, xact 330605 us, query 1130 us wait time 179371 us\r\n2018-05-30 13:14:01.296 1686 LOG Stats: 22 xacts/s, 1281 queries/s, in 656547 B/s, out 4127384 B/s, xact 244638 us, query 1089 us wait time 25105 us\r\n2018-05-30 13:15:01.296 1686 LOG Stats: 22 xacts/s, 1179 queries/s, in 600150 B/s, out 3748148 B/s, xact 268356 us, query 1055 us wait time 12338 us\r\n2018-05-30 13:16:01.296 1686 LOG Stats: 23 xacts/s, 1355 queries/s, in 690950 B/s, out 4290023 B/s, xact 316081 us, query 1049 us wait time 41257 us\r\n```\r\n\r\n\r\nHowever, since the migration to CentOS, we are having this brief moments where pgbouncer starts logging **a lot** of lines saying that a connection has been taked from the reserve_pool of a specific database. \r\nIn the log lines I previously showed, notice that pgbouncer reports around ~25 xacts/s, which is the normal activity. But, for example, yesterday, during a window time of 2 minutes, pgbouncer logged more than 130.000 lines with this message:\r\n\r\n```\r\n2018-05-30 13:18:23.016 1686 WARNING C-0x1374668: mydatabase/myuser@127.0.0.1:46955 Taking connection from reserve_pool\r\n2018-05-30 13:18:23.016 1686 WARNING C-0x1374668: mydatabase/myuser@127.0.0.1:46955 Taking connection from reserve_pool\r\n2018-05-30 13:18:23.016 1686 WARNING C-0x1374668: mydatabase/myuser@127.0.0.1:46955 Taking connection from reserve_pool\r\n2018-05-30 13:18:23.016 1686 WARNING C-0x1374668: mydatabase/myuser@127.0.0.1:46955 Taking connection from reserve_pool\r\n2018-05-30 13:18:23.016 1686 WARNING C-0x1374668: mydatabase/myuser@127.0.0.1:46955 Taking connection from reserve_pool\r\n2018-05-30 13:18:23.016 1686 WARNING C-0x1374668: mydatabase/myuser@127.0.0.1:46955 Taking connection from reserve_pool\r\n2018-05-30 13:18:23.016 1686 WARNING C-0x1374668: mydatabase/myuser@127.0.0.1:46955 Taking connection from reserve_pool\r\n```\r\n\r\nSo many lines were logged, that much of them had the same timestamp. I'm thinking if that is even possible. My pgbouncer.ini looks like this:\r\n\r\n```\r\n[pgbouncer]\r\nlogfile = /var/log/pgbouncer/pgbouncer.log\r\npidfile = /var/run/pgbouncer/pgbouncer.pid\r\nlisten_addr = 127.0.0.1\r\nlisten_port = 5432\r\nauth_type = md5\r\nauth_file = /etc/pgbouncer/userlist.txt\r\nadmin_users = postgres\r\nstats_users = postgres\r\npool_mode = transaction\r\nserver_reset_query = DISCARD ALL\r\nmax_client_conn = 10000\r\ndefault_pool_size = 2\r\nmin_pool_size = 0\r\nlog_connections = 0\r\nlog_disconnections = 0\r\nserver_idle_timeout = 10\r\nquery_wait_timeout = 30\r\nreserve_pool_timeout = 5\r\nmax_db_connections = 6\r\n\r\n[databases]\r\nmydatabase = host=localhost port=6543 dbname=mydatabase pool_size=6 reserve_pool=3\r\notherdb = host=localhost port=6543 dbname=otherdb pool_size=6 reserve_pool=3\r\n```\r\n\r\nNotice that the pool_size is 6 and the reserve_pool is only 3.\r\nIf pgbouncer was taking that many connections from reserve pool, shouldn't it be exhausted much sooner?\r\n\r\nConnections to pgbouncer are made only from localhost.\r\nMy application code hasn't changed, it's the same that's been running since a long time ago. We just moved from Ubuntu to CentOS, but since the migration, pgbouncer is reporting that strange situation, and I can't figure out what is going on.\r\n\r\nCould this be an issue within pgBouncer? Where else can I look for errors? I checked postgresql log but there is nothing strange there. Any help or suggestion will be much appreciated.\r\n"},"comment":{"url":"https://api.github.com/repos/pgbouncer/pgbouncer/issues/comments/394766940","html_url":"https://github.com/pgbouncer/pgbouncer/issues/300#issuecomment-394766940","issue_url":"https://api.github.com/repos/pgbouncer/pgbouncer/issues/300","id":394766940,"node_id":"MDEyOklzc3VlQ29tbWVudDM5NDc2Njk0MA==","user":{"login":"gonguinguen","id":3819939,"node_id":"MDQ6VXNlcjM4MTk5Mzk=","avatar_url":"https://avatars2.githubusercontent.com/u/3819939?v=4","gravatar_id":"","url":"https://api.github.com/users/gonguinguen","html_url":"https://github.com/gonguinguen","followers_url":"https://api.github.com/users/gonguinguen/followers","following_url":"https://api.github.com/users/gonguinguen/following{/other_user}","gists_url":"https://api.github.com/users/gonguinguen/gists{/gist_id}","starred_url":"https://api.github.com/users/gonguinguen/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/gonguinguen/subscriptions","organizations_url":"https://api.github.com/users/gonguinguen/orgs","repos_url":"https://api.github.com/users/gonguinguen/repos","events_url":"https://api.github.com/users/gonguinguen/events{/privacy}","received_events_url":"https://api.github.com/users/gonguinguen/received_events","type":"User","site_admin":false},"created_at":"2018-06-05T16:05:44Z","updated_at":"2018-06-05T16:05:44Z","author_association":"NONE","body":"Hi Glenn, thank you for your time.\r\n\r\n> pool_size is a per-database setting, if not set, it will use the default_pool_size. So setting a pool_size of 2 + 1 reserve basically states to only allow 3\r\n\r\nTrue. That's what I want in those cases, no more than 3 connections do that database. For some other databases, as their websites have more traffic, pool_size and reserve_pool is a bit higher (6 and 3 respectively), allowing up to 9 connections.\r\n\r\n\r\n> Also, make sure you postgresql config : max_connections is large enough to cover the connections pgbouncer will open.\r\n\r\nYes. I have postgresql max_connections set to 300. Also I use Longview to monitor postgresql, and with this configuration, it shows ~70 connections.\r\n\r\n\r\n> (abount min_pool_size) No, that's not how the pools work. the pools only come into existence when there is a client.\r\n\r\nI've just tried to change min_pool_size in production. As I pointed before, postgresql reports ~70 connections. I changed pgbouncer min_pool_size from 0 to 5 and it happened what I thought it would: real connections to postgres went to the roof, in less than a minute I had almost 300, and as my postgresql max_connections is set to 300, pgbouncer started to throw errors saying this.\r\n\r\n```\r\n2018-06-05 12:36:53.701 1686 ERROR S: login failed: FATAL: las conexiones restantes están reservadas a superusuarios y no de replicación\r\n2018-06-05 12:37:14.289 1686 WARNING C-0x13d07a0: secundaria27campana/medios@127.0.0.1:62479 Pooler Error: pgbouncer cannot connect to server\r\n2018-06-05 12:37:15.205 1686 WARNING C-0x1374008: meganoticias/medios@127.0.0.1:62543 Pooler Error: pgbouncer cannot connect to server\r\n2018-06-05 12:37:43.660 1686 WARNING C-0x13d0f98: noticiasderufino/medios@127.0.0.1:1522 Pooler Error: pgbouncer cannot connect to server\r\n2018-06-05 12:42:36.959 1686 WARNING C-0x13cf948: nortegrandenews/medios@127.0.0.1:29482 Pooler Error: pgbouncer cannot connect to server\r\n```\r\n\r\nI think that, in my scenario, min_pool_size=0 is what I want. \r\nOr maybe min_pool_size=1, but I think I would have to increase postgresql max_connections, just in case.\r\n\r\n\r\n> I'm working on a deeper issue with query_wait_timeout where I have tons of connections that seem to be stuck in that state [...] You could use a larger value for query_wait_timeout to still do some cleaning , like 3600 or bigger.\r\n\r\nI don't think that's safe. The query_wait_timeout is presented in the official docs under the \"Dangerous timeouts\" section. It says _Maximum time queries are allowed to spend waiting for execution. If the query is not assigned to a server during that time, the client is disconnected. This is used to prevent unresponsive servers from grabbing up connections. [seconds]. It also helps when server is down or database rejects connections for any reason. If this is disabled, clients will be queued infinitely._\r\n\r\nI think it depends on the case, but in my case (news and articles websites), I think a small value is more appropiate. There isn't any query that takes too much time to execute, most of them are simple selects. And considering my webserver stabishes a 60 second http timeout, I think query_wait_timeout is fine at 30 seconds, and could be even smaller.\r\n\r\nBut I'm not expert on this. PgBouncer is a really powerful tool, but it's been difficult for me to understand how some options work and how to tune them for my specific scenario. \r\n\r\nMaybe the problem I'm seeing is produced by another layer of my application. This exact pgbouncer version and configuration was running smoothly at Ubuntu, but at Centos it started reporting those weird logs. I don't understand what pgBouncer is logging, is that even possible? Taking connections from reserve pool at that rate, with that configuration, would make the pool exhausted in a few seconds, but it kept logging the same, thousands of times, during two minutes. What scenario could produce that? I don't see any requests spikes on nginx monitors :/"}}
{"actor":{"display_login":"gonguinguen"}}