Re: PostgreSQL 8.4.8 bringing my website down every evening

Hello,

I'm still suffering with my Drupal 7.2 site and
PostgreSQL 8.4.8 every evening, for example
right now. I have tried different combinations
for /etc/pgbouncer.ini - for example now I have:

[databases]
pref = host=/tmp user=pref password=XXX dbname=pref

[pgbouncer]
logfile = /var/log/pgbouncer.log
pidfile = /var/run/pgbouncer/pgbouncer.pid
;listen_addr = 127.0.0.1
listen_port = 6432
unix_socket_dir = /tmp

auth_type = md5
auth_file = /var/lib/pgsql/data/global/pg_auth

pool_mode = session

; If server was used more recently that this many seconds ago,
; skip the check query.  Value 0 may or may not run in immidiately.
server_check_delay = 10

max_client_conn = 200
default_pool_size = 20

log_connections = 1
log_disconnections = 1
log_pooler_errors = 1

I have moved Drupal 7.2 and all my PHP scripts
(mostly displaying stats for the players of my card game)
to use the /tmp and port 6432 (instead of 5432).

During off-peak hours the site works ok.

But on evenings everything stops.

For example pg_top shows (why is everything idle?):

last pid:  5215;  load avg:  0.65,  1.64,  2.13;       up 0+00:46:48

20:16:37
22 processes: 22 sleeping
CPU states: 12.4% user,  0.0% nice,  0.3% system, 87.4% idle,  0.1% iowait
Memory: 1187M used, 2737M free, 34M buffers, 611M cached
Swap: 7812M free

  PID USERNAME PRI NICE  SIZE   RES STATE   TIME   WCPU    CPU COMMAND
 3303 postgres  16    0 1170M  137M sleep   3:29 10.92% 20.16%
postgres: pref pref [local] idle
 5045 postgres  18    0 1169M  168M sleep   0:49  0.00%  0.00%
postgres: pref pref [local] idle
 5057 postgres  16    0 1169M  168M sleep   0:37  0.00%  0.00%
postgres: pref pref [local] idle
 5000 postgres  16    0 1169M  168M sleep   0:34  0.00%  0.00%
postgres: pref pref [local] idle
 5025 postgres  18    0 1169M  150M sleep   0:31  0.00%  0.00%
postgres: pref pref [local] idle
 5030 postgres  16    0 1171M  152M sleep   0:29  0.00%  0.00%
postgres: pref pref [local] idle
 5046 postgres  18    0 1169M  168M sleep   0:28  0.00%  0.00%
postgres: pref pref [local] idle
 5001 postgres  18    0 1169M  168M sleep   0:24  0.00%  0.00%
postgres: pref pref [local] idle
 5050 postgres  16    0 1169M  168M sleep   0:18  0.00%  0.00%
postgres: pref pref [local] idle
 5047 postgres  16    0 1169M  168M sleep   0:18  0.00%  0.00%
postgres: pref pref [local] idle
 5014 postgres  16    0 1169M  168M sleep   0:15  0.00%  0.00%
postgres: pref pref [local] idle
 5038 postgres  16    0 1171M   73M sleep   0:13  0.00%  0.00%
postgres: pref pref [local] idle
 5024 postgres  19    0 1169M  168M sleep   0:10  0.00%  0.00%
postgres: pref pref [local] idle
 5004 postgres  25    0 1169M   52M sleep   0:10  0.00%  0.00%
postgres: pref pref [local] idle
 5039 postgres  16    0 1169M   70M sleep   0:10  0.00%  0.00%
postgres: pref pref [local] idle
 5059 postgres  23    0 1169M  150M sleep   0:10  0.00%  0.00%
postgres: pref pref [local] idle
 5015 postgres  16    0 1167M  163M sleep   0:08  0.00%  0.00%
postgres: pref pref [local] idle
 5003 postgres  23    0 1169M  167M sleep   0:08  0.00%  0.00%
postgres: pref pref [local] idle
 5013 postgres  25    0 1169M  150M sleep   0:07  0.00%  0.00%
postgres: pref pref [local] idle
 5051 postgres  23    0 1169M  150M sleep   0:07  0.00%  0.00%
postgres: pref pref [local] idle
 4999 postgres  25    0 1169M   30M sleep   0:05  0.00%  0.00%
postgres: pref pref [local] idle
 5216 postgres  16    0 1166M 4752K sleep   0:00  0.00%  0.00%
postgres: pref pref [local] idle

In my postgresql.conf I have:

max_connections = 50
shared_buffers = 1024MB

(the rest unchanged, besides log settings.
I can't access logs well enough now,
because I'm on bad GPRS connection from Mallorca...)

In my httpd.conf I have:

<IfModule prefork.c>
StartServers       8
MinSpareServers    5
MaxSpareServers   20
ServerLimit      120
MaxClients       120
MaxRequestsPerChild  4000
</IfModule>

In error_log I see no alarming errors, but I don't
understand why does pg_top show "idle"?

In pgbouncer.log I have:

2011-06-16 20:10:54.315 4997 LOG C-0xbab2f40: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:10:56.472 4997 LOG C-0xbab30a0: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:10:58.488 4997 LOG C-0xbab3200: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:10:58.957 4997 LOG C-0xbab3360: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:02.264 4997 LOG C-0xbab34c0: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:05.782 4997 LOG C-0xbab3620: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:09.348 4997 LOG C-0xbab3780: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:12.349 4997 LOG C-0xbab38e0: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:12.701 4997 LOG C-0xbab3a40: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:14.452 4997 LOG C-0xbab3ba0: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:20.091 4997 LOG C-0xbab3d00: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:21.301 4997 LOG C-0xbab3e60: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:27.123 4997 LOG C-0xbab3fc0: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:32.739 4997 LOG Stats: 20 req/s, in 2366 b/s, out
53821 b/s,query 114176 us
2011-06-16 20:11:34.074 4997 LOG C-0xbab4120: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:35.395 4997 LOG C-0xbab4280: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:37.558 4997 LOG C-0xbab43e0: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:47.783 4997 LOG C-0xbab4540: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:48.624 4997 LOG C-0xbab46a0: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:50.553 4997 LOG C-0xbab4800: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:51.802 4997 LOG C-0xbab4960: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:53.019 4997 LOG C-0xbab4ac0: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:54.021 4997 LOG C-0xbab4c20: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:12:03.959 4997 LOG C-0xbab4d80: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:12:11.356 4997 LOG C-0xbab4ee0: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:12:11.794 4997 LOG C-0xbab5040: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:12:28.356 4997 LOG C-0xbab51a0: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:12:29.506 4997 LOG C-0xbab5300: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:12:30.033 4997 LOG C-0xbab5460: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:12:32.740 4997 LOG Stats: 13 req/s, in 1601 b/s, out
20196 b/s,query 107777 us
2011-06-16 20:12:33.978 4997 LOG C-0xbab5460: pref/pref@unix:6432
closing because: client close request (age=3)
2011-06-16 20:12:41.241 4997 LOG C-0xbab5460: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:13:00.454 4997 LOG C-0xbab55c0: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:13:15.025 4997 LOG C-0xbab5720: pref/pref@unix:6432
login attempt: db=pref user=pref
2011-06-16 20:13:32.740 4997 LOG Stats: 3 req/s, in 415 b/s, out 31253
b/s,query 108335 us
2011-06-16 20:14:32.740 4997 LOG Stats: 0 req/s, in 0 b/s, out 0 b/s,query 0 us
2011-06-16 20:15:32.740 4997 LOG Stats: 0 req/s, in 0 b/s, out 0 b/s,query 0 us
2011-06-16 20:16:32.740 4997 LOG Stats: 0 req/s, in 0 b/s, out 0 b/s,query 0 us
2011-06-16 20:17:32.740 4997 LOG Stats: 0 req/s, in 0 b/s, out 0 b/s,query 0 us
2011-06-16 20:18:32.741 4997 LOG Stats: 0 req/s, in 0 b/s, out 0 b/s,query 0 us
2011-06-16 20:19:32.741 4997 LOG Stats: 0 req/s, in 0 b/s, out 0 b/s,query 0 us
2011-06-16 20:20:32.742 4997 LOG Stats: 0 req/s, in 0 b/s, out 0 b/s,query 0 us

(why 0 req/s here?)

My machine is a Quad-core with 4GB RAM.
I'm running CentOS 5.6 / 64 bit with PGDG:

pgbouncer-1.3.4-1.rhel5
pgdg-centos-8.4-2
pg_top-3.6.2-1.rhel5
php53-pgsql-5.3.3-1.el5_6.1
compat-postgresql-libs-4-1PGDG.rhel5
postgresql-8.4.8-1PGDG.rhel5
postgresql-devel-8.4.8-1PGDG.rhel5
postgresql-libs-8.4.8-1PGDG.rhel5
postgresql-server-8.4.8-1PGDG.rhel5

It is not loaded since I have pgbouncer active:

top - 20:26:42 up 56 min,  2 users,  load average: 0.54, 0.70, 1.38
Tasks: 251 total,   2 running, 249 sleeping,   0 stopped,   0 zombie
Cpu0  :  0.3%us,  0.0%sy,  0.0%ni, 99.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu1  :  0.0%us,  0.3%sy,  0.0%ni, 99.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu2  : 13.2%us,  0.0%sy,  0.0%ni, 85.5%id,  1.3%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu3  : 20.5%us,  0.3%sy,  0.0%ni, 78.2%id,  0.3%wa,  0.0%hi,  0.7%si,  0.0%st
Mem:   4018280k total,  1229012k used,  2789268k free,    36832k buffers
Swap:  7999472k total,        0k used,  7999472k free,   636948k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 2847 afarber   16   0 98808  29m 2704 S 21.2  0.7  11:28.30 pref.pl
 3303 postgres  16   0 1169m 137m 134m R 12.9  3.5   4:43.59 postmaster
 5239 afarber   15   0 12896 1228  828 R  0.7  0.0   0:00.08 top
    1 root      15   0 10372  696  580 S  0.0  0.0   0:01.05 init
    2 root      RT  -5     0    0    0 S  0.0  0.0   0:00.00 migration/0
    3 root      34  19     0    0    0 S  0.0  0.0   0:00.01 ksoftirqd/0
    4 root      RT  -5     0    0    0 S  0.0  0.0   0:00.00 watchdog/0
    5 root      RT  -5     0    0    0 S  0.0  0.0   0:00.00 migration/1
    6 root      34  19     0    0    0 S  0.0  0.0   0:00.00 ksoftirqd/1
    7 root      RT  -5     0    0    0 S  0.0  0.0   0:00.00 watchdog/1
    9 root      34  19     0    0    0 S  0.0  0.0   0:00.00 ksoftirqd/2
   10 root      RT  -5     0    0    0 S  0.0  0.0   0:00.00 watchdog/2
   11 root      RT  -5     0    0    0 S  0.0  0.0   0:00.00 migration/3
   12 root      34  19     0    0    0 S  0.0  0.0   0:00.00 ksoftirqd/3
   13 root      RT  -5     0    0    0 S  0.0  0.0   0:00.00 watchdog/3
   14 root      10  -5     0    0    0 S  0.0  0.0   0:00.00 events/0
   15 root      10  -5     0    0    0 S  0.0  0.0   0:00.00 events/1
   16 root      10  -5     0    0    0 S  0.0  0.0   0:00.00 events/2
   17 root      10  -5     0    0    0 S  0.0  0.0   0:00.00 events/3
   18 root      10  -5     0    0    0 S  0.0  0.0   0:00.00 khelper
   55 root      14  -5     0    0    0 S  0.0  0.0   0:00.00 kthread
   62 root      10  -5     0    0    0 S  0.0  0.0   0:00.00 kblockd/0
   63 root      10  -5     0    0    0 S  0.0  0.0   0:00.00 kblockd/1
   64 root      10  -5     0    0    0 S  0.0  0.0   0:00.02 kblockd/2
....

I have probably misconfigured pgbouncer?

My (poor) site is: preferans.de (currently almost at halt)

Any help please?
Alex