Odd new symptom - database locking up on a query - Mailing list pgsql-general

Hello,

I've encountered an odd new symptom which has me absolutely flabbergasted.

I'm running about 20-25 parallel connections to my Debian/Woody PostgreSQL
7.2.1 server (Dual P4X 2.4, RAID-1 log partition, RAID-5 data partition,
8gb RAM, 64meg sort space, 256meg shared memory segment).

At a certain point, a query hangs, then another, then another, until all my
connections are blocked. My application completely comes to a halt.

I've never seen this before, and don't know where to begin trying to solve
it. Certainly nothing should cause these problems: the three queries being
heavily used are simple:

1) A single one-to-one Joined SELECT
2) A simple DELETE with a static IN clause to delete a whole bunch of records
3) A simple UPDATE with a similar static IN clause to update one field (to
now()) of a whole bunch of primary keys

Nothing appears in the logs. In fact, nothing seems amiss anywhere.

So, I'm stumped. I'm going to turn on some of the statistics collection
stuff (new in 7.2) but really don't know what to do.

I welcome ideas. Some "top" and "ps" stuff is below.

Cheers,

Doug

TOP

  22:30:25 up 14 days,  5:59,  1 user,  load average: 12.02, 10.67, 9.59
89 processes: 77 sleeping, 12 running, 0 zombie, 0 stopped
CPU states:  99.1% user,   0.5% system,   0.4% nice,  -0.0% idle
Mem:   8123456K total,  2839996K used,  5283460K free,   133144K buffers
Swap:  8000208K total,        0K used,  8000208K free,  2453568K cached

   PID USER     PRI  NI  SIZE  RSS SHARE STAT %CPU %MEM   TIME COMMAND
19405 postgres  18   0 42244  41M 40956 S    21.2  0.5   1:15 postmaster
19421 postgres  20   0 39928  38M 38612 R    21.2  0.4   1:15 postmaster
19398 postgres  18   0 42796  41M 41480 R    20.6  0.5   1:14 postmaster
19417 postgres  20   0 40448  39M 39168 R    20.6  0.4   1:15 postmaster
19426 postgres  20   0 36436  35M 35104 R    20.4  0.4   1:10 postmaster
19427 postgres  19   0 33928  33M 32592 S    20.4  0.4   1:11 postmaster
19416 postgres  19   0 37852  36M 36500 S    20.2  0.4   1:10 postmaster
19402 postgres  17   0 51508  50M 50268 S    20.0  0.6   1:27 postmaster
19411 postgres  18   0 40884  39M 39620 R    20.0  0.5   1:21 postmaster
19393 postgres  19   0 47952  46M 46700 S    19.6  0.5   1:34 postmaster
19400 postgres  18   0 54308  52M 53068 S    19.6  0.6   1:31 postmaster
19423 postgres  20   0 37648  36M 36356 R    19.6  0.4   1:13 postmaster
19403 postgres  19   0 49708  48M 48456 S    19.4  0.6   1:26 postmaster
19406 postgres  16   0 45292  44M 44040 R    19.4  0.5   1:24 postmaster
19431 postgres  18   0 35856  34M 34524 S    19.4  0.4   1:11 postmaster
19410 postgres  17   0 43508  42M 42248 R    19.2  0.5   1:21 postmaster
19394 postgres  18   0 58308  56M 57096 S    19.0  0.7   1:43 postmaster
19414 postgres  17   0 39452  38M 38168 R    19.0  0.4   1:15 postmaster
19399 postgres  15   0 50424  49M 49184 S    18.4  0.6   1:37 postmaster
19391 postgres  15   0 66668  65M 65464 S    17.7  0.8   1:45 postmaster

