[Zodb-checkins] CVS: Packages/ZEO - zeolog.py:1.1.2.1 ClientCache.py:1.14.4.4 ClientStorage.py:1.26.4.11 StorageServer.py:1.21.4.6 smac.py:1.9.6.4 zrpc2.py:1.1.2.9

jeremy@digicool.com jeremy@digicool.com
Fri, 20 Apr 2001 15:14:09 -0400 (EDT)


Update of /cvs-repository/Packages/ZEO
In directory korak:/tmp/cvs-serv24482

Modified Files:
      Tag: ZEO-ZRPC-Dev
	ClientCache.py ClientStorage.py StorageServer.py smac.py 
	zrpc2.py 
Added Files:
      Tag: ZEO-ZRPC-Dev
	zeolog.py 
Log Message:
Big changes to logging to improve performance.

Replace use of zLOG with zeolog (a slimmed-down replacement).  Protect
all calls for TRACE level inside if __debug__.

The zLOG code has a lot of extra indirections that slow down an
application.  zeolog appears to be about 15% faster.

The use of __debug__ has a much more dramatic effect, because there is
a lot of logging in the lower layers of zrpc2.  By putting TRACE-level
logging inside if __debug__ and running python -O, the net savings is
another 20% (measured with speed.py).

Also, add ZPL and doc string to zrpc2.py



--- Added File zeolog.py in package Packages/ZEO ---
"""ZEO-specific replacement for the zLOG module"""

import os
import sys
import time

# the logging severity constants defined by zLOG
from zLOG import TRACE, DEBUG, BLATHER, INFO, PROBLEM, WARNING, ERROR, PANIC

severity_strings = {TRACE: 'TRACE',
                    DEBUG: 'DEBUG',
                    BLATHER: 'BLATHER',
                    INFO: 'INFO',
                    PROBLEM: 'PROBLEM',
                    WARNING: 'WARNING',
                    ERROR: 'ERROR',
                    PANIC: 'PANIC',
                    }

def now():
    t = time.time()
    hms = time.gmtime(t)[3:6]
    msec = int(1000 * (t - int(t)))
    return "%2.2d:%2.2d:%2.2d." % hms + "%03d" % msec

def LOG(subsys, severity, summary, detail='', error=None,
        reraise=None):
    if log_file is None or severity < log_level:
        return
    s = "%s %7s %s %s" % (now(), severity_strings[severity], subsys, summary)
    if detail:
        s = "%s\n%s" % (s, detail)
    print >> log_file, s
    log_file.flush()

    if error:
        pass # XXX haven't implemented traceback writing

    if reraise and error:
        raise error[0], error[1], error[2]

def initialize():
    """Initialize the module from environment variables"""
    global log_file, log_level
    
    path = os.environ.get('STUPID_LOG_FILE', None)
    if path is None:
        log_file = None
    else:
        if path:
            log_file = open(path, 'a')
        else:
            log_file = sys.stderr

    severity = os.environ.get('STUPID_LOG_SEVERITY', None)
    if severity:
        log_level = int(severity)
    else:
        log_level = INFO

__all__ = ["LOG", "TRACE", "DEBUG", "BLATHER", "INFO", "PROBLEM",
           "WARNING", "ERROR", "PANIC"] 
initialize()

--- Updated File ClientCache.py in package Packages/ZEO --
--- ClientCache.py	2001/04/19 19:18:20	1.14.4.3
+++ ClientCache.py	2001/04/20 19:14:08	1.14.4.4
@@ -151,10 +151,10 @@
 from thread import allocate_lock
 
 import sys
-import zLOG
+import zeolog
 
-def log(msg, level=zLOG.INFO):
-    zLOG.LOG("ZEC", level, msg)
+def log(msg, level=zeolog.INFO):
+    zeolog.LOG("ZEC", level, msg)
 
 magic='ZEC0'
 

--- Updated File ClientStorage.py in package Packages/ZEO --
--- ClientStorage.py	2001/04/20 13:56:10	1.26.4.10
+++ ClientStorage.py	2001/04/20 19:14:08	1.26.4.11
@@ -108,7 +108,7 @@
 
 from ZODB import POSException, BaseStorage
 from ZODB.TimeStamp import TimeStamp
-from zLOG import LOG, PROBLEM, INFO, BLATHER
+from zeolog import LOG, PROBLEM, INFO, BLATHER
 
 try:
     from ZODB.ConflictResolution import ResolvedSerial

