Odd new symptom - database locking up on a query

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