changeset 2208:2f7f195f4dd2

log timing (using std logging)
author Thomas Waldmann <tw AT waldmann-edv DOT de>
date Thu, 21 Jun 2007 09:05:18 +0200
parents 7ae581d79352
children ebdcd00ce19d
files MoinMoin/config/multiconfig.py MoinMoin/request/__init__.py
diffstat 2 files changed, 37 insertions(+), 0 deletions(-) [+]
line wrap: on
line diff
--- a/MoinMoin/config/multiconfig.py	Mon May 14 22:03:21 2007 +0200
+++ b/MoinMoin/config/multiconfig.py	Thu Jun 21 09:05:18 2007 +0200
@@ -325,6 +325,7 @@
 
     log_reverse_dns_lookups = True  # if we do reverse dns lookups for logging hostnames
                                     # instead of just IPs
+    log_timing = False              # update <data_dir>/timing.log?
 
     xapian_search = False
     xapian_index_dir = None
--- a/MoinMoin/request/__init__.py	Mon May 14 22:03:21 2007 +0200
+++ b/MoinMoin/request/__init__.py	Thu Jun 21 09:05:18 2007 +0200
@@ -848,6 +848,36 @@
             msg = msg.encode(config.charset)
         logging.info(msg)
 
+    def timing_log(self, start, action):
+        """ Log to timing log (for performance analysis) """
+        indicator = ''
+        if start:
+            total = "vvv"
+        else:
+            self.clock.stop('total') # make sure it is stopped
+            total_secs = self.clock.timings['total']
+            # we add some stuff that is easy to grep when searching for peformance problems:
+            if total_secs > 50:
+                indicator += '!4!'
+            elif total_secs > 20:
+               indicator += '!3!'
+            elif total_secs > 10:
+                indicator += '!2!'
+            elif total_secs > 2:
+                indicator += '!1!'
+            total = self.clock.value('total')
+            # use + for existing pages, - for non-existing pages
+            indicator += self.page.exists() and '+' or '-'
+            if self.isSpiderAgent:
+                indicator += "B"
+
+        # Add time stamp and process ID
+        pid = os.getpid()
+        t = time.time()
+        timestr = time.strftime("%Y%m%d %H%M%S", time.gmtime(t))
+        msg = '%s %5d %-6s %4s %-10s %s\n' % (timestr, pid, total, indicator, action, self.url)
+        self.log(msg)
+
     def write(self, *data):
         """ Write to output stream. """
         raise NotImplementedError
@@ -1143,6 +1173,9 @@
 
         # parse request data
         try:
+            if self.cfg.log_timing:
+                self.timing_log(True, action)
+
             # The last component in path_info is the page name, if any
             path = self.getPathinfo()
 
@@ -1237,6 +1270,9 @@
             self.finish()
             self.fail(err)
 
+        if self.cfg.log_timing:
+            self.timing_log(False, action)
+
         return self.finish()
 
     def http_redirect(self, url):