[ZODB-Dev] Tracking down a freeze (deadlock?)

Mon Feb 21 10:14:41 EST 2005

Hi all,

I'm trying to track down what looks to me like a deadlock, using Zope 
2.7.4. We're using ZEO, on single processor machines. The ZEO client is 
configured for 4 threads.

The freeze appears often but only on production servers (which doesn't 
help), the symptoms are that suddenly Zope stops responding to requests.

The trace.log which normally shows B/I/A/E phases for each request is 
stopping at B/I. I inserted some additional logging in 
ZServer.Publish.publish to try to find where everything was stopping. I 
added the following logs:

At the very beginning of the publish method:
     DebugLogger.log('P0', id(request), request['PATH_INFO'])
Just before request.traverse:
         DebugLogger.log('P1', id(request))
Just before mapply:
         DebugLogger.log('P2', id(request))
Just after mapply:
         DebugLogger.log('P3', id(request))
Just after transaction commit:
         DebugLogger.log('F', id(request))

When the freeze occurs, the logs show the following patterns. Two 
requests are started nearly simultaneously (the logs are interleaved). 
The first one logs up to P1. The second one logs up to P3. Two further 
requests log up to P1. Then nothing logs further than I, because the 
thread pool is exhausted.

This still leaves a wide field to explore, and I'd like to hear 
suggestions of where to put additional logging to get further.

Thanks,

Florent

Here are 3 example of logs (note, the id(request) in publish is not the 
same as those for B/I/A/E phases, the last part of the P0 line is used 
to match requests). *** and @@@ parts are notes added by hand.

TRACE 1 (10:39)
---------------

B 1313501164 2005-02-21T10:39:49 GET publication_change
I 1313501164 2005-02-21T10:39:49 0
P0 1257832780 2005-02-21T10:39:49 publication_change
P1 1257832780 2005-02-21T10:39:49
P2 1257832780 2005-02-21T10:39:49

B 1313997100 2005-02-21T10:39:50 GET /sites/marine/
I 1313997100 2005-02-21T10:39:50 0
P0 1313997260 2005-02-21T10:39:50 /sites/marine/
P1 1313997260 2005-02-21T10:39:50 *********** last /sites/marine/
P3 1257832780 2005-02-21T10:39:50 @@@@@@@@@@@ last publication_change

B 1301579308 2005-02-21T10:41:06 GET /sites/marine/base/view
I 1301579308 2005-02-21T10:41:06 0
P0 1279924204 2005-02-21T10:41:06 /sites/marine/base/view
P1 1279924204 2005-02-21T10:41:06 *********** last /sites/marine/base/view

B 1301578732 2005-02-21T10:41:07 GET /sites/marine/base/view
I 1301578732 2005-02-21T10:41:07 0
P0 1301471820 2005-02-21T10:41:07 /sites/marine/base/view
P1 1301471820 2005-02-21T10:41:07 *********** last /sites/marine/base/view

TRACE 2 (11:07)
---------------

B 1218610316 2005-02-21T11:07:20 GET /workspaces
I 1218610316 2005-02-21T11:07:20 0
P0 1166158060 2005-02-21T11:07:20 /workspaces
P1 1166158060 2005-02-21T11:07:20
P2 1166158060 2005-02-21T11:07:20

B 1133974636 2005-02-21T11:07:20 GET /misc_/CMFDefault/portal.gif
I 1133974636 2005-02-21T11:07:20 0

B 1220321516 2005-02-21T11:07:20 GET /misc_/Localizer/localizer.gif
I 1220321516 2005-02-21T11:07:20 0
P0 1220321452 2005-02-21T11:07:20 /misc_/CMFDefault/portal.gif
P1 1220321452 2005-02-21T11:07:20
P0 1220322924 2005-02-21T11:07:20 /misc_/Localizer/localizer.gif
P2 1220321452 2005-02-21T11:07:20
P1 1220322924 2005-02-21T11:07:20 ********* last 
/misc_/Localizer/localizer.gif
P3 1220321452 2005-02-21T11:07:20
F 1220321452 2005-02-21T11:07:20 @@@@@@@@ last /misc_/CMFDefault/portal.gif

B 1156696684 2005-02-21T11:07:20 GET /UserFolder_icon.gif
I 1156696684 2005-02-21T11:07:20 0
P3 1166158060 2005-02-21T11:07:20
F 1166158060 2005-02-21T11:07:20 @@@@@@@@@ last /workspaces

B 1220264364 2005-02-21T11:07:21 GET /stylesheet_print.css
I 1220264364 2005-02-21T11:07:21 0
P0 1133970988 2005-02-21T11:07:21 /stylesheet_print.css
P1 1133970988 2005-02-21T11:07:21 ********* last /stylesheet_print.css

TRACE 3 (11:31)
---------------

B 1165903020 2005-02-21T11:31:31 GET /dicod/marine/bandeau.jpg
I 1165903020 2005-02-21T11:31:31 0
P0 1173903244 2005-02-21T11:31:31 /dicod/marine/bandeau.jpg
P1 1173903244 2005-02-21T11:31:31

B 1146954892 2005-02-21T11:31:31 GET /portal_stylesheet.css
I 1146954892 2005-02-21T11:31:31 0
P0 1173844748 2005-02-21T11:31:31 /portal_stylesheet.css
P1 1173844748 2005-02-21T11:31:31 ******* last /portal_stylesheet.css
P2 1173903244 2005-02-21T11:31:31
P3 1173903244 2005-02-21T11:31:31
F 1173903244 2005-02-21T11:31:31 @@@@@@@ last /dicod/marine/bandeau.jpg

B 1168012460 2005-02-21T11:31:31 GET /stylesheet_generic.css
I 1168012460 2005-02-21T11:31:31 0
P0 1121806540 2005-02-21T11:31:31 /stylesheet_generic.css
P1 1121806540 2005-02-21T11:31:31 ******* last /stylesheet_generic.css

B 1142382092 2005-02-21T11:31:31 GET /stylesheet_marine.css
I 1142382092 2005-02-21T11:31:31 0
P0 1121807660 2005-02-21T11:31:31 /stylesheet_marine.css
P1 1121807660 2005-02-21T11:

-- 
Florent Guillaume, Nuxeo (Paris, France)   CTO, Director of R&D
+33 1 40 33 71 59   http://nuxeo.com   fg at nuxeo.com