Merge lp:~coreygoldberg/lp-dev-utils/ppr-access-parser into lp:lp-dev-utils

[Corey Goldberg]

 give PPR (page-performance-report) ability to analyze Apache Access logs.

this branch is an enhancement to PPR (page-performance-report)... giving it the ability to analyze Apache Access logs.

when configured to run in "access log mode" (log_format=access), no 3rd party python libs are needed (such as zc.zservertracelog)

Change Summary:
---------------

* added parser for apache access logs

* added new mandatory [parser] config section to ini.
  takes option: (log_format=launchpad|access)

* changed CSS links in HTML to relative URLs,
  so we aren't harcoded to devpad.c.c.

* added new config/ini file for SSO/access logs:
    * page-perf_acccess.ini

* tweaked inline css slightly, and switched to Ubuntu font

Notes:
------

* report generated from sample staging access log:
    * https://chinstrap.canonical.com/~cgoldberg/ppr/sample-ppr/combined.html

* sample log for testing:
    * https://chinstrap.canonical.com/~cgoldberg/ppr/access_sample_sso_staging.log

* command-line example invoking page-performance-report.py
against sample access log, using new ini and a defined
output directory:

$ python page-performance-report.py \
--config=page-perf_acccess.ini \
--directory=/home/cgoldberg/tmp \
--no-partition \
access_sample_sso_staging.log

[lp:~coreygoldberg/lp-dev-utils/ppr-access-parser]

131. By Corey Goldberg on 2012-08-13

use genex to convert to ints

132. By Corey Goldberg on 2012-08-14

updated ini and fixed url field in parser

133. By Corey Goldberg on 2012-08-14

updated example SSO config

134. By Corey Goldberg on 2012-08-15

updated ini with SSO categories

135. By Corey Goldberg on 2012-08-15

fixed regexes in .ini categories

136. By Corey Goldberg on 2012-08-15

fixed config for ppr

137. By Corey Goldberg on 2012-08-16

ini cleanup

[j.c.sackett (jcsackett)]

Corey--

This looks like a good start, but there's some confusing and possibly
unnecessary code here, plus a few style issues.

#117: Looks like you've unordered the imports here, please reorder them
appropriately (e.g. alphabetically).

#159 `create_request_class` method seems unnecessary; as you know in
`parse_launchpad` or `parse_access` which format you're using, it would be
cleaner to just define two different classes instead and use the appropriate
one in the appropriate parse function. I'm guessing this to facilitate not
importing from zc unless you need it, but this seems like an unnecessary
optimization that results in less clear code.

review: Needs Fixing

[Corey Goldberg (coreygoldberg)]

thanks for looking over the code.

> #159 `create_request_class` method seems unnecessary;
> I'm guessing this to facilitate not importing from zc
> unless you need it, but this seems like an unnecessary
> optimization that results in less clear code.

I am going to be using this code on servers that don't have zc libs installed.

[j.c.sackett (jcsackett)]

As discussed in IRC, given the apparent need to have this script support both functions and not require zc &c, if you just fix the other import issues and leave a comment indicating why this peculiarity exists and that if we separated these two utilities in some way we might be able to clean it up, we can call this good to go.

Thanks, Corey.

[lp:~coreygoldberg/lp-dev-utils/ppr-access-parser]

138. By Corey Goldberg on 2012-08-16

reordered imports and left XXX comment per MP comments

139. By Corey Goldberg on 2012-08-16

fixed comments

[Corey Goldberg (coreygoldberg)]

> fix the other import issues and leave a comment
> indicating why this peculiarity exists and that
> if we separated these two utilities in some way
> we might be able to clean it up

fixed imports and left comment. see updated branch/diff.

thanks!

[j.c.sackett (jcsackett)]

Thanks, Corey.

review: Approve

=== added file 'page-perf_acccess.ini'
--- page-perf_acccess.ini	1970-01-01 00:00:00 +0000
+++ page-perf_acccess.ini	2012-08-16 19:59:16 +0000
@@ -0,0 +1,40 @@
+[categories]
+# 
+# Category -> Python regular expression.
+# Remeber to quote ?, ., + & ? characters to match litterally.
+#
+Home=^/$
+Login=/(\+login|\+enter_token)
+Logout=/\+logout
+OpenID=/(\+openid|\+id|\+decide)
+Static Media=/assets/
+Admin=/admin/
+API=/api/
+Registration=/\+new_account
+Two Factor=/(device-list|two_factor_auth|device-addition)
+Account=/(\+edit|\+new-email|\+emails)
+Consumer=/consumer/
+All Requests=.
+
+
+[metrics]
+home=Home
+login=Login
+logout=Logout
+open_id=OpenID
+static_media=Static Media
+admin=Admin
+api=API
+registration=Registration
+two_factor=Two Factor
+account=Account
+consumer=Consumer
+all_requests=All Requests
+
+
+[partition]
+All Requests=
+
+
+[parser]
+log_format=access

