[Zope] CST 0.9 Problems under load?

[Tim Hicks]

Zopers and Chris,

I have written a little zope app that allows people to search an oracle
database thru-the-web.  Relevant details:

Zope 2.3.3
Win NT
DC Oracle 1
CST 0.9 - used in just about every request as it provided shopping basket
functionality
Session timeout set to 20 mins
Using ZServer (i.e. no apache/squid in front)
P2 450MHz
Can't remember how much RAM, but we didn't use it all.
[From Analog]
Day:  reqs:  pages:
Wed: 133586:  2458:
Thu:  48310:   831:
Fri:  24890:   438:

We launched the site last Wednesday (10am), and the little box it was
running on was a bit overwhelmed.  We started to see KeyErrors relating to
the session data manager (more on that below), so backed off to an earlier
search app that had no CST component.  CPU had been running at 100% almost
solidly for about half an hour, but we still had half our RAM free.  At this
stage, we weren't logging the errors.
After the load died down a bit (the first hour was far and away the worst),
we switched back to the CST'ified app.  Server load was lower, and although
we still weren't logging, we got the impression that the errors had gone.
Sadly, the KeyErrors were spotted again.  At this point, I setup
standard_error_message to email me with the REQUEST and traceback whenever
it caught a KeyError.  That began at 5pm Wednesday.  From then until 1pm
Friday, I received 174 error messages of the following form:

-----
<snipped REQUEST>
Traceback (innermost last):
  File C:\PROGRA~1\zope233\lib\python\ZPublisher\Publish.py, line 171, in
publish
  File C:\PROGRA~1\zope233\lib\python\ZPublisher\mapply.py, line 160, in
mapply
    (Object: results)
  File C:\PROGRA~1\zope233\lib\python\ZPublisher\Publish.py, line 112, in
call_object
    (Object: results)
  File C:\PROGRA~1\zope233\lib\python\OFS\DTMLMethod.py, line 189, in
__call__
    (Object: results)
  File C:\PROGRA~1\zope233\lib\python\DocumentTemplate\DT_String.py, line
540, in __call__
    (Object: results)
  File C:\PROGRA~1\zope233\lib\python\OFS\DTMLMethod.py, line 182, in
__call__
    (Object: standard_html_header)
  File C:\PROGRA~1\zope233\lib\python\DocumentTemplate\DT_String.py, line
540, in __call__
    (Object: standard_html_header)
  File C:\PROGRA~1\zope233\lib\python\DocumentTemplate\DT_Util.py, line 339,
in eval
    (Object: sdm.getSessionData().has_key('your_results'))
    (Info: sdm)
  File <string>, line 0, in ?
  File
C:\PROGRA~1\zope233\lib\python\Products\CoreSessionTracking\SessionDataManag
er.py, line 264, in getSessionData
    (Object: sdm)
  File
C:\PROGRA~1\zope233\lib\python\Products\CoreSessionTracking\SessionDataManag
er.py, line 375, in _createSessionDataObject
    (Object: sdm)
  File
C:\PROGRA~1\zope233\lib\python\Products\CoreSessionTracking\SessionDataConta
iner.py, line 191, in set
    (Object: /accom2/search/sdm)
  File
C:\PROGRA~1\zope233\lib\python\Products\CoreSessionTracking\SessionDataConta
iner.py, line 344, in __setitem__
    (Object: /accom2/search/sdm)
KeyError: 64396498A0K2Wz9uuoA
-----
As far as I can tell, the only difference between each of the 174 errors is
a different key value (corresponding to different sessions I presume).

I also received 4 of this sort:

-----
Traceback (innermost last):
  File C:\PROGRA~1\zope233\lib\python\ZPublisher\Publish.py, line 171, in
publish
  File C:\PROGRA~1\zope233\lib\python\ZPublisher\mapply.py, line 160, in
