Re: Postmaster hangs

Karen Pease wrote:
> Sorry for the delay in responding, and thanks for your help.

Sorry I have to keep on asking things. Unfortunately it's sometimes
quite hard to tell what part of a system is misbehaving, and it can
require the collection of quite a bit of diagnostic data :S

From what I've seen below (see inline comments) it looks most of the
tasks you've provided information for are busy doing atime updates on
files after reading them. This doesn't necessarily mean the file system
and the atime updates are part of the problem, but given that you're
observing problems and the problem processes seems to be busy doing
atime updates it's at least interesting.

Possible explanations that spring to mind:

- Your disk subsystem is hopelessly overloaded and is trying to service
too many requests, so all you're really seeing is processes stuck in
synchronous read requests in the kernel while they wait for I/O
operations to complete. The atime writes add lots of small writes in
amongst the reads, which can really kill the performance of some RAID
systems in particular. However, if this was the problem then you'd
expect that after killing the problem processes with a SIGTERM (kill
-15) they'd eventually exit, even if it took a few minutes. Also, if
you ran "vmstat 1" you'd see a fair bit of disk activity.

- There's something wrong with your storage subsystem so that it's
failing to return from some read or write attempts. I've seen this
before when bad blocks on a disk cause almost endless retries, with the
reading process stuck waiting for a read that'll take hours to return if
it ever does. You'd usually see signs of this sort of issue in the
kernel log (dmesg) for direct disk access, in hardware raid controller
monitoring tools if it's hardware RAID, in `mdadm --detail' for Linux
software RAID, etc. smartctl from smartmontools can check individual ATA
disks for bad sectors and can report their internal error logs; this
won't help for hardware RAID arrays or SCSI/FC disks.

- You've hit a kernel bug, probably related to ext4.

- ... something I haven't thought of ...

Anyway, first, turn off atime updates, at least for any file system you
use PostgreSQL on. It's a performance killer. The "noatime" mount option
will disable atime updates for ext2/3/4 ; add it to the options section
in /etc/fstab then "mount -o remount" the file system(s) of interest.

Second, consider updating to the latest Linux kernel and seeing if the
problem goes away.

Details below:

> For a newly-started psql process that locks as soon as the password is
> entered:
>
> #0 0x00fbe416 in __kernel_vsyscall ()
> #1 0x00c7673b in poll () from /lib/libc.so.6
> #2 0x00d20eaa in ?? () from /usr/lib/libpq.so.5
> #3 0x00d20faa in ?? () from /usr/lib/libpq.so.5
> #4 0x00d1b344 in ?? () from /usr/lib/libpq.so.5
> #5 0x00d1d571 in PQsetdbLogin () from /usr/lib/libpq.so.5
> #6 0x08055662 in geteuid ()
> #7 0x00bb36e5 in __libc_start_main () from /lib/libc.so.6
> #8 0x0804a9c1 in geteuid ()

You're missing debug symbols for libpq, so gdb can't show line numbers
in libpq, and it can't even show function names unless the function is a
public export. Your Linux distro clearly separates debug info out of
packages, and you'll need to install some debug symbol packages. For
Fedora, you can find instructions at:

https://fedoraproject.org/wiki/StackTraces#debuginfo

In this case it's probably not important since it's pretty clear any
issue is on the backend side, but in general it's a good idea to make
sure you have appropriate debug info packages installed, as noted in the
Pg wiki article on getting a stack trace.

> And for the process that ran the update commands that locked it:
>
> #0 0x00e12416 in __kernel_vsyscall ()
> #1 0x00c7673b in poll () from /lib/libc.so.6
> #2 0x00d20eaa in ?? () from /usr/lib/libpq.so.5
> #3 0x00d20faa in ?? () from /usr/lib/libpq.so.5
> #4 0x00d21023 in ?? () from /usr/lib/libpq.so.5
> #5 0x00d2062a in PQgetResult () from /usr/lib/libpq.so.5
> #6 0x00d20853 in ?? () from /usr/lib/libpq.so.5
> #7 0x0804e97f in geteuid ()
> #8 0x080528bb in geteuid ()
> #9 0x0804b37c in geteuid ()
> #10 0x08055856 in geteuid ()
> #11 0x00bb36e5 in __libc_start_main () from /lib/libc.so.6
> #12 0x0804a9c1 in geteuid ()

OK, so nothing special - it's waiting for something to read on a socket,
in this case presumably waiting for the Pg backend to respond.

> That sysctl command did the trick. Here's the relevant sections:

OK, so both postgresql instances (it's hard to tell from here which is a
backend and which is the postmaster) appear to be doing atime updates
for files touched in disk reads, or at least that's how it looks with my
very minimal kernel knowledge.

Second: From this one snapshot in time it's not possible to tell what
(if anything) is going wrong with the postgresql backends. Everything
looks pretty sane. The kernel stack trace doesn't tell us if PostgreSQL
is somehow stuck doing this atime update or whether it's just busy
touching a lot of files. There's nothing inconsistent with a big, busy
query.

This is when I start wanting to be able to play with the machine. It's
hard to do interactive debugging remotely, and that's what I really want
to do to get a handle on this. I don't think I'm smart enough to figure
this one out otherwise, though others here on this list probably are.

As for Apache: about half of your httpd instances appear to be waiting
on a lock. The other half of them are updating atime metadata on files
after performing reads. And this one I'm not sure what it's doing:

> httpd S c06aaab2 0 18474 3285
> ef333d94 00000082 ef333d2c c06aaab2 ef333d38 c087c67c c087fc00
> c087fc00
> c087fc00 ec6319a0 ec631c14 c1ff7c00 00000002 c1ff7c00 c087c8e8
> ef333dc4
> ef333d80 c041f4f5 ef333d6c ec631c14 05f8a33e c04ec457 ef333dc8
> ee32dea8
> Call Trace:
> [<c06aaab2>] ? _cond_resched+0x8/0x32
> [<c041f4f5>] ? kmap_atomic_prot+0x1b0/0x1da
> [<c04ec457>] ? ipc_lock+0x2b/0x45
> [<c04ee244>] sys_semtimedop+0x4ca/0x579
> [<c047d8fb>] ? handle_mm_fault+0x2e8/0x6ec
> [<c041f325>] ? kunmap_atomic+0x87/0xa7
> [<c06adcde>] ? do_page_fault+0x3ac/0x710
> [<c041f8b4>] ? resched_task+0x3a/0x6e
> [<c06abfcb>] ? _spin_unlock_irqrestore+0x22/0x38
> [<c0422597>] ? __dequeue_entity+0x73/0x7b
> [<c048edad>] ? __slab_alloc+0x56/0x45b
> [<c04036bf>] ? __switch_to+0xb9/0x139
> [<c06abe09>] ? _spin_lock+0x8/0xb
> [<c043f21a>] ? add_wait_queue+0x2b/0x30
> [<c04b99b5>] ? ep_ptable_queue_proc+0x58/0x69
> [<c0407c02>] sys_ipc+0x48/0x149
> [<c040b098>] ? syscall_trace_enter+0xb5/0xc9
> [<c0404c8a>] syscall_call+0x7/0xb

--
Craig Ringer