[Zope] DeadlockDebugger revisited
Matthew X. Economou
xenophon at irtnog.org
Fri Jun 16 09:10:33 EDT 2006
I thought a recent operating system upgrade (FreeBSD 5.4 to 6.1) fixed
my problems with Zope. Unfortunately, once I re-compiled Python et al
(to remove dependencies on the old libraries), my problems with Zope
deadlocking recurred. I tried to use a combination of tools to try to
discover the root cause of this problem, but nothing seems to work.
What am I missing, and what else can I try?
This system is:
Nokia IP440 (Pentium II-333MHz, 256 MB RAM)
FreeBSD 6.1-RELEASE-p1
Python 2.3.5
Zope 2.8.6
Plone 2.1.2
Trace and event logs:
I set up the trace log to save all messages, and the last few lines of
the access, event, and trace logs are:
Z2.log:
127.0.0.1 - Anonymous [15/Jun/2006:22:52:54 -0400] "GET
/VirtualHostBase/http/web.irtnog.org:80/irtnog/VirtualHostRoot/irtnog/he
lpcenter_icon.gif HTTP/1.1" 200 1322
"http://web.irtnog.org/howtos-orig/freebsd-pf-pppoe" "Mozilla/4.0
(compatible; MSIE 6.0; Windows NT 5.1; SV1; .NET CLR 1.1.4322)"
event.log:
2006-06-15T22:40:28 INFO Plone Debug Error exceptions.AttributeError on
getBeginAndEndTimes while rendering portlet
here/portlet_simpleblog/macros/portletBlogFull_local
trace.log:
B 221198124 2006-06-15T22:52:54 GET
/VirtualHostBase/http/web.irtnog.org:80/irtnog/VirtualHostRoot/Members/x
enophon/photos/washdc-jan-2006/photoalbum_view?b_start:int=20
I 221198124 2006-06-15T22:52:54 0
DeadlockDebugger + threadframe:
Once the Zope process deadlocks, it ceases to respond on port 8080 (the
configured listener port). Thus it is not possible to obtain a thread
dump from Zope using this package.
Lsof:
I checked the list of open files on the Zope process but didn't see
anything out of the ordinary (attached as "zope-lsof.txt")
Strace/Truss/Ktrace:
I traced the process using ktrace, dumped it with "kdump -H" to get
thread IDs, and got the following information:
7505 100075 python2.3 PSIG SIGSEGV SIG_DFL
7505 100075 python2.3 PSIG SIGSEGV SIG_DFL
7505 100075 python2.3 PSIG SIGSEGV SIG_DFL
7505 100075 python2.3 PSIG SIGSEGV SIG_DFL
7505 100075 python2.3 PSIG SIGSEGV SIG_DFL
7505 100075 python2.3 PSIG SIGSEGV SIG_DFL
7505 100075 python2.3 PSIG SIGSEGV SIG_DFL
7505 100075 python2.3 PSIG SIGSEGV SIG_DFL
7505 100075 python2.3 PSIG SIGSEGV SIG_DFL
7505 100075 python2.3 PSIG SIGSEGV SIG_DFL
I traced the process using truss and got the following information:
SIGNAL 11 (SIGSEGV)
SIGNAL 11 (SIGSEGV)
SIGNAL 11 (SIGSEGV)
SIGNAL 11 (SIGSEGV)
SIGNAL 11 (SIGSEGV)
SIGNAL 11 (SIGSEGV)
Strace showed the same information:
--- SIGSEGV (Segmentation fault: 11) ---
--- SIGSEGV (Segmentation fault: 11) ---
--- SIGSEGV (Segmentation fault: 11) ---
--- SIGSEGV (Segmentation fault: 11) ---
--- SIGSEGV (Segmentation fault: 11) ---
--- SIGSEGV (Segmentation fault: 11) ---
--- SIGSEGV (Segmentation fault: 11) ---
--- SIGSEGV (Segmentation fault: 11) ---
GDB + attach + info threads
(https://engineering.purdue.edu/ECN/Resources/KnowledgeBase/Docs/2006051
8104722):
The faulting thread seems to be in the middle of pthread_mutexattr_init.
(gdb) info threads
* 7 LWP 100075 0x2820e5c2 in pthread_mutexattr_init () from
/usr/lib/libpthread.so.2
6 Thread 0x8111000 (sleeping) 0x2820df0f in pthread_mutexattr_init ()
from /usr/lib/libpthread.so.2
5 Thread 0xa318a00 (LWP 100062) 0x2821546b in pthread_testcancel ()
from /usr/lib/libpthread.so.2
4 Thread 0x991ac00 (runnable) 0x00000000 in ?? ()
3 Thread 0x9062400 (runnable) 0x0cea3a2c in ?? ()
2 Thread 0x9a37a00 (sleeping) 0x2820df0f in pthread_mutexattr_init ()
from /usr/lib/libpthread.so.2
1 Thread 0x9a35800 (sleeping) 0x2820df0f in pthread_mutexattr_init ()
from /usr/lib/libpthread.so.2
None of the threads are in the sigsuspend, poll, select, or kill state,
although it's possible that the sleeping state is equivalent to
sigsuspend. At a whim, I tried stepping into the process, but this
didn't do anything other than show the SEGV on the console.
(gdb) call PyRun_SimpleString("import string,sys,os,ZServer;
sys.stdout=open('/tmp/urls','w',0); print string.join(map(lambda
a:str(getattr(a,'env',{}).get('PATH_INFO','')),
sys.modules['asyncore'].socket_map.values()), '\\n')")
Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x9062400 (LWP 100075)]
0x0cea3a2c in ?? ()
The program being debugged was signaled while in a function called from
GDB.
And:
(gdb) call PyRun_SimpleString("import sys,
traceback;sys.stderr=open('/tmp/tb','w',0); traceback.print_stack()")
[Switching to Thread 0x9062400 (LWP 100114)]
Cannot set lwp 100114 registers: Invalid argument
Cannot set lwp 100114 registers: Invalid argument
--
jsoffron: I'm generally pretty high on national defense...
Mr. Bad Example: Careful...it's a gateway policy. Before you know it,
you'll be mainlining the hard stuff like trade agreements.
jsoffron: Too late...I've been freebasing Nafta all day... Sweet,
sweet NAFTA.
- As seen on Slashdot
-------------- next part --------------
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
python2.3 7505 zope cwd VDIR 0,93 512 94208 /var/www/zope
python2.3 7505 zope rtd VDIR 0,87 512 2 /
python2.3 7505 zope txt VREG 0,92 771932 28649 /usr/local/bin/python2.3
python2.3 7505 zope txt VREG 0,87 136992 16724 /libexec/ld-elf.so.1
python2.3 7505 zope txt VREG 0,87 43576 16707 /lib/libutil.so.5
python2.3 7505 zope txt VREG 0,92 803288 315076 /usr/lib/libstdc++.so.5
python2.3 7505 zope txt VREG 0,87 98120 16703 /lib/libm.so.4
python2.3 7505 zope txt VREG 0,92 140200 315063 /usr/lib/libpthread.so.2
python2.3 7505 zope txt VREG 0,87 882116 16712 /lib/libc.so.6
python2.3 7505 zope txt VREG 0,92 18815 123975 /usr/local/lib/python2.3/lib-dynload/time.so
python2.3 7505 zope txt VREG 0,92 25480 123972 /usr/local/lib/python2.3/lib-dynload/strop.so
python2.3 7505 zope txt VREG 0,92 17182 124000 /usr/local/lib/python2.3/lib-dynload/cStringIO.so
python2.3 7505 zope txt VREG 0,92 47903 124031 /usr/local/lib/python2.3/lib-dynload/_socket.so
python2.3 7505 zope txt VREG 0,92 19656 124032 /usr/local/lib/python2.3/lib-dynload/_ssl.so
python2.3 7505 zope txt VREG 0,92 184752 315088 /usr/lib/libssl.so.4
python2.3 7505 zope txt VREG 0,87 995056 16655 /lib/libcrypto.so.4
python2.3 7505 zope txt VREG 0,92 19939 123996 /usr/local/lib/python2.3/lib-dynload/binascii.so
python2.3 7505 zope txt VREG 0,92 16626 123970 /usr/local/lib/python2.3/lib-dynload/math.so
python2.3 7505 zope txt VREG 0,92 11648 123977 /usr/local/lib/python2.3/lib-dynload/_random.so
python2.3 7505 zope txt VREG 0,92 15970 123990 /usr/local/lib/python2.3/lib-dynload/fcntl.so
python2.3 7505 zope txt VREG 0,92 14427 123994 /usr/local/lib/python2.3/lib-dynload/md5.so
python2.3 7505 zope txt VREG 0,92 13476 123995 /usr/local/lib/python2.3/lib-dynload/sha.so
python2.3 7505 zope txt VREG 0,92 55837 123976 /usr/local/lib/python2.3/lib-dynload/datetime.so
python2.3 7505 zope txt VREG 0,92 74327 124003 /usr/local/lib/python2.3/lib-dynload/cPickle.so
python2.3 7505 zope txt VREG 0,92 22178 123950 /usr/local/lib/python2.3/lib-dynload/struct.so
python2.3 7505 zope txt VREG 0,92 186006 124042 /usr/local/lib/python2.3/lib-dynload/pyexpat.so
python2.3 7505 zope txt VREG 0,92 8450 123966 /usr/local/lib/python2.3/lib-dynload/_weakref.so
python2.3 7505 zope txt VREG 0,92 25432 247701 /usr/local/www/Zope28/lib/python/persistent/cPersistence.so
python2.3 7505 zope txt VREG 0,92 10999 247703 /usr/local/www/Zope28/lib/python/persistent/TimeStamp.so
python2.3 7505 zope txt VREG 0,92 18594 247702 /usr/local/www/Zope28/lib/python/persistent/cPickleCache.so
python2.3 7505 zope txt VREG 0,92 12595 246516 /usr/local/www/Zope28/lib/python/zope/interface/_zope_interface_coptimizations.so
python2.3 7505 zope txt VREG 0,92 6715 223388 /usr/local/www/Zope28/lib/python/Products/ZCTextIndex/okascore.so
python2.3 7505 zope txt VREG 0,92 15740 123993 /usr/local/lib/python2.3/lib-dynload/select.so
python2.3 7505 zope txt VREG 0,92 20905 124040 /usr/local/lib/python2.3/lib-dynload/zlib.so
python2.3 7505 zope txt VREG 0,87 60672 16723 /lib/libz.so.3
python2.3 7505 zope txt VREG 0,92 19551 123979 /usr/local/lib/python2.3/lib-dynload/operator.so
python2.3 7505 zope txt VREG 0,92 25254 248028 /usr/local/www/Zope28/lib/python/ExtensionClass/_ExtensionClass.so
python2.3 7505 zope txt VREG 0,92 29954 247113 /usr/local/www/Zope28/lib/python/AccessControl/cAccessControl.so
python2.3 7505 zope txt VREG 0,92 30093 246947 /usr/local/www/Zope28/lib/python/Acquisition/_Acquisition.so
python2.3 7505 zope txt VREG 0,92 12449 247661 /usr/local/www/Zope28/lib/python/Record/_Record.so
python2.3 7505 zope txt VREG 0,92 42040 123997 /usr/local/lib/python2.3/lib-dynload/parser.so
python2.3 7505 zope txt VREG 0,92 24445 247275 /usr/local/www/Zope28/lib/python/DocumentTemplate/cDocumentTemplate.so
python2.3 7505 zope txt VREG 0,92 61071 247898 /usr/local/www/Zope28/lib/python/BTrees/_OOBTree.so
python2.3 7505 zope txt VREG 0,92 61767 247899 /usr/local/www/Zope28/lib/python/BTrees/_OIBTree.so
python2.3 7505 zope txt VREG 0,92 64481 247901 /usr/local/www/Zope28/lib/python/BTrees/_IOBTree.so
python2.3 7505 zope txt VREG 0,92 64949 247900 /usr/local/www/Zope28/lib/python/BTrees/_IIBTree.so
python2.3 7505 zope txt VREG 0,92 7101 247709 /usr/local/www/Zope28/lib/python/ComputedAttribute/_ComputedAttribute.so
python2.3 7505 zope txt VREG 0,92 7237 247057 /usr/local/www/Zope28/lib/python/Persistence/_Persistence.so
python2.3 7505 zope txt VREG 0,92 6301 247682 /usr/local/www/Zope28/lib/python/MethodObject/_MethodObject.so
python2.3 7505 zope txt VREG 0,92 16560 123984 /usr/local/lib/python2.3/lib-dynload/_locale.so
python2.3 7505 zope txt VREG 0,92 18232 27499 /usr/local/lib/nss_winbind.so.1
python2.3 7505 zope txt VREG 0,92 5571 124029 /usr/local/lib/python2.3/lib-dynload/crypt.so
python2.3 7505 zope txt VREG 0,87 28680 16700 /lib/libcrypt.so.3
python2.3 7505 zope txt VREG 0,92 9549 123991 /usr/local/lib/python2.3/lib-dynload/pwd.so
python2.3 7505 zope txt VREG 0,92 5465 223608 /usr/local/www/Zope28/lib/python/initgroups.so
python2.3 7505 zope txt VREG 0,92 24535 123978 /usr/local/lib/python2.3/lib-dynload/itertools.so
python2.3 7505 zope txt VREG 0,92 8803 247552 /usr/local/www/Zope28/lib/python/Missing/_Missing.so
python2.3 7505 zope txt VREG 0,92 9358 247877 /usr/local/www/Zope28/lib/python/MultiMapping/_MultiMapping.so
python2.3 7505 zope txt VREG 0,92 6223 223387 /usr/local/www/Zope28/lib/python/Products/ZCTextIndex/stopper.so
python2.3 7505 zope txt VREG 0,92 8937 246753 /usr/local/www/Zope28/lib/python/zope/thread/_zope_thread.so
python2.3 7505 zope txt VREG 0,92 34823 123968 /usr/local/lib/python2.3/lib-dynload/array.so
python2.3 7505 zope txt VREG 0,92 221446 100561 /usr/local/lib/python2.3/site-packages/PIL/_imaging.so
python2.3 7505 zope txt VREG 0,92 132986 27216 /usr/local/lib/libjpeg.so.9
python2.3 7505 zope txt VREG 0,92 10218 246877 /usr/local/www/Zope28/lib/python/ThreadLock/_ThreadLock.so
python2.3 7505 zope txt VREG 0,92 6456 25359 /usr/local/lib/python2.3/site-packages/threadframe.so
python2.3 7505 zope txt VREG 0,92 27054 246694 /usr/local/www/Zope28/lib/python/zope/proxy/_zope_proxy_proxy.so
python2.3 7505 zope txt VREG 0,92 29174 246439 /usr/local/www/Zope28/lib/python/zope/security/_proxy.so
python2.3 7505 zope txt VREG 0,92 13999 246440 /usr/local/www/Zope28/lib/python/zope/security/_zope_security_checker.so
python2.3 7505 zope txt VREG 0,92 8239 246730 /usr/local/www/Zope28/lib/python/zope/hookable/_zope_hookable.so
python2.3 7505 zope txt VREG 0,92 9298 123992 /usr/local/lib/python2.3/lib-dynload/grp.so
python2.3 7505 zope txt VREG 0,92 32057 245630 /usr/local/www/Zope28/lib/python/zope/app/container/_zope_app_container_contained.so
python2.3 7505 zope txt VREG 0,92 53270 25428 /usr/local/lib/python2.3/site-packages/_ldap.so
python2.3 7505 zope txt VREG 0,92 221441 27416 /usr/local/lib/libldap_r-2.2.so.7
python2.3 7505 zope txt VREG 0,92 55824 27324 /usr/local/lib/liblber-2.2.so.7
python2.3 7505 zope txt VREG 0,92 401051 123981 /usr/local/lib/python2.3/lib-dynload/unicodedata.so
python2.3 7505 zope 0r VCHR 0,23 0t0 23 /dev/null
python2.3 7505 zope 1w VCHR 0,23 0t0 23 /dev/null
python2.3 7505 zope 2w VCHR 0,23 0t0 23 /dev/null
python2.3 7505 zope 3u IPv4 0xc2a76000 0t0 TCP *:8080 (LISTEN)
python2.3 7505 zope 4u IPv4 0xc2ab01d0 0t0 TCP localhost:1980 (LISTEN)
python2.3 7505 zope 5wW VREG 0,93 4 94455 /var/www/zope/var/Z2.lock
python2.3 7505 zope 6u unix 0xc2ac742c 0t0 ->0xc23989bc
python2.3 7505 zope 7u VREG 0,91 289849 102 /tmp (/dev/ad0s1e)
python2.3 7505 zope 8u PIPE 0xc237b660 16384 ->0xc237b718
python2.3 7505 zope 9u PIPE 0xc237b718 0 ->0xc237b660
python2.3 7505 zope 10u VREG 0,93 20971520 97339 /var/www/zope/var/cinep011fbvoip-1.zec
python2.3 7505 zope 11u IPv4 0xc2041ae0 0t0 TCP localhost:50905->localhost:8100 (ESTABLISHED)
python2.3 7505 zope 12u IPv4 0t0 TCP no PCB, CANTSENDMORE, CANTRCVMORE
python2.3 7505 zope 13u IPv4 0t0 TCP no PCB, CANTSENDMORE, CANTRCVMORE
python2.3 7505 zope 14u IPv4 0t0 TCP no PCB, CANTSENDMORE, CANTRCVMORE
python2.3 7505 zope 22w VREG 0,93 14821106 94228 /var/www/zope/log/event.log
python2.3 7505 zope 23w VREG 0,93 11478968 94219 /var/www/zope/log/Z2.log
python2.3 7505 zope 24w VREG 0,93 20896 94640 /var/www/zope/log/trace.log
More information about the Zope
mailing list