~launchpad-pqm/launchpad/devel

# Copyright 2010 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."""

__metaclass__ = type

__all__ = ['main']

import bz2

from cgi import escape as html_quote

from ConfigParser import RawConfigParser

import copy

import cPickle

import csv

from datetime import datetime

import gzip

import math

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 canonical.config import config

from canonical.launchpad.scripts.logger import log

from lp.scripts.helpers import LPOptionParser

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

class Category:

    """A Category in our report.

    Requests belong to a Category if the URL matches a regular expression.

    """

    def __init__(self, title, regexp):

        self.title = title

        self.regexp = regexp

        self._compiled_regexp = re.compile(regexp, re.I | re.X)

        self.partition = False

    def match(self, request):

        """Return true when the request match this category."""

        return self._compiled_regexp.search(request.url) is not None

    def __cmp__(self, other):

        return cmp(self.title.lower(), other.title.lower())

    def __deepcopy__(self, memo):

        # We provide __deepcopy__ because the module doesn't handle

        # compiled regular expression by default.

        return Category(self.title, self.regexp)

class OnlineStatsCalculator:

    """Object that can compute count, sum, mean, variance and median.

    It computes these value incrementally and using minimal storage

    using the Welford / Knuth algorithm described at

    http://en.wikipedia.org/wiki/Algorithms_for_calculating_variance#On-line_algorithm

    """

    def __init__(self):

        self.count = 0

        self.sum = 0

        self.M2 = 0.0 # Sum of square difference

        self.mean = 0.0

    def update(self, x):

        """Incrementally update the stats when adding x to the set.

        None values are ignored.

        """

        if x is None:

            return

        self.count += 1

        self.sum += x

        delta = x - self.mean

        self.mean = float(self.sum)/self.count

        self.M2 += delta*(x - self.mean)

    @property

    def variance(self):

        """Return the population variance."""

        if self.count == 0:

            return 0

        else:

            return self.M2/self.count

    @property

    def std(self):

        """Return the standard deviation."""

        if self.count == 0:

            return 0

        else:

            return math.sqrt(self.variance)

    def __add__(self, other):

        """Adds this and another OnlineStatsCalculator.

        The result combines the stats of the two objects.

        """

        results = OnlineStatsCalculator()

        results.count = self.count + other.count

        results.sum = self.sum + other.sum

        if self.count > 0 and other.count > 0:

            # This is 2.1b in Chan, Tony F.; Golub, Gene H.; LeVeque,

            # Randall J. (1979), "Updating Formulae and a Pairwise Algorithm

            # for Computing Sample Variances.",

            # Technical Report STAN-CS-79-773,

            # Department of Computer Science, Stanford University,

            # ftp://reports.stanford.edu/pub/cstr/reports/cs/tr/79/773/CS-TR-79-773.pdf .

            results.M2 = self.M2 + other.M2 + (

                (float(self.count) / (other.count * results.count)) *

                ((float(other.count) / self.count) * self.sum - other.sum)**2)

        else:

            results.M2 = self.M2 + other.M2 # One of them is 0.

        if results.count > 0:

            results.mean = float(results.sum) / results.count

        return results