--- Updated File StorageServer.py in package Packages/ZEO --
--- StorageServer.py	2001/04/19 15:47:48	1.21.4.5
+++ StorageServer.py	2001/04/20 19:14:08	1.21.4.6
@@ -1,3 +1,93 @@
+##############################################################################
+# 
+# Zope Public License (ZPL) Version 1.0
+# -------------------------------------
+# 
+# Copyright (c) Digital Creations.  All rights reserved.
+# 
+# This license has been certified as Open Source(tm).
+# 
+# Redistribution and use in source and binary forms, with or without
+# modification, are permitted provided that the following conditions are
+# met:
+# 
+# 1. Redistributions in source code must retain the above copyright
+#    notice, this list of conditions, and the following disclaimer.
+# 
+# 2. Redistributions in binary form must reproduce the above copyright
+#    notice, this list of conditions, and the following disclaimer in
+#    the documentation and/or other materials provided with the
+#    distribution.
+# 
+# 3. Digital Creations requests that attribution be given to Zope
+#    in any manner possible. Zope includes a "Powered by Zope"
+#    button that is installed by default. While it is not a license
+#    violation to remove this button, it is requested that the
+#    attribution remain. A significant investment has been put
+#    into Zope, and this effort will continue if the Zope community
+#    continues to grow. This is one way to assure that growth.
+# 
+# 4. All advertising materials and documentation mentioning
+#    features derived from or use of this software must display
+#    the following acknowledgement:
+# 
+#      "This product includes software developed by Digital Creations
+#      for use in the Z Object Publishing Environment
+#      (http://www.zope.org/)."
+# 
+#    In the event that the product being advertised includes an
+#    intact Zope distribution (with copyright and license included)
+#    then this clause is waived.
+# 
+# 5. Names associated with Zope or Digital Creations must not be used to
+#    endorse or promote products derived from this software without
+#    prior written permission from Digital Creations.
+# 
+# 6. Modified redistributions of any form whatsoever must retain
+#    the following acknowledgment:
+# 
+#      "This product includes software developed by Digital Creations
+#      for use in the Z Object Publishing Environment
+#      (http://www.zope.org/)."
+# 
+#    Intact (re-)distributions of any official Zope release do not
+#    require an external acknowledgement.
+# 
+# 7. Modifications are encouraged but must be packaged separately as
+#    patches to official Zope releases.  Distributions that do not
+#    clearly separate the patches from the original work must be clearly
+#    labeled as unofficial distributions.  Modifications which do not
+#    carry the name Zope may be packaged in any form, as long as they
+#    conform to all of the clauses above.
+# 
+# 
+# Disclaimer
+# 
+#   THIS SOFTWARE IS PROVIDED BY DIGITAL CREATIONS ``AS IS'' AND ANY
+#   EXPRESSED OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
+#   IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR
+#   PURPOSE ARE DISCLAIMED.  IN NO EVENT SHALL DIGITAL CREATIONS OR ITS
+#   CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
+#   SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
+#   LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF
+#   USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND
+#   ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY,
+#   OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT
+#   OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
+#   SUCH DAMAGE.
+# 
+# 
+# This software consists of contributions made by Digital Creations and
+# many individuals on behalf of Digital Creations.  Specific
+# attributions are listed in the accompanying credits file.
+# 
+##############################################################################
+"""Network ZODB storage server
+
+This server acts as a front-end for one or more real storages, like
+file storage or Berkeley storage.
+"""
+
 import cPickle
 import os
 import sys
@@ -5,7 +95,7 @@
 
 import ClientStub
 import zrpc2
-import zLOG
+import zeolog
 
 from zrpc2 import Dispatcher, Handler, ManagedServerConnection, Delay
 from ZODB.POSException import StorageError, StorageTransactionError, \
@@ -20,8 +110,8 @@
 pickler.fast = 1 # Don't use the memo
 dump = pickler.dump
 
-def log(message, level=zLOG.INFO, label="zeoserver:%s" % os.getpid()):
-    zLOG.LOG(label, level, message)
+def log(message, level=zeolog.INFO, label="zeoserver:%s" % os.getpid()):
+    zeolog.LOG(label, level, message)
 
 class StorageServerError(StorageError):
     pass
@@ -157,7 +247,7 @@
         try: 
             self.__storage.pack(t, referencesf)
         except:
-            log('ZEO Server', zLOG.ERROR,
+            log('ZEO Server', zeolog.ERROR,
                 'Pack failed for %s' % self.__storage_id,
                 error=sys.exc_info())
             if wait:
@@ -208,7 +298,7 @@
             # IOW, Anything that ends up here is evil enough to be logged.
             error = sys.exc_info()
             log('store error: %s: %s' % (error[0], error[1]).
-                zLOG.ERROR)
+                zeolog.ERROR)
             newserial = sys.exc_info()[1]
         else:
             if serial != '\0\0\0\0\0\0\0\0':