mapply
    (Object: results)
  File C:\PROGRA~1\zope233\lib\python\ZPublisher\Publish.py, line 112, in
call_object
    (Object: results)
  File C:\PROGRA~1\zope233\lib\python\OFS\DTMLMethod.py, line 189, in
__call__
    (Object: results)
  File C:\PROGRA~1\zope233\lib\python\DocumentTemplate\DT_String.py, line
540, in __call__
    (Object: results)
  File C:\PROGRA~1\zope233\lib\python\OFS\DTMLMethod.py, line 182, in
__call__
    (Object: standard_html_header)
  File C:\PROGRA~1\zope233\lib\python\DocumentTemplate\DT_String.py, line
540, in __call__
    (Object: standard_html_header)
  File C:\PROGRA~1\zope233\lib\python\DocumentTemplate\DT_Util.py, line 339,
in eval
    (Object: sdm.getSessionData().has_key('your_results'))
    (Info: sdm)
  File <string>, line 0, in ?
  File
C:\PROGRA~1\zope233\lib\python\Products\CoreSessionTracking\SessionDataManag
er.py, line 258, in getSessionData
    (Object: sdm)
  File
C:\PROGRA~1\zope233\lib\python\Products\CoreSessionTracking\SessionDataManag
er.py, line 390, in _getSessionDataObject
    (Object: sdm)
  File C:\PROGRA~1\zope233\lib\python\ZODB\Connection.py, line 508, in
setstate
  File
C:\PROGRA~1\zope233\lib\python\Products\CoreSessionTracking\SessionStorage.p
y, line 156, in load
    (Object: SessionStorage)
KeyError:
-----
<No key value given!?>

As I said, the relevant REQUEST objects for each of these errors if they can
help shed any light on the problems I'm seeing... just ask.

In addition, I also managed to salvage this traceback from about 10.15am on
Wednesday, when the CST site was getting hammered.  I only saw it once, but
wasn't logging at that stage...

-----
Error Type: TypeError
Error Value: function requires exactly 1 argument; 2 given

Traceback (innermost last):
  File C:\PROGRA~1\zope233\lib\python\ZPublisher\Publish.py, line 223, in
publish_module
  File C:\PROGRA~1\zope233\lib\python\ZPublisher\Publish.py, line 187, in
publish
  File C:\PROGRA~1\zope233\lib\python\Zope\__init__.py, line 221, in
zpublisher_exception_hook
    (Object: Traversable)
  File C:\PROGRA~1\zope233\lib\python\ZPublisher\Publish.py, line 175, in
publish
  File C:\PROGRA~1\zope233\lib\python\Zope\__init__.py, line 235, in commit
  File C:\PROGRA~1\zope233\lib\python\ZODB\Transaction.py, line 300, in
commit
  File C:\PROGRA~1\zope233\lib\python\ZODB\Connection.py, line 377, in
commit
    (Info: (('BTrees.OOBTree', 'OOBTree'),
'\000\000\000\000\000\000\000\020', ''))
  File
C:\PROGRA~1\zope233\lib\python\Products\CoreSessionTracking\SessionStorage.p
y, line 182, in store
    (Object: SessionStorage)
  File C:\PROGRA~1\zope233\lib\python\ZODB\ConflictResolution.py, line 177,
in tryToResolveConflict
    (Object: SessionStorage)
TypeError: (see above)
-----

I don't really no how to try to reproduce these errors short of getting a
few thousand people to access the site at the same time again.  The CST site
is still up and in use under much lighter load.  I haven't received any of
these errors since Friday lunch time, so it really does seem to be a load
issue.

I don't have much Zen, so to me it looks like the first error is CST not
being able to find (losing?) some session information.  The second one is a
bit of a mystery to me, and the third looks like it might just be a bug in
the way the CST code calls ConflictResolution.<some
class>.tryToResolveConflict()

I'd really appreciate any enlightenment anyone could give about these
errors, and how to fix them.

cheers

tim