PixelData tile performance log parsing script

tileperf.py

#!/usr/bin/env python
# encoding: utf-8

"""
Performs various performance metrics and reports on PixelData log files.
"""

# Copyright (C) 2011 University of Dundee

# This program is free software; you can redistribute it and/or
# modify it under the terms of the GNU General Public License
# as published by the Free Software Foundation; either version 2
# of the License, or (at your option) any later version.

# This program is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
# GNU General Public License for more details.

# You should have received a copy of the GNU General Public License
# along with this program; if not, write to the Free Software
# Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301, USA.

from __future__ import division
import re
import os
import sys

import mx.DateTime as DateTime
from mx.DateTime import DateTimeDelta
from getopt import getopt, GetoptError

def usage(error):
    """Prints usage so that we don't have to. :)"""
    cmd = sys.argv[0]
    print """%s
Usage: %s [options...] <log_file>
Generate performance metrics from a PixelData log file.

Options:
  --help              Display this help and exit

Examples:
  %s PixelData-0.log

Report bugs to [email protected]""" % \
        (error, cmd, cmd)
    sys.exit(2)

class ParsingError(Exception):
    """Raised whenever there is an error parsing a log file."""
    pass

class PixelDataLog(object):
    """
    Parses and stores context from a PixelData log file. It also has
    the capability of producing various reports.
    """

    # 2012-01-25 12:27:04,701 INFO  [                ome.io.nio.PixelsService] (2-thread-1) Creating BfPixelBuffer: /OMERO/Files/152 Series: 2
    # Regular expression for matching log4j log lines
    log_regex = re.compile(
            '^(?P<date_time>\S+\s+\S+)\s+(?P<level>\S+)\s+' \
            '(?P<class>\[.*?\])\s+(?P<thread>\(\S+\))\s+' \
            '(?P<message>.*)$')

    # Regular expression for matching possible PixelData tile status messages
    status_regex = re.compile('^Pyramid creation for Pixels:' \
            '(?P<pixels_id>\d+)\s+(?P<progress>\d+)\/(?P<total>\d+)')

    # Format string for matching log4j date/time strings
    date_time_fmt = '%Y-%m-%d %H:%M:%S'

    def __init__(self, log_file):
        self.log_file = log_file
        self.data = dict()
    
    def parse(self):
        """Parses the specified log file."""
        line_no = 1
        for line in self.log_file:
            match = self.log_regex.match(line)
            if match:
                self.handle_match(match)
            line_no += 1

    def handle_match(self, match):
        """Handles cases where the log_regex is matched."""
        message = match.group('message')
        status_match = self.status_regex.match(message)
        if not status_match:
            return
        date_time = match.group('date_time')
        date_time, ms = date_time.split(',')
        date_time = DateTime.strptime(date_time, self.date_time_fmt)
        ms = DateTimeDelta(0, 0, 0, int(ms) / 1000.0)
        date_time = date_time + ms
        pixels_id = long(status_match.group('pixels_id'))
        progress = long(status_match.group('progress'))
        total = long(status_match.group('total'))
        if pixels_id not in self.data:
            self.data[pixels_id] = list()
        self.data[pixels_id].append((date_time, progress, total))

    def elapsed(self, start, end):
        if start is not None and end is not None:
            return str((end - start).seconds) + "sec"
        return 'Unknown'

    def report(self):
        for pixels_id, data in self.data.items():
            progress = 0
            last_timestamp = data[0][0]
            tiles_per_sec = list()
            for v in data[1:]:
                current_progress = v[1] - progress
                elapsed = (v[0] - last_timestamp).seconds
                tiles_per_sec.append(current_progress / elapsed)
                last_timestamp = v[0]
                progress = v[1]
            for v in tiles_per_sec:
                print 'Pixels:%d -- %s tiles per second' % (pixels_id, v)

if __name__ == "__main__":
    try:
        options, args = getopt(sys.argv[1:], "", ['help'])
    except GetoptError, (msg, opt):
        usage(msg)

    try:
        log_file, = args
    except ValueError:
        usage('Must specify at least one log file.')
    log = PixelDataLog(open(log_file))

    for option, argument in options:
        if option == '--help':
            usage('')
    log.parse()
    log.report()