@@ -218,7 +308,7 @@
             nil = dump(newserial, 1)
         except:
             log("couldn't pickle newserial: %s" % repr(newserial),
-                zLOG.ERROR)
+                zeolog.ERROR)
             dump('', 1) # clear pickler
             r = StorageServerError("Couldn't pickle exception %s" % \
                                    `newserial`)

--- Updated File smac.py in package Packages/ZEO --
--- smac.py	2001/04/18 20:55:09	1.9.6.3
+++ smac.py	2001/04/20 19:14:08	1.9.6.4
@@ -88,7 +88,7 @@
 __version__ = "$Revision$"[11:-2]
 
 import asyncore, string, struct, sys, Acquisition
-from zLOG import LOG, TRACE, ERROR, INFO, BLATHER
+from zeolog import LOG, TRACE, ERROR, INFO, BLATHER
 from types import StringType
 
 class SizedMessageAsyncConnection(asyncore.dispatcher):

--- Updated File zrpc2.py in package Packages/ZEO --
--- zrpc2.py	2001/04/19 18:25:03	1.1.2.8
+++ zrpc2.py	2001/04/20 19:14:09	1.1.2.9
@@ -36,14 +36,14 @@
 from ZODB import POSException
 import smac
 import trigger
-import zLOG
+import zeolog
 import ThreadedAsync
 
 REPLY = ".reply" # message name used for replies
 ASYNC = 1
 
-def log(message, level=zLOG.BLATHER, label="zrpc:%s" % os.getpid()):
-    zLOG.LOG(label, level, message)
+def log(message, level=zeolog.BLATHER, label="zrpc:%s" % os.getpid()):
+    zeolog.LOG(label, level, message)
 
 class ZRPCError(POSException.StorageError):
     pass
@@ -97,11 +97,11 @@
         unpickler.find_global = find_global
 
         try:
+            return unpickler.load() # msgid, flags, name, args
             msgid, flags, name, args = unpickler.load()
         except (cPickle.UnpicklingError, IndexError), err_msg:
-            log("can't decode %s" % repr(msg), level=zLOG.ERROR)
+            log("can't decode %s" % repr(msg), level=zeolog.ERROR)
             raise DecodingError(msg)
-        return msgid, flags, name, args
 
 class Delay:
     """Used to delay response to client for synchronous calls
@@ -118,43 +118,6 @@
     def reply(self, obj):
         self.send_reply(self.msgid, obj)
 
-class DebugLock:
-
-    __locks = 0
-    
-    def __init__(self):
-        self.lock = thread.allocate_lock()
-        # XXX this actually needs to be locked too
-        self.__lock_id = self.__locks
-        self.__locks = self.__locks + 1
-
-    def _debug(self):
-        method = sys._getframe().f_back
-        caller = method.f_back
-        filename = os.path.split(caller.f_code.co_filename)[1]
-        log("LOCK %s (tid %s): " \
-            "%s called by %s, %s, line %s" % (self.__lock_id,
-                                              thread.get_ident(),
-                                              method.f_code.co_name,
-                                              caller.f_code.co_name,
-                                              filename,
-                                              caller.f_lineno))
-
-    def acquire(self, wait=None):
-        self._debug()
-        if wait is not None:
-            return self.lock.acquire(wait)
-        else:
-            return self.lock.acquire()
-        
-    def release(self):
-        self._debug()
-        return self.lock.release()
-
-    def locked(self):
-        self._debug()
-        return self.lock.locked()
-    
 class Connection(smac.SizedMessageAsyncConnection):
     """Dispatcher for RPC on object
 
@@ -182,7 +145,6 @@
         # waiting for a response
         self.__super_init(sock, addr)
         self._prepare_async()
-##        self.__reply_lock = DebugLock()
         self.__reply_lock = thread.allocate_lock()
         self.__reply_lock.acquire()
         if isinstance(obj, Handler):
@@ -211,20 +173,25 @@
             return self.return_error(None, None, sys.exc_info()[0],
                                      sys.exc_info()[1])  
 
