[ZODB-Dev] ZEO overhead?

[Neil Schemenauer]

Loading one our complicated pages (with an empty ZODB cache) takes 7.7
seconds using filestorage directly and 35 seconds using ZEO.  That seems
like a lot of overhead for ZEO.  The client side profile with ZEO looks
like this:

   Ordered by: cumulative time
   List reduced from 289 to 20 due to restriction <20>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000   36.032   36.032 ...
        1    0.000    0.000   36.031   36.031 ...
        1    0.000    0.000   36.031   36.031 ...
        1    0.000    0.000   36.031   36.031 ...
        1    0.000    0.000   36.020   36.020 ...
        1    0.000    0.000   35.917   35.917 ...
        2    0.000    0.000   34.637   17.318 ...
       14    0.000    0.000   34.637    2.474 ...
     5755    1.157    0.000   34.274    0.006 Connection.py:554(setstate)
     5755    0.251    0.000   29.480    0.005 ClientStorage.py:698(load)
     5755    0.050    0.000   26.401    0.005 ServerStub.py:77(zeoLoad)
     5755    0.110    0.000   26.351    0.005 connection.py:359(call)
     5755    0.994    0.000   24.061    0.004 connection.py:437(wait)
    11564    2.659    0.000   20.256    0.002 asyncore.py:94(poll)
        1    0.000    0.000   15.976   15.976 ...
        1    0.035    0.035   15.928   15.928 ...
        1    0.033    0.033   14.793   14.793 ...
     5755    0.041    0.000   12.886    0.002 asyncore.py:75(write)
     5755    0.042    0.000   12.845    0.002 asyncore.py:389(handle_write_event)
     5755    0.250    0.000   12.803    0.002 smac.py:206(handle_write)


   Function                   was called by...
   asyncore.py:94(poll)       connection.py:437(wait)(11564)    24.061
   connection.py:437(wait)    connection.py:359(call)(5755)     26.351
   connection.py:359(call)    ServerStub.py:77(zeoLoad)(5755)   26.401
   ServerStub.py:77(zeoLoad)  ClientStorage.py:698(load)(5755)  29.480
   ClientStorage.py:698(load) Connection.py:554(setstate)(5755) 34.274

I did more profiling use 'oprofile' and also used hotshot on the ZEO
server.  It looks like a lot of time is spend polling the connection
between server and client.  I'm wondering if there is bug that causes
both the client and server to end up waiting for each other at certain
times.

I'm considering ripping the asyncore parts out of the ZEO client and
server, making them both synchronous, and seeing how much difference
that makes.  Does anyone have a better idea of how to track down this
problem (if it is indeed a problem at all)?

  Neil