=== modified file 'page-performance-report.ini'
--- page-performance-report.ini	2012-08-09 04:53:16 +0000
+++ page-performance-report.ini	2012-08-16 19:59:16 +0000
@@ -77,3 +77,6 @@
 Public XML-RPC=
 Web (Non API/non operational/non XML-RPC)=
 Other=
+
+[parser]
+log_format=launchpad

=== modified file 'page-performance-report.py'
--- page-performance-report.py	2012-08-09 04:53:16 +0000
+++ page-performance-report.py	2012-08-16 19:59:16 +0000
@@ -1,9 +1,9 @@
 #!/usr/bin/python -S
 #
-# Copyright 2010 Canonical Ltd.  This software is licensed under the
+# Copyright 2010 - 2012 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
-"""Page performance report generated from zserver tracelogs."""
+"""Page performance report generated from zserver tracelogs or apache access logs."""
 
 __metaclass__ = type
 
@@ -11,7 +11,7 @@
 
 import sys
 
-from lp.scripts.utilities.pageperformancereport import main
+from pageperformancereport import main
 
 
 if __name__ == '__main__':

=== modified file 'pageperformancereport.py'
--- pageperformancereport.py	2012-08-09 04:53:16 +0000
+++ pageperformancereport.py	2012-08-16 19:59:16 +0000
@@ -1,31 +1,29 @@
-# Copyright 2010 Canonical Ltd.  This software is licensed under the
+# Copyright 2010-2012 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
-"""Page performance report generated from zserver trace logs."""
+"""Page performance report generated from zserver tracelogs or apache access logs."""
 
 __metaclass__ = type
 __all__ = ['main']
 
+from cgi import escape as html_quote
 import bz2
-from cgi import escape as html_quote
-from ConfigParser import RawConfigParser
+import ConfigParser
 import copy
 import cPickle
 import csv
-from datetime import datetime
+from datetime import (datetime, timedelta)
 import gzip
 import logging
 import math
 import optparse
 import os.path
 import re
-import textwrap
-from textwrap import dedent
-import time
-
 import simplejson as json
 import sre_constants
-import zc.zservertracelog.tracereport
+from textwrap import dedent
+import time     
+
 
 logging.basicConfig()
 log = logging
@@ -61,7 +59,7 @@
     TYPE_CHECKER[datetime] = _check_datetime
 
 
-class OptionParser(optparse.OptionParser):
+class ExtendedOptionParser(optparse.OptionParser):
     """Extended optparse OptionParser.
 
     Adds a 'datetime' option type.
@@ -72,27 +70,63 @@
         optparse.OptionParser.__init__(self, *args, **kw)
 
 
-class Request(zc.zservertracelog.tracereport.Request):
-    url = None
-    pageid = None
-    ticks = None
-    sql_statements = None
-    sql_seconds = None
-
-    # Override the broken version in our superclass that always
-    # returns an integer.
-    @property
-    def app_seconds(self):
-        interval = self.app_time - self.start_app_time
-        return interval.seconds + interval.microseconds / 1000000.0
-
-    # Override the broken version in our superclass that always
-    # returns an integer.
-    @property
-    def total_seconds(self):
-        interval = self.end - self.start
-        return interval.seconds + interval.microseconds / 1000000.0
-
+# XXX: coreygoldberg 2012-08-16 : this function exists to avoid importing 
+#  zc libs (zc.zservertracelog.tracereport) when not in log_format=launchpad
+#  parser mode.  It could be cleaned up if we refactored and made modular, or
+#  separated this into different projects/utils.
+def create_request_class(log_format='launchapd'):
+    """ Define a Request class for use with compatible log_format. """
+    
+    if log_format == 'launchpad':
+        import zc.zservertracelog.tracereport
+        class ZServerRequest(zc.zservertracelog.tracereport.Request):
+            url = None
+            pageid = None
+            ticks = None
+            sql_statements = None
+            sql_seconds = None
+
+            # Override the broken version in our superclass that always
+            # returns an integer.
+            @property
+            def app_seconds(self):
+                interval = self.app_time - self.start_app_time
+                return interval.seconds + interval.microseconds / 1000000.0
+
+            # Override the broken version in our superclass that always
+            # returns an integer.
+            @property
+            def total_seconds(self):
+                interval = self.end - self.start
+                return interval.seconds + interval.microseconds / 1000000.0
+        return ZServerRequest
+        
+    elif log_format == 'access':
+        class AccessRequest(object):
+            url = None
+            pageid = None
+            ticks = None
+            sql_statements = None
+            sql_seconds = None
+            
+            def __init__(self, dt, method, url, duration):
+                self.dt = dt
+                self.method = method
+                self.url = url
+                self.duration = duration
+                self.interval = timedelta(microseconds=self.duration)
+                
+            @property
+            def app_seconds(self):
+                interval = self.interval
+                return interval.seconds + interval.microseconds / 1000000.0
+
+            @property
+            def total_seconds(self):
+                interval = self.interval
+                return interval.seconds + interval.microseconds / 1000000.0
+        return AccessRequest
+        
 
 class Category:
     """A Category in our report.