-        log("message: %s, %s, %s, %s" % (msgid, flags, name, repr(args)[:40]),
-            level=zLOG.TRACE)
+        if __debug__:
+            log("message: %s, %s, %s, %s" % (msgid, flags, name,
+                                             repr(args)[:40]),
+                level=zeolog.TRACE)
         if name == REPLY:
             self.handle_reply(msgid, flags, args)
         else:
             self.handle_request(msgid, flags, name, args)
 
     def handle_reply(self, msgid, flags, args):
-        log("reply: %s, %s, %s" % (msgid, flags, str(args)[:40]))
+        if __debug__:
+            log("reply: %s, %s, %s" % (msgid, flags, str(args)[:40]),
+                level=zeolog.TRACE)
         self.__reply = msgid, flags, args
         self.__reply_lock.release() # will fail if lock is unlocked
 
     def handle_request(self, msgid, flags, name, args):
-        log("%s%s" % (name, repr(args)[:40]), zLOG.TRACE)
+        if __debug__:
+            log("%s%s" % (name, repr(args)[:40]), zeolog.TRACE)
         if not self.check_method(name):
             raise ZRPCError("Invalid method name: %s" % name)
 
@@ -250,7 +217,8 @@
             if ret is not None:
                 raise ZRPCError("async method returned value")
         else:
-            log("%s reply %s" % (name, repr(ret)[:40]), zLOG.TRACE)
+            if __debug__:
+                log("%s reply %s" % (name, repr(ret)[:40]), zeolog.TRACE)
             if isinstance(ret, Delay):
                 ret.set_sender(msgid, self.send_reply)
             else:
@@ -324,7 +292,6 @@
             raise DisconnectedError("This action is temporarily unavailable")
         msgid = self.msgid
         self.msgid = self.msgid + 1
-        log("call %s %s" % (msgid, method))
         self.message_output(self.marshal.encode(msgid, 0, method, args))
 
         self.__reply = None
@@ -333,15 +300,12 @@
         # lock is held again...
         r_msgid, r_flags, r_args = self.__reply
         self.__reply_lock.acquire()
-        log("call acquired lock")
         assert r_msgid == msgid, "%s != %s: %s" % (r_msgid, msgid, r_args)
 
         if type(r_args) == types.TupleType \
            and type(r_args[0]) == types.ClassType \
            and issubclass(r_args[0], Exception):
-            log("call %s %s raised error" % (msgid, method))
             raise r_args[1]
-        log("call %s %s returned" % (msgid, method))
         return r_args
 
     def callAsync(self, method, *args):
@@ -349,12 +313,14 @@
             raise DisconnectedError("This action is temporarily unavailable")
         msgid = self.msgid
         self.msgid = self.msgid + 1
-        log("async %s %s" % (msgid, method))
         self.message_output(self.marshal.encode(msgid, ASYNC, method, args))
         self._do_io()
 
     # handle IO, possibly in async mode
 
+    def sync(self):
+        pass # XXX what is this supposed to do?
+
     def _prepare_async(self):
         self._async = 0
         ThreadedAsync.register_loop_callback(self.set_async)
@@ -373,9 +339,10 @@
     def _do_io(self, wait=0): # XXX need better name
         # XXX invariant? lock must be held when calling with wait==1
         # otherwise, in non-async mode, there will be no poll
-        
-        log("_do_io(wait=%d), async=%d" % (wait, self.is_async()),
-            level=zLOG.TRACE)
+
+        if __debug__:
+            log("_do_io(wait=%d), async=%d" % (wait, self.is_async()),
+                level=zeolog.TRACE)
         if self.is_async():
             self.trigger.pull_trigger()
             if wait:
@@ -465,12 +432,12 @@
                 s.connect(self.addr)
             except socket.error:
                 if self.debug:
-                    log("Failed to connect to server", level=zLOG.DEBUG)
+                    log("Failed to connect to server", level=zeolog.DEBUG)
                 if repeat:
                     t = self._wait(t)
             else:
                 if self.debug:
-                    log("Connected to server", level=zLOG.DEBUG)
+                    log("Connected to server", level=zeolog.DEBUG)
                 self.connected = 1
         if self.connected:
             c = ManagedConnection(s, self.addr, self.obj, self)
@@ -502,7 +469,6 @@
 
     def close(self):
         self.__super_close()
-        log("self.__mgr = %s" % repr(self.__mgr))
         self.__mgr.close(self)
 
 class ManagedConnection(Connection):
@@ -578,7 +544,7 @@
             log("accepted failed: %s" % msg)
             return
         c = self.factory(sock, addr, self.obj)
-        log("connect from %s: %s" % (addr, c))
+        log("connect from %s: %s" % (repr(addr), c))
         self.clients.append(c)
 
 class Handler: