Re: syslog enabled causes random hangs?

I'm back with more on the funky glibc-syslog-Postgres deadlocking behavior:

> It's really too bad that your gdb backtrace didn't show anything past
> the write_syslog level (which is an elog subroutine).  If we could see
> whether the elog had been issued from a signal handler, and if so what
> it had interrupted, we'd have an idea whether this is a known syslog
> deficiency or not.  Do you want to rebuild with debug symbols and try
> the backtrace again?

A minor ah-ha here: Whoever wrote the original Gentoo build for Postgres
left out --enable-debug, even though Gentoo has a system-wide flag for
"no, I don't want symbols" (which I did not set).

I was testing a different piece of my app at home, and triggered the
deadlock by accident. Being frustrated, I took the time to rebuild PG with
symbols, and also rebuilt Python (for other reasons), which accounts for
the RExec exception in the traceback here. The exception normally comes
back to the client with no problems. I had forgotten to comment out the
poison line in Python 2.2.3's RExec module so my plpython code would
continue working.

This is Postgresql 7.3.4 running against glibc 2.3.2. It just occured to
me that I didn't trace the postmaster or the other always-on processes,
just the two dead backends. In a couple of attempts to recreate the
problem again, I had no failures. :-( The original problem was on a
different machine running a different part of my project, and seemed more
reproducible, or I could have just had a bad day, so I can go back to that
at some point if tracing the other processes is a good idea.

postgres 27259  3.2  6.4 47488 20600 pts/0   S    03:30   0:05 postgres:
postgres Trucking [local] VACUUM
(gdb) bt
#0  0x4dbf81a7 in semop () from /lib/libc.so.6
#1  0x080f2dd7 in PGSemaphoreLock (sema=0x1, interruptOK=1 '\001') at
pg_sema.c:434
#2  0x08106dd3 in ProcWaitForSignal () at proc.c:895
#3  0x08101878 in LockBufferForCleanup (buffer=1021) at bufmgr.c:1946
#4  0x080c380b in lazy_vacuum_heap (onerel=0x420a20f8,
vacrelstats=0x8288f88) at vacuumlazy.c:474
#5  0x080c3476 in lazy_scan_heap (onerel=0x420a20f8,
vacrelstats=0x8288f88, Irel=0x8297818, nindexes=3) at vacuumlazy.c:426
#6  0x080c31e2 in lazy_vacuum_rel (onerel=0x21, vacstmt=0x1) at
vacuumlazy.c:158
#7  0x080c02ee in vacuum_rel (relid=1021, vacstmt=0x8287138,
expected_relkind=114 'r') at vacuum.c:829
#8  0x080bfd32 in vacuum (vacstmt=0x8287138) at vacuum.c:290
#9  0x0810a3a1 in pg_exec_query_string (query_string=0x8287138,
dest=Remote, parse_context=0x827bb30) at postgres.c:789
#10 0x0810afdf in PostgresMain (argc=4, argv=0xbfff7cc8,
username=0x822e1d9 "postgres") at postgres.c:2013
#11 0x080f5175 in DoBackend (port=0x822e0a8) at postmaster.c:2310
#12 0x080f4d2f in BackendStartup (port=0x822e0a8) at postmaster.c:1932
#13 0x080f3f95 in ServerLoop () at postmaster.c:1009
#14 0x080f3989 in PostmasterMain (argc=1, argv=0x82162e0) at postmaster.c:788
#15 0x080d684c in main (argc=1, argv=0xbfff85c4) at main.c:210
#16 0x4db327a7 in __libc_start_main () from /lib/libc.so.6

postgres 27235  5.7  3.0 41900 9784 pts/0    S    03:29   0:15 postgres:
award Trucking [local] INSERT
(gdb) bt
#0  0x4db45ed6 in sigsuspend () from /lib/libc.so.6
#1  0x4de40218 in __pthread_wait_for_restart_signal () from
/lib/libpthread.so.0
#2  0x4de419a0 in __pthread_alt_lock () from /lib/libpthread.so.0
#3  0x4de3ec17 in pthread_mutex_lock () from /lib/libpthread.so.0
#4  0x4dbf334c in vsyslog () from /lib/libc.so.6
#5  0x4dbf2ebf in syslog () from /lib/libc.so.6
#6  0x0814a49b in write_syslog (level=4,
    line=0xbfff70fc "ERROR:  plpython: Unable to create rexec.RExec
instance\nexceptions.RuntimeError: This code is not secure in Python
2.2 and 2.3") at elog.c:728
#7  0x08149bf9 in elog (lev=-1073779172, fmt=0x421a44fa "plpython:
%s\n%s") at elog.c:383
#8  0x4214b496 in PLy_elog (elevel=20, fmt=0x421a4a80 "Unable to create
rexec.RExec instance") at plpython.c:2811
#9  0x421490ff in PLy_procedure_compile (proc=0x83abdb8,
    src=0x8359610 "\n# TD[\"args\"][0] - audit_table (with schema) \n#
TD[\"relid\"] = OID of the table being triggered on\n\nif not
SD.has_key(\"plans\"):\n\tSD[\"plans\"] = {}\n\nif
SD[\"plans\"].has_key(TD[\"relid\"]):\n\tcachedPlans = SD"...)
    at plpython.c:1203
#10 0x42148f32 in PLy_procedure_create (fcinfo=0xbfff78c0, is_trigger=1
'\001', procTup=0x420b1910,
    key=0xbfff7730 "5210458_trigger") at plpython.c:1177
#11 0x42148ba8 in PLy_procedure_get (fcinfo=0xbfff78c0, is_trigger=1
'\001') at plpython.c:1043
#12 0x4214758e in plpython_call_handler (fcinfo=0xbfff78c0) at plpython.c:423
#13 0x0814b4cc in fmgr_security_definer (fcinfo=0xbfff78c0) at fmgr.c:681
#14 0x080bbb8f in ExecCallTriggerFunc (trigdata=0xbfff79e8,
finfo=0x82aff98, per_tuple_context=0x827c9d0) at trigger.c:1121
#15 0x080bc39a in DeferredTriggerExecute (event=0x82c2ba8, itemno=-4,
rel=0x4f815b, trigdesc=0x828bff8, finfo=0x82afcf0,
    per_tuple_context=0x827c9d0) at trigger.c:1656
#16 0x080bc685 in deferredTriggerInvokeEvents (immediate_only=1 '\001') at
trigger.c:1804
#17 0x080bc7fb in DeferredTriggerEndQuery () at trigger.c:1964
#18 0x0810a4c7 in finish_xact_command (forceCommit=0 '\0') at postgres.c:970
#19 0x0810a287 in pg_exec_query_string (query_string=0xbfff7aac,
dest=Remote, parse_context=0x827bb30) at postgres.c:897
#20 0x0810afdf in PostgresMain (argc=4, argv=0xbfff7cc8,
username=0x822e1d9 "award") at postgres.c:2013
#21 0x080f5175 in DoBackend (port=0x822e0a8) at postmaster.c:2310
#22 0x080f4d2f in BackendStartup (port=0x822e0a8) at postmaster.c:1932
#23 0x080f3f95 in ServerLoop () at postmaster.c:1009
#24 0x080f3989 in PostmasterMain (argc=1, argv=0x82162e0) at postmaster.c:788
#25 0x080d684c in main (argc=1, argv=0xbfff85c4) at main.c:210
#26 0x4db327a7 in __libc_start_main () from /lib/libc.so.6