PS (IP addresses removed)
postgres 19376  0.0  0.0 276036 4520 pts/0   S    22:22   0:00
/usr/lib/postgresql/bin/postmaster
postgres 19378  0.0  0.0 277028 4500 pts/0   S    22:22   0:00 postgres:
stats buffer process
postgres 19379  0.0  0.0 276128 4596 pts/0   S    22:22   0:00 postgres:
stats collector process
postgres 19386  0.0  0.0 277164 6716 pts/0   S    22:22   0:00 postgres:
bknowlton bfkdev A.B.C.20 idle
postgres 19387  0.0  0.0 277164 6540 pts/0   S    22:22   0:00 postgres:
bknowlton bfkdev A.B.C.20 idle
postgres 19388  0.0  0.0 277164 6548 pts/0   S    22:22   0:00 postgres:
bknowlton bfkdev A.B.C.20 idle
postgres 19389  0.0  0.0 277164 6544 pts/0   S    22:22   0:00 postgres:
bknowlton bfkdev A.B.C.20 SELECT
postgres 19390  0.0  0.0 277164 6548 pts/0   S    22:22   0:00 postgres:
bknowlton bfkdev A.B.C.20 idle
postgres 19391 22.2  0.8 277808 72828 pts/0  S    22:22   1:59 postgres:
tomcat pexicast_lg A.B.C.100 DELETE
postgres 19392  0.3  0.1 277816 15248 pts/0  S    22:22   0:01 postgres:
tomcat pexicast_lg A.B.C.100 DELETE waiting
postgres 19393 20.3  0.6 277816 52536 pts/0  S    22:22   1:48 postgres:
tomcat pexicast_lg A.B.C.100 DELETE
postgres 19394 21.9  0.7 277812 63936 pts/0  S    22:22   1:57 postgres:
tomcat pexicast_lg A.B.C.100 DELETE
postgres 19395  0.3  0.1 277812 15600 pts/0  S    22:22   0:01 postgres:
tomcat pexicast_lg A.B.C.100 DELETE waiting
postgres 19396  0.2  0.1 277812 15608 pts/0  S    22:22   0:01 postgres:
tomcat pexicast_lg A.B.C.100 DELETE waiting
postgres 19397  0.4  0.1 277812 16128 pts/0  S    22:22   0:02 postgres:
tomcat pexicast_lg A.B.C.100 DELETE waiting
postgres 19398 16.5  0.5 277956 47424 pts/0  R    22:22   1:28 postgres:
tomcat pexicast_lg A.B.C.100 DELETE
postgres 19399 20.8  0.6 277816 55272 pts/0  S    22:22   1:51 postgres:
tomcat pexicast_lg A.B.C.100 DELETE
postgres 19400 19.7  0.7 277816 59996 pts/0  S    22:22   1:45 postgres:
tomcat pexicast_lg A.B.C.100 DELETE
postgres 19401  0.8  0.2 277816 16764 pts/0  S    22:22   0:04 postgres:
tomcat pexicast_lg A.B.C.100 DELETE waiting
postgres 19402 19.1  0.7 277812 57124 pts/0  S    22:22   1:42 postgres:
tomcat pexicast_lg A.B.C.100 DELETE
postgres 19403 18.8  0.6 277816 54764 pts/0  S    22:22   1:40 postgres:
tomcat pexicast_lg A.B.C.100 DELETE
postgres 19404  0.4  0.1 277956 16068 pts/0  S    22:22   0:02 postgres:
tomcat pexicast_lg A.B.C.100 DELETE waiting
postgres 19405 16.8  0.5 277952 46812 pts/0  S    22:22   1:29 postgres:
tomcat pexicast_lg A.B.C.100 DELETE
postgres 19406 18.5  0.6 277948 49896 pts/0  R    22:22   1:38 postgres:
tomcat pexicast_lg A.B.C.100 DELETE
postgres 19407  0.3  0.1 277952 15892 pts/0  S    22:22   0:01 postgres:
tomcat pexicast_lg A.B.C.100 DELETE waiting
postgres 19408  0.3  0.1 277948 16060 pts/0  S    22:22   0:01 postgres:
tomcat pexicast_lg A.B.C.100 DELETE waiting
postgres 19409  0.5  0.2 278216 17524 pts/0  S    22:22   0:02 postgres:
tomcat pexicast_lg A.B.C.100 DELETE waiting
postgres 19410 18.1  0.5 277952 48120 pts/0  S    22:22   1:35 postgres:
tomcat pexicast_lg A.B.C.100 DELETE
postgres 19411 18.0  0.5 277952 44904 pts/0  S    22:22   1:35 postgres:
tomcat pexicast_lg A.B.C.100 DELETE
postgres 19412  0.3  0.1 277952 16156 pts/0  S    22:22   0:01 postgres:
tomcat pexicast_lg A.B.C.100 DELETE waiting
postgres 19413  0.7  0.2 277952 17396 pts/0  S    22:22   0:03 postgres:
tomcat pexicast_lg A.B.C.100 DELETE waiting
postgres 19414 17.0  0.5 278212 43368 pts/0  S    22:22   1:30 postgres:
tomcat pexicast_lg A.B.C.100 DELETE
postgres 19415  0.4  0.2 278216 17080 pts/0  S    22:22   0:02 postgres:
tomcat pexicast_lg A.B.C.100 DELETE waiting
postgres 19416 16.1  0.5 278220 41980 pts/0  S    22:22   1:24 postgres:
tomcat pexicast_lg A.B.C.100 DELETE
postgres 19417 17.1  0.5 278208 44652 pts/0  S    22:22   1:30 postgres:
tomcat pexicast_lg A.B.C.100 DELETE
postgres 19418  0.5  0.2 278212 17440 pts/0  S    22:22   0:02 postgres:
tomcat pexicast_lg A.B.C.100 DELETE waiting
postgres 19419  0.2  0.2 278216 17692 pts/0  S    22:22   0:01 postgres:
tomcat pexicast_lg A.B.C.100 DELETE waiting
postgres 19421 17.2  0.5 278216 43920 pts/0  S    22:22   1:30 postgres:
tomcat pexicast_lg A.B.C.100 DELETE
postgres 19422  0.3  0.0 277452 6548 pts/0   S    22:22   0:02 postgres:
tomcat pexicast_lg A.B.C.100 idle
postgres 19423 16.8  0.5 278208 41528 pts/0  S    22:22   1:28 postgres:
tomcat pexicast_lg A.B.C.100 DELETE
postgres 19424  0.3  0.2 278216 16508 pts/0  S    22:22   0:01 postgres:
tomcat pexicast_lg A.B.C.100 DELETE waiting
postgres 19425  0.7  0.2 278216 18040 pts/0  S    22:22   0:03 postgres:
tomcat pexicast_lg A.B.C.100 DELETE waiting
postgres 19426 16.3  0.4 278216 40352 pts/0  R    22:22   1:25 postgres:
tomcat pexicast_lg A.B.C.100 DELETE
postgres 19427 16.4  0.4 278216 37476 pts/0  S    22:22   1:26 postgres:
tomcat pexicast_lg A.B.C.100 DELETE
postgres 19428  0.4  0.2 278216 16844 pts/0  S    22:22   0:02 postgres:
tomcat pexicast_lg A.B.C.100 DELETE waiting
postgres 19429  0.3  0.0 277192 6532 pts/0   S    22:22   0:01 postgres:
tomcat pexicast_lg A.B.C.100 idle
postgres 19430  0.3  0.0 277188 6596 pts/0   S    22:22   0:01 postgres:
tomcat pexicast_lg A.B.C.100 idle
postgres 19431 16.4  0.4 278216 39696 pts/0  S    22:22   1:25 postgres:
tomcat pexicast_lg A.B.C.100 DELETE
postgres 19432  0.7  0.2 278212 18164 pts/0  S    22:22   0:03 postgres:
tomcat pexicast_lg A.B.C.100 DELETE waiting
postgres 19433  0.5  0.0 277184 6552 pts/0   S    22:22   0:02 postgres:
tomcat pexicast_lg A.B.C.100 idle
postgres 19434  0.5  0.0 277200 6724 pts/0   S    22:22   0:02 postgres:
tomcat pexicast_lg A.B.C.100 idle
root     19452  0.0  0.0  1344  436 pts/0    S    22:31   0:00 fgrep post