class OnlineApproximateMedian:

    """Approximate the median of a set of elements.

    This implements a space-efficient algorithm which only sees each value

    once. (It will hold in memory log bucket_size of n elements.)

    It was described and analysed in

    D. Cantone and  M.Hofri,

    "Analysis of An Approximate Median Selection Algorithm"

    ftp://ftp.cs.wpi.edu/pub/techreports/pdf/06-17.pdf

    This algorithm is similar to Tukey's median of medians technique.

    It will compute the median among bucket_size values. And the median among

    those.

    """

    def __init__(self, bucket_size=9):

        """Creates a new estimator.

        It approximates the median by finding the median among each

        successive bucket_size element. And then using these medians for other

        rounds of selection.

        The bucket size should be a low odd-integer.

        """

        self.bucket_size = bucket_size

        # Index of the median in a completed bucket.

        self.median_idx = (bucket_size-1)//2

        self.buckets = []

    def update(self, x, order=0):

        """Update with x."""

        if x is None:

            return

        i = order

        while True:

            # Create bucket on demand.

            if i >= len(self.buckets):

                for n in range((i+1)-len(self.buckets)):

                    self.buckets.append([])

            bucket = self.buckets[i]

            bucket.append(x)

            if len(bucket) == self.bucket_size:

                # Select the median in this bucket, and promote it.

                x = sorted(bucket)[self.median_idx]

                # Free the bucket for the next round.

                del bucket[:]

                i += 1

                continue

            else:

                break

    @property

    def median(self):

        """Return the median."""

        # Find the 'weighted' median by assigning a weight to each

        # element proportional to how far they have been selected.

        candidates = []

        total_weight = 0

        for i, bucket in enumerate(self.buckets):

            weight = self.bucket_size ** i

            for x in bucket:

                total_weight += weight

                candidates.append([x, weight])

        if len(candidates) == 0:

            return 0

        # Each weight is the equivalent of having the candidates appear

        # that number of times in the array.

        # So buckets like [[1, 2], [2, 3], [4, 2]] would be expanded to

        # [1, 2, 2, 2, 2, 2, 2, 2, 2, 2, 2, 2, 2, 3, 3, 3, 4, 4, 4, 4,

        # 4, 4, 4, 4, 4] and we find the median of that list (2).

        # We don't expand the items to conserve memory.

        median = (total_weight-1) / 2

        weighted_idx = 0

        for x, weight in sorted(candidates):

            weighted_idx += weight

            if weighted_idx > median:

                return x

    def __add__(self, other):

        """Merge two approximators together.

        All candidates from the other are merged through the standard

        algorithm, starting at the same level. So an item that went through

        two rounds of selection, will be compared with other items having

        gone through the same number of rounds.

        """

        results = OnlineApproximateMedian(self.bucket_size)

        results.buckets = copy.deepcopy(self.buckets)

        for i, bucket in enumerate(other.buckets):

            for x in bucket:

                results.update(x, i)

        return results

class Stats:

    """Bag to hold and compute request statistics.

    All times are in seconds.

    """

    total_hits = 0 # Total hits.

    total_time = 0 # Total time spent rendering.

    mean = 0 # Mean time per hit.

    median = 0 # Median time per hit.

    std = 0 # Standard deviation per hit.

    histogram = None # # Request times histogram.

    total_sqltime = 0 # Total time spent waiting for SQL to process.

    mean_sqltime = 0 # Mean time spend waiting for SQL to process.

    median_sqltime = 0 # Median time spend waiting for SQL to process.

    std_sqltime = 0 # Standard deviation of SQL time.

    total_sqlstatements = 0 # Total number of SQL statements issued.

    mean_sqlstatements = 0

    median_sqlstatements = 0

    std_sqlstatements = 0

    @property

    def ninetyninth_percentile_time(self):

        """Time under which 99% of requests are rendered.

        This is estimated as 3 std deviations from the mean. Given that

        in a daily report, many URLs or PageIds won't have 100 requests, it's

        more useful to use this estimator.

        """

        return self.mean + 3*self.std

    @property

    def ninetyninth_percentile_sqltime(self):

        """SQL time under which 99% of requests are rendered.

        This is estimated as 3 std deviations from the mean.

        """

        return self.mean_sqltime + 3*self.std_sqltime

    @property

    def ninetyninth_percentile_sqlstatements(self):

        """Number of SQL statements under which 99% of requests are rendered.

        This is estimated as 3 std deviations from the mean.

        """

        return self.mean_sqlstatements + 3*self.std_sqlstatements

    def text(self):

        """Return a textual version of the stats."""

        return textwrap.dedent("""

        <Stats for %d requests:

            Time:     total=%.2f; mean=%.2f; median=%.2f; std=%.2f

            SQL time: total=%.2f; mean=%.2f; median=%.2f; std=%.2f

            SQL stmt: total=%.f;  mean=%.2f; median=%.f; std=%.2f

            >""" % (

                self.total_hits, self.total_time, self.mean, self.median,

                self.std, self.total_sqltime, self.mean_sqltime,

                self.median_sqltime, self.std_sqltime,

                self.total_sqlstatements, self.mean_sqlstatements,

                self.median_sqlstatements, self.std_sqlstatements))

class OnlineStats(Stats):

    """Implementation of stats that can be computed online.

    You call update() for each request and the stats are updated incrementally

    with minimum storage space.

    """

    def __init__(self, histogram_width, histogram_resolution):

        self.time_stats = OnlineStatsCalculator()

        self.time_median_approximate = OnlineApproximateMedian()

        self.sql_time_stats = OnlineStatsCalculator()

        self.sql_time_median_approximate = OnlineApproximateMedian()

        self.sql_statements_stats = OnlineStatsCalculator()

        self.sql_statements_median_approximate = OnlineApproximateMedian()

        self.histogram = Histogram(histogram_width, histogram_resolution)

    @property

    def total_hits(self):

        return self.time_stats.count

    @property

    def total_time(self):

        return self.time_stats.sum

    @property

    def mean(self):

        return self.time_stats.mean

    @property

    def median(self):

        return self.time_median_approximate.median

    @property

    def std(self):

        return self.time_stats.std

    @property

    def total_sqltime(self):

        return self.sql_time_stats.sum

    @property

    def mean_sqltime(self):

        return self.sql_time_stats.mean

    @property

    def median_sqltime(self):

        return self.sql_time_median_approximate.median

    @property

    def std_sqltime(self):

        return self.sql_time_stats.std

    @property

    def total_sqlstatements(self):

        return self.sql_statements_stats.sum

    @property

    def mean_sqlstatements(self):

        return self.sql_statements_stats.mean

    @property

    def median_sqlstatements(self):

        return self.sql_statements_median_approximate.median

    @property

    def std_sqlstatements(self):

        return self.sql_statements_stats.std

    def update(self, request):

        """Update the stats based on request."""

        self.time_stats.update(request.app_seconds)

        self.time_median_approximate.update(request.app_seconds)

        self.sql_time_stats.update(request.sql_seconds)

        self.sql_time_median_approximate.update(request.sql_seconds)

        self.sql_statements_stats.update(request.sql_statements)

        self.sql_statements_median_approximate.update(request.sql_statements)

        self.histogram.update(request.app_seconds)

    def __add__(self, other):

        """Merge another OnlineStats with this one."""

        results = copy.deepcopy(self)

        results.time_stats += other.time_stats

        results.time_median_approximate += other.time_median_approximate

        results.sql_time_stats += other.sql_time_stats

        results.sql_time_median_approximate += (

            other.sql_time_median_approximate)

        results.sql_statements_stats += other.sql_statements_stats

        results.sql_statements_median_approximate += (

            other.sql_statements_median_approximate)

        results.histogram = self.histogram + other.histogram

        return results

class Histogram:

    """A simple object to compute histogram of a value."""

    @staticmethod

    def from_bins_data(data):

        """Create an histogram from existing bins data."""

        assert data[0][0] == 0, "First bin should start at zero."

        hist = Histogram(len(data), data[1][0])

        for idx, bin in enumerate(data):

            hist.count += bin[1]

            hist.bins[idx][1] = bin[1]

        return hist

    def __init__(self, bins_count, bins_size):

        """Create a new histogram.

        The histogram will count the frequency of values in bins_count bins

        of bins_size each.

        """

        self.count = 0

        self.bins_count = bins_count

        self.bins_size = bins_size

        self.bins = []

        for x in range(bins_count):

            self.bins.append([x*bins_size, 0])

    @property

    def bins_relative(self):

        """Return the bins with the frequency expressed as a ratio."""

        return [[x, float(f)/self.count] for x, f in self.bins]

    def update(self, value):

        """Update the histogram for this value.

        All values higher than the last bin minimum are counted in that last

        bin.

        """

        self.count += 1

        idx = int(min(self.bins_count-1, value / self.bins_size))

        self.bins[idx][1] += 1

    def __repr__(self):

        """A string representation of this histogram."""

        return "<Histogram %s>" % self.bins

    def __eq__(self, other):

        """Two histogram are equals if they have the same bins content."""

        if not isinstance(other, Histogram):

            return False

        if self.bins_count != other.bins_count:

            return False

        if self.bins_size != other.bins_size:

            return False

        for idx, other_bin in enumerate(other.bins):

            if self.bins[idx][1] != other_bin[1]:

                return False

        return True

    def __add__(self, other):

        """Add the frequency of the other histogram to this one.

        The resulting histogram has the same bins_size than this one.

        If the other one has a bigger bins_size, we'll assume an even

        distribution and distribute the frequency across the smaller bins. If

        it has a lower bin_size, we'll aggregate its bins into the larger

        ones. We only support different bins_size if the ratio can be

        expressed as the ratio between 1 and an integer.

        The resulting histogram is as wide as the widest one.

        """

        ratio = float(other.bins_size) / self.bins_size

        bins_count = max(self.bins_count, math.ceil(other.bins_count * ratio))

        total = Histogram(int(bins_count), self.bins_size)

        total.count = self.count + other.count

        # Copy our bins into the total

        for idx, bin in enumerate(self.bins):

            total.bins[idx][1] = bin[1]

        assert int(ratio) == ratio or int(1/ratio) == 1/ratio, (

            "We only support different bins size when the ratio is an "

            "integer to 1: "

            % ratio)

        if ratio >= 1:

            # We distribute the frequency across the bins.

            # For example. if the ratio is 3:1, we'll add a third

            # of the lower resolution bin to 3 of the higher one.

            for other_idx, bin in enumerate(other.bins):

                f = bin[1] / ratio

                start = int(math.floor(other_idx * ratio))

                end = int(start + ratio)

                for idx in range(start, end):

                    total.bins[idx][1] += f

        else:

            # We need to collect the higher resolution bins into the

            # corresponding lower one.

            for other_idx, bin in enumerate(other.bins):

                idx = int(other_idx * ratio)

                total.bins[idx][1] += bin[1]

        return total

