Added log.stat, supybot.log.statistics, and changed some statistic-keeping functions over to use log.stat.

src/asyncoreDrivers.py

@@ -106,8 +106,7 @@ class AsyncoreDriver(asynchat.async_chat, drivers.ServersMixin):
 
     def found_terminator(self):
         start = time.time()
-        msg = ircmsgs.IrcMsg(self.buffer)
+        msg = drivers.parseMsg(self.buffer)
-        #log.debug('Time to parse IrcMsg: %s', time.time()-start)
         self.buffer = ''
         self.irc.feedMsg(msg)
 

src/callbacks.py

@@ -299,7 +299,7 @@ def tokenize(s, brackets=None, channel=None):
         return Tokenizer(tokens).tokenize(s)
     except ValueError, e:
         raise SyntaxError, str(e)
-    #log.debug('tokenize took %s seconds.' % (time.time() - start))
+    log.stat('tokenize took %s seconds.' % (time.time() - start))
 
 def getCommands(tokens):
     """Given tokens as output by tokenize, returns the command names."""
@@ -911,7 +911,7 @@ class Privmsg(irclib.IrcCallback):
         start = time.time()
         method(irc, msg, *L)
         elapsed = time.time() - start
-        self.log.debug('%s took %s seconds', name, elapsed)
+        log.stat('%s took %s seconds', name, elapsed)
 
     def registryValue(self, name, channel=None, value=True):
         plugin = self.name()

src/drivers.py

@@ -40,6 +40,7 @@ import supybot.fix as fix
 import re
 import os
 import sys
+import time
 
 import supybot.log as supylog
 import supybot.conf as conf
@@ -172,6 +173,7 @@ class Log(object):
     critical = staticmethod(supylog.critical)
     timestamp = staticmethod(supylog.timestamp)
     exception = staticmethod(supylog.exception)
+    stat = staticmethod(supylog.stat)
 
 log = Log()
         
@@ -195,4 +197,10 @@ def newDriver(irc, moduleName=None):
     irc.driver = driver
     return driver
 
+def parseMsg(s):
+    start = time.time()
+    msg = ircmsgs.IrcMsg(s)
+    log.stat('Time to parse IrcMsg: %s', time.time()-start)
+    return msg
+
 # vim:set shiftwidth=4 tabstop=8 expandtab textwidth=78:

src/log.py

@@ -162,6 +162,10 @@ error = _logger.error
 critical = _logger.critical
 exception = _logger.exception
 
+def stat(*args):
+    level = conf.supybot.log.statistics()
+    _logger.log(level, *args)
+    
 setLevel = _logger.setLevel
 
 atexit.register(logging.shutdown)
@@ -276,6 +280,11 @@ conf.registerGlobalValue(conf.supybot.log, 'level',
     LogLevel(logging.INFO, """Determines what the minimum priority level logged
     will be.  Valid values are DEBUG, INFO, WARNING, ERROR, and CRITICAL, in
     order of increasing priority."""))
+conf.registerGlobalValue(conf.supybot.log, 'statistics',
+    ValidLogLevel(logging.DEBUG, """Determines what level statistics reporting
+    is to be logged at.  Mostly, this just includes, for instance, the time it
+    took to parse a message, process a command, etc.  You probably don't care
+    about this."""))
 conf.registerGlobalValue(conf.supybot.log, 'stdout',
     registry.Boolean(True, """Determines whether the bot will log to
     stdout."""))

src/socketDrivers.py

@@ -105,9 +105,7 @@ class SocketDriver(drivers.IrcDriver, drivers.ServersMixin):
             lines = self.inbuffer.split('\n')
             self.inbuffer = lines.pop()
             for line in lines:
-                start = time.time()
+                msg = drivers.parseMsg(line)
-                msg = ircmsgs.IrcMsg(line)
-                #log.debug('Time to parse IrcMsg: %s', time.time()-start)
                 self.irc.feedMsg(msg)
         except socket.timeout:
             pass

src/twistedDrivers.py

@@ -60,8 +60,7 @@ class SupyIrcProtocol(LineReceiver):
 
     def lineReceived(self, line):
         start = time.time()
-        msg = ircmsgs.IrcMsg(line)
+        msg = drivers.parseMsg(line)
-        #log.debug('Time to parse IrcMsg: %s', time.time()-start)
         self.irc.feedMsg(msg)
 
     def checkIrcForMsgs(self):