Improved logging of ZEO reads and writes

Bug #424172 reported by Andreas Jung
12
This bug affects 2 people
Affects Status Importance Assigned to Milestone
ZODB
New
Wishlist
Unassigned

Bug Description

In a large-scale ZEO setup like we have it at Haufe, it is hard to track down what's going on ZEO level - especially when you have
to track down conflict errors, transaction write congestion etc.

The attached version of ZEO/ServerStub.py adds additional logging to the ZEO client. The logging can be controlled for reads and
write using the ZEO_LOG_CLIENT_READ and ZEO_LOG_CLIENT-WRITE environment variables.

The related logs lock like this:

2009-09-04 08:38:38 INFO ZeoServerStub-write tpc_begin: tid=None descr='/manage_delObjects' time=0.887ms
2009-09-04 08:38:38 INFO ZeoServerStub-write storea: oid='\x00\x00\x00\x00\x00\x00\x00\x01' class=<class 'OFS.Application.Application'> size=1239
2009-09-04 08:38:38 INFO ZeoServerStub-write vote: tid=37611344 time=39.543ms
2009-09-04 08:38:38 INFO ZeoServerStub-write tpc_finish: tid=37611344 time=95.546ms

2009-09-04 08:38:37 INFO ZeoServerStub-read loadEx: oid='\x00\x00\x00\x00\x00\x00\t\x1c' class=<class 'HelpSys.APIHelpTopic.APIHelpTopic'> size=155 time=0.779ms
2009-09-04 08:38:37 INFO ZeoServerStub-read loadEx: oid='\x00\x00\x00\x00\x00\x00\t\x1d' class=<class 'HelpSys.HelpTopic.STXTopic'> size=1133 time=0.730ms
2009-09-04 08:38:37 INFO ZeoServerStub-read loadEx: oid='\x00\x00\x00\x00\x00\x00\t\x1e' class=<class 'HelpSys.HelpTopic.STXTopic'> size=1877 time=0.738ms
2009-09-04 08:38:37 INFO ZeoServerStub-read loadEx: oid='\x00\x00\x00\x00\x00\x00\t\x1f' class=<class 'Products.ZCatalog.ZCatalog.ZCatalog'> size=170 time=0.647ms
2009-09-04 08:38:37 INFO ZeoServerStub-read loadEx: oid='\x00\x00\x00\x00\x00\x00\t ' class=<class 'HelpSys.HelpTopic.STXTopic'> size=1779 time=0.644ms
2009-09-04 08:38:37 INFO ZeoServerStub-read loadEx: oid='\x00\x00\x00\x00\x00\x00\t!' class=<class 'HelpSys.HelpTopic.STXTopic'> size=842 time=0.633ms
2009-09-04 08:38:37 INFO ZeoServerStub-read loadEx: oid='\x00\x00\x00\x00\x00\x00\t"' class=<class 'HelpSys.HelpTopic.STXTopic'> size=1841 time=0.983ms
2009-09-04 08:38:37 INFO ZeoServerStub-read loadEx: oid='\x00\x00\x00\x00\x00\x00\x00\n' class=***exception*** size=29 time=0.721ms

There is likely a performance impact but the logging should be used for debugging and performance analysis only

Revision history for this message
Andreas Jung (ajung) wrote :
Changed in zodb:
importance: Undecided → Wishlist
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.