class RequestTimes:

    """Collect statistics from requests.

    Statistics are updated by calling the add_request() method.

    Statistics for mean/stddev/total/median for request times, SQL times and

    number of SQL statements are collected.

    They are grouped by Category, URL or PageID.

    """

    def __init__(self, categories, options):

        self.by_pageids = options.pageids

        self.top_urls = options.top_urls

        # We only keep in memory 50 times the number of URLs we want to

        # return. The number of URLs can go pretty high (because of the

        # distinct query parameters).

        #

        # Keeping all in memory at once is prohibitive. On a small but

        # representative sample, keeping 50 times the possible number of

        # candidates and culling to 90% on overflow, generated an identical

        # report than keeping all the candidates in-memory.

        #

        # Keeping 10 times or culling at 90% generated a near-identical report

        # (it differed a little in the tail.)

        #

        # The size/cull parameters might need to change if the requests

        # distribution become very different than what it currently is.

        self.top_urls_cache_size = self.top_urls * 50

        # Histogram has a bin per resolution up to our timeout

        #(and an extra bin).

        self.histogram_resolution = float(options.resolution)

        self.histogram_width = int(

            options.timeout / self.histogram_resolution) + 1

        self.category_times = [

            (category, OnlineStats(

                self.histogram_width, self.histogram_resolution))

            for category in categories]

        self.url_times = {}

        self.pageid_times = {}

    def add_request(self, request):

        """Add request to the set of requests we collect stats for."""

        matched = []

        for category, stats in self.category_times:

            if category.match(request):

                stats.update(request)

                if category.partition:

                    matched.append(category.title)

        if len(matched) > 1:

            log.warning(

                "Multiple partition categories matched by %s (%s)",

                request.url, ", ".join(matched))

        elif not matched:

            log.warning("%s isn't part of the partition", request.url)

        if self.by_pageids:

            pageid = request.pageid or 'Unknown'

            stats = self.pageid_times.setdefault(

                pageid, OnlineStats(

                    self.histogram_width, self.histogram_resolution))

            stats.update(request)

        if self.top_urls:

            stats = self.url_times.setdefault(

                request.url, OnlineStats(

                    self.histogram_width, self.histogram_resolution))

            stats.update(request)

            #  Whenever we have more URLs than we need to, discard 10%

            # that is less likely to end up in the top.

            if len(self.url_times) > self.top_urls_cache_size:

                cutoff = int(self.top_urls_cache_size*0.90)

                self.url_times = dict(

                    sorted(self.url_times.items(),

                    key=lambda (url, stats): stats.total_time,

                    reverse=True)[:cutoff])

    def get_category_times(self):

        """Return the times for each category."""

        return self.category_times

    def get_top_urls_times(self):

        """Return the times for the Top URL by total time"""

        # Sort the result by total time

        return sorted(

            self.url_times.items(),

            key=lambda (url, stats): stats.total_time,

            reverse=True)[:self.top_urls]

    def get_pageid_times(self):

        """Return the times for the pageids."""

        # Sort the result by pageid

        return sorted(self.pageid_times.items())

    def __add__(self, other):

        """Merge two RequestTimes together."""

        results = copy.deepcopy(self)

        for other_category, other_stats in other.category_times:

            for i, (category, stats) in enumerate(self.category_times):

                if category.title == other_category.title:

                    results.category_times[i] = (

                        category, stats + other_stats)

                    break

            else:

                results.category_times.append(

                    (other_category, copy.deepcopy(other_stats)))

        url_times = results.url_times

        for url, stats in other.url_times.items():

            if url in url_times:

                url_times[url] += stats

            else:

                url_times[url] = copy.deepcopy(stats)

        # Only keep top_urls_cache_size entries.

        if len(self.url_times) > self.top_urls_cache_size:

            self.url_times = dict(

                sorted(

                    url_times.items(),

                    key=lambda (url, stats): stats.total_time,

                    reverse=True)[:self.top_urls_cache_size])

        pageid_times = results.pageid_times

        for pageid, stats in other.pageid_times.items():

            if pageid in pageid_times:

                pageid_times[pageid] += stats

            else:

                pageid_times[pageid] = copy.deepcopy(stats)

        return results

def main():

    parser = LPOptionParser("%prog [args] tracelog [...]")

    parser.add_option(

        "-c", "--config", dest="config",

        default=os.path.join(

            config.root, "utilities", "page-performance-report.ini"),

        metavar="FILE", help="Load configuration from FILE")

    parser.add_option(

        "--from", dest="from_ts", type="datetime",

        default=None, metavar="TIMESTAMP",

        help="Ignore log entries before TIMESTAMP")

    parser.add_option(

        "--until", dest="until_ts", type="datetime",

        default=None, metavar="TIMESTAMP",

        help="Ignore log entries after TIMESTAMP")

    parser.add_option(

        "--no-partition", dest="partition",

        action="store_false", default=True,

        help="Do not produce partition report")

    parser.add_option(

        "--no-categories", dest="categories",

        action="store_false", default=True,

        help="Do not produce categories report")

    parser.add_option(

        "--no-pageids", dest="pageids",

        action="store_false", default=True,

        help="Do not produce pageids report")

    parser.add_option(

        "--top-urls", dest="top_urls", type=int, metavar="N",

        default=50, help="Generate report for top N urls by hitcount.")

    parser.add_option(

        "--directory", dest="directory",

        default=os.getcwd(), metavar="DIR",

        help="Output reports in DIR directory")

    parser.add_option(

        "--timeout", dest="timeout",

        # Default to 9: our production timeout.

        default=9, type="int", metavar="SECONDS",

        help="The configured timeout value: used to determine high risk " +

        "page ids. That would be pages which 99% under render time is "

        "greater than timeoout - 2s. Default is %defaults.")

    parser.add_option(

        "--histogram-resolution", dest="resolution",

        # Default to 0.5s

        default=0.5, type="float", metavar="SECONDS",

        help="The resolution of the histogram bin width. Detault to "

        "%defaults.")

    parser.add_option(