@@ -335,7 +369,7 @@
 
     def text(self):
         """Return a textual version of the stats."""
-        return textwrap.dedent("""
+        return dedent("""
         <Stats for %d requests:
             Time:     total=%.2f; mean=%.2f; median=%.2f; std=%.2f
             SQL time: total=%.2f; mean=%.2f; median=%.2f; std=%.2f
@@ -762,10 +796,20 @@
         parser.error("Config file %s not found." % options.config)
 
     # Need a better config mechanism as ConfigParser doesn't preserve order.
-    script_config = RawConfigParser()
+    script_config = ConfigParser.RawConfigParser()
     script_config.optionxform = str # Make keys case sensitive.
     script_config.readfp(open(options.config))
-
+    
+    try:
+        parser_options = script_config.options('parser')
+    except ConfigParser.NoSectionError:
+        log.fatal("[parser] section not found in ini file.")
+        return 1
+    if 'log_format' in parser_options:
+        log_format = script_config.get('parser', 'log_format')
+    else:    
+        parser.error("[parser] log_format not defined in ini file.")
+        
     categories = [] # A list of Category, in report order.
     for option in script_config.options('categories'):
         regexp = script_config.get('categories', option)
@@ -789,7 +833,7 @@
             log.warning(
                 "In partition definition: %s isn't a defined category",
                 option)
-
+                
     times = RequestTimes(categories, options)
 
     if options.merge:
@@ -799,8 +843,15 @@
             times += cPickle.load(f)
             f.close()
     else:
-        parse(args, times, options)
+        if log_format == 'launchpad':
+            parse_launchpad(args, times, options, log_format)
+        elif log_format == 'access':
+            parse_access(args, times, options, log_format)
+        else:
+            log.fatal("No parser available for log_format: %r" % log_format)
+            return 1
 
+        
     category_times = times.get_category_times()
 
     pageid_times = []
@@ -916,21 +967,36 @@
     """A malformed line was found in the trace log."""
 
 
-_ts_re = re.compile(
+_zserver_ts_re = re.compile(
     '^(\d{4})-(\d\d)-(\d\d)\s(\d\d):(\d\d):(\d\d)(?:.(\d{6}))?$')
 
-
-def parse_timestamp(ts_string):
-    match = _ts_re.search(ts_string)
+_access_ts_re = re.compile(
+    '^\[(\d{2})/([A-Za-z]+)/(\d{4}):(\d{2}):(\d{2}):(\d{2})[+-]\d{4}\]$')
+    
+      
+def parse_timestamp_zserverlog(ts_string):
+    match = _zserver_ts_re.search(ts_string)
     if match is None:
         raise ValueError("Invalid timestamp")
     return datetime(
         *(int(elem) for elem in match.groups() if elem is not None))
 
 
-def parse(tracefiles, times, options):
+def parse_timestamp_accesslog(ts_string):
+    match = _access_ts_re.search(ts_string)
+    if match is None:
+        raise ValueError("Invalid timestamp")
+    day, alpha_month, year, hour, min, sec = match.groups()
+    month = time.strptime(alpha_month,'%b').tm_mon # get numeric month
+    return datetime(
+        *(int(elem) for elem in (year, month, day, hour, min, sec)))
+        
+
+
+def parse_launchpad(tracefiles, times, options, log_format):
     requests = {}
     total_requests = 0
+    Request = create_request_class(log_format)
     for tracefile in tracefiles:
         log.info('Processing %s', tracefile)
         for line in smart_open(tracefile):
@@ -949,7 +1015,7 @@
                 # Parse the timestamp.
                 ts_string = '%s %s' % (date, time_)
                 try:
-                    dt = parse_timestamp(ts_string)
+                    dt = parse_timestamp_zserverlog(ts_string)
                 except ValueError:
                     raise MalformedLine(
                         'Invalid timestamp %s' % repr(ts_string))
@@ -1035,6 +1101,57 @@
             "Unknown extension prefix %s" % prefix)
 
 
+def parse_access(tracefiles, times, options, log_format):
+    requests = {}
+    total_requests = 0
+    Request = create_request_class(log_format)
+    for tracefile in tracefiles:
+        log.info('Processing %s', tracefile)
+        for line in smart_open(tracefile):
+            line = line.rstrip()
+            try:
+                record = line.split()
+                try:
+                    request_id = record[6]
+                    date = record[3]
+                    time_ = record[4]
+                    url = record[6]
+                    method = record[5]
+                    duration = int(record[-1])                
+                except ValueError:
+                    raise MalformedLine()
+
+                # Parse the timestamp.
+                ts_string = '%s%s' % (date, time_)
+                try:
+                    dt = parse_timestamp_accesslog(ts_string)
+                except ValueError:
+                    raise MalformedLine(
+                        'Invalid timestamp %s' % repr(ts_string))
+
+                # Filter entries by command line date range.
+                if options.from_ts is not None and dt < options.from_ts:
+                    continue # Skip to next line.
+                if options.until_ts is not None and dt > options.until_ts:
+                    break # Skip to next log file.
+
+                requests[request_id] = Request(dt, method, url, duration)    
+                request = requests.get(request_id, None)
+                if request is None: # Just ignore partial records.
+                    continue
+                request.url = url
+                del requests[request_id]
+                total_requests += 1
+                if total_requests % 10000 == 0:
+                    log.debug("Parsed %d requests", total_requests)
+                # Add the request to any matching categories.
+                times.add_request(request)
+
+            except MalformedLine as x:
+                log.error(
+                    "Malformed line %s (%s)" % (repr(line), x))
+                    
+                    
 def html_report(
     outf, category_times, pageid_times, url_times,
     ninetyninth_percentile_threshold=None, histogram_resolution=0.5,
@@ -1058,28 +1175,30 @@
         <html>
         <head>
         <meta http-equiv="Content-Type" content="text/html; charset=utf-8">
-        <title>Launchpad Page Performance Report %(date)s</title>
-        <script language="javascript" type="text/javascript"
-            src="https://devpad.canonical.com/~lpqateam/ppr/js/flot/jquery.min.js"
-            ></script>
-        <script language="javascript" type="text/javascript"
-            src="https://devpad.canonical.com/~lpqateam/ppr/js/jquery.appear-1.1.1.min.js"
-            ></script>
-        <script language="javascript" type="text/javascript"
-            src="https://devpad.canonical.com/~lpqateam/ppr/js/flot/jquery.flot.min.js"
-            ></script>
-        <script language="javascript" type="text/javascript"
-            src="https://devpad.canonical.com/~lpqateam/ppr/js/sorttable.js"></script>
+        <title>Page Performance Report %(date)s</title>
+        <script language="javascript" type="text/javascript"
+            src="../js/flot/jquery.min.js"
+            ></script>
+        <script language="javascript" type="text/javascript"
+            src="../js/jquery.appear-1.1.1.min.js"
+            ></script>
+        <script language="javascript" type="text/javascript"
+            src="../js/flot/jquery.flot.min.js"
+            ></script>
+        <script language="javascript" type="text/javascript"
+            src="../js/sorttable.js"></script>
+        <link href='http://fonts.googleapis.com/css?family=Ubuntu' rel='stylesheet' type='text/css'>
         <style type="text/css">
+            body { font-family: 'Ubuntu', sans-serif; }
             h3 { font-weight: normal; font-size: 1em; }
             thead th { padding-left: 1em; padding-right: 1em; }
             .category-title { text-align: right; padding-right: 2em;
-                              max-width: 25em; }
+                              max-width: 30em; font-size: 0.9em; font-weight: normal; }
             .regexp { font-size: x-small; font-weight: normal; }
             .mean { text-align: right; padding-right: 1em; }
             .median { text-align: right; padding-right: 1em; }
             .standard-deviation { text-align: right; padding-right: 1em; }
-            .histogram { padding: 0.5em 1em; width:400px; height:250px; }
+            .histogram { padding: 0.5em 1em; width:400px; height:250px; border-left: 1px dashed #000000; }
             .odd-row { background-color: #eeeeff; }
             .even-row { background-color: #ffffee; }
             table.sortable thead {
@@ -1094,12 +1213,14 @@
                 padding: 1em;
                 }
             .clickable { cursor: hand; }
-            .total-hits, .histogram, .median-sqltime,
-            .median-sqlstatements { border-right: 1px dashed #000000; }
+            .total-hits, .histogram, .category-title,
+            .median-sqltime, .median-sqlstatements {  
+                border-right: 1px dashed #000000; 
+                }
         </style>
         </head>
         <body>
-        <h1>Launchpad Page Performance Report</h1>
+        <h1>Page Performance Report</h1>
         <h3>%(date)s</h3>
         ''' % {'date': time.ctime()})