[Zodb-checkins] CVS: StandaloneZODB/ZEO - StorageServer.py:1.34.2.4

Jeremy Hylton jeremy@zope.com
Fri, 15 Mar 2002 02:30:42 -0500


Update of /cvs-repository/StandaloneZODB/ZEO
In directory cvs.zope.org:/tmp/cvs-serv29726

Modified Files:
      Tag: zeo-1_0-debug-branch
	StorageServer.py 
Log Message:
Extend status() with last method status and asyncore status.

For each active connection, log the last method that was invoked,
the time it was invoked, and the time it returned.

Also, log whether asyncore thinks the connection is readable or
writable.




=== StandaloneZODB/ZEO/StorageServer.py 1.34.2.3 => 1.34.2.4 ===
 from cStringIO import StringIO
 from thread import start_new_thread
+import time
 from types import StringType
 
 from ZODB import POSException
@@ -128,7 +129,9 @@
                                                    len(connections))
             lines.append(s)
             for c in connections:
-                lines.append(str(c))
+                lines.append("%s readable=%s writeable=%s" % (
+                   c, c.readable(), c.writable()))
+                lines.append("\t" + c.stats())
         log.info(string.join(lines, "\n"))
 
 storage_methods={}
@@ -178,9 +181,36 @@
             debug = log
         else:
             debug = None
+
+        if __debug__:
+            # store some detailed statistics about method calls
+            self._last_method = None
+            self._t_begin = None
+            self._t_end = None
+            
         SizedMessageAsyncConnection.__init__(self, sock, addr, debug=debug)
         log.info('Connect %s %s' % (id(self), `addr`))
 
+    def stats(self):
+        # This method is called via the status() command.  The stats
+        # are of limited use for the current command, because the
+        # actual invocation of status() will clobber the previous
+        # method's statistics.
+        #
+        # When there are multiple connections active, a new connection
+        # can always get detailed statistics about other connections.
+        if __debug__:
+            if self._last_method == "status":
+                return "method=status begin=%s end=..." % self._t_begin
+            if self._t_end is not None and self._t_begin is not None:
+                delta = self._t_end - self._t_begin
+            else:
+                delta = -1
+            return "method=%s begin=%s end=%s delta=%.3f" % (
+                self._last_method, self._t_begin, self._t_end, delta)
+        else:
+            return ""
+
     def __repr__(self):
         return "<ZEOConnection %s%s" % (`self.addr`,
                          # sort of messy way to add tag 'closed' to
@@ -205,6 +235,10 @@
                       dump=dump, Unpickler=Unpickler, StringIO=StringIO,
                       None=None):
         if __debug__:
+
+            self._t_begin = time.time()
+            self._t_end = None
+            
             if len(message) > 120: # XXX need constant from logger
                 tmp = `message[:120]`
             else:
@@ -212,6 +246,9 @@
             log.trace("message_input %s" % tmp)
 
         if self.__storage is None:
+            if __debug__:
+                log.debug("register connection to %s from %s" % (message,
+                                                                 self.addr))
             # This is the first communication from the client
             self.__storage, self.__storage_id = (
                 self.__server.register_connection(self, message))
@@ -229,11 +266,14 @@
             
             name, args = args[0], args[1:]
             if __debug__:
+                self._last_method = name
                 log.debug("call %s%s from %s" % (name, format_msg(args),
                                                  self.addr))
                 
             if not storage_method(name):
                 log.warning("Invalid method name: %s" % name)
+                if __debug__:
+                    self._t_end = time.time()
                 raise 'Invalid Method Name', name
             if hasattr(self, name):
                 r=apply(getattr(self, name), args)
@@ -241,19 +281,26 @@
                 r=apply(getattr(self.__storage, name), args)
             if r is _noreturn:
                 if __debug__:
-                    log.trace("no return to %s" % `self.addr`)
+                    log.debug("no return to %s" % `self.addr`)
+                    self._t_end = time.time()
                 return
-        except (UndoError, VersionCommitError):
-            # These are normal usage errors. No need to leg them
+        except (UndoError, VersionCommitError), err:
+            if __debug__:
+                log.debug("return error %s to %s" % (err, self.addr))
+                self._t_end = time.time()
+            # These are normal usage errors. No need to log them.
             self.return_error(sys.exc_info()[0], sys.exc_info()[1])
             return
         except:
+            if __debug__:
+                self._t_end = time.time()
             log.error("error", error=sys.exc_info())
             self.return_error(sys.exc_info()[0], sys.exc_info()[1])
             return
 
         if __debug__:
-            log.trace("return %s to %s" % (`r`, self.addr))
+            log.debug("return %s to %s" % (format_msg(r), self.addr))
+            self._t_end = time.time()
             
         r=dump(r,1)            
         self.message_output('R'+r)