Improved logging of ZEO reads and writes

Bug #424172 reported by Andreas Jung on 2009-09-04
12
This bug affects 2 people
Affects Status Importance Assigned to Milestone
ZODB
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

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

Other bug subscribers

Bug attachments