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(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:10:56.472 4997 LOG C-0xbab30a0: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:10:58.488 4997 LOG C-0xbab3200: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:10:58.957 4997 LOG C-0xbab3360: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:02.264 4997 LOG C-0xbab34c0: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:05.782 4997 LOG C-0xbab3620: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:09.348 4997 LOG C-0xbab3780: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:12.349 4997 LOG C-0xbab38e0: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:12.701 4997 LOG C-0xbab3a40: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:14.452 4997 LOG C-0xbab3ba0: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:20.091 4997 LOG C-0xbab3d00: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:21.301 4997 LOG C-0xbab3e60: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:27.123 4997 LOG C-0xbab3fc0: pref/pref(at)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(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:35.395 4997 LOG C-0xbab4280: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:37.558 4997 LOG C-0xbab43e0: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:47.783 4997 LOG C-0xbab4540: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:48.624 4997 LOG C-0xbab46a0: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:50.553 4997 LOG C-0xbab4800: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:51.802 4997 LOG C-0xbab4960: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:53.019 4997 LOG C-0xbab4ac0: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:11:54.021 4997 LOG C-0xbab4c20: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:12:03.959 4997 LOG C-0xbab4d80: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:12:11.356 4997 LOG C-0xbab4ee0: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:12:11.794 4997 LOG C-0xbab5040: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:12:28.356 4997 LOG C-0xbab51a0: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:12:29.506 4997 LOG C-0xbab5300: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:12:30.033 4997 LOG C-0xbab5460: pref/pref(at)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(at)unix:6432
closing because: client close request (age=3)
2011-06-16 20:12:41.241 4997 LOG C-0xbab5460: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:13:00.454 4997 LOG C-0xbab55c0: pref/pref(at)unix:6432
login attempt: db=pref user=pref
2011-06-16 20:13:15.025 4997 LOG C-0xbab5720: pref/pref(at)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