plot-timeline.py

#!/usr/bin/env python3

import math
import optparse
import os
import re
import sys
import cairo

FONT_NAME = "Bitstream Vera Sans"
FONT_SIZE = 10
PIXELS_PER_SECOND = 1000
PIXELS_PER_LINE = 12
PLOT_WIDTH = 1400
TIME_SCALE_WIDTH = 20
SYSCALL_MARKER_WIDTH = 20
LOG_TEXT_XPOS = 300
LOG_MARKER_WIDTH = 20
BACKGROUND_COLOR = (0, 0, 0)

# list of strings to ignore in the plot
ignore_strings = [
#    "nautilus_directory_async_state_changed"
    ]

# list of pairs ("string", (r, g, b)) to give a special color to some strings
special_colors = [
    ("nautilus_window_size_allocate", (1, 1, 1)),
    ("STARTING MAIN LOOP", (1, 0, 0)),
    ("directory_load_callback", (1, 1, 0)),
    ("nautilus_directory_new", (1, 1, 0)),
    ("nautilus_directory_async_state_changed", (1, 1, 0)),
    ("fm-directory-view.c: finish_loading", (1, 0.5, 0)),
    ("fm-directory-view.c", (1, 1, 0)),
    ("fm_icon_view_begin_loading", (1, 0, 1)),
    ("location_has_really_changed", (1, 0, 1)),
    ("update_for_new_location", (1, 0, 1)),
    ("expose_event", (0, 1, 1)),
    ("fm_icon_view_add_file", (0, 1, 1)),
    ]

def get_special_color (string):
    for sc in special_colors:
        if string.find (sc[0]) >= 0:
            return sc[1]

    return None

def string_has_substrings (string, substrings):
    for i in substrings:
        if string.find (i) >= 0:
            return True

    return False

# basic (non-strace) format
# Example:
# doozerd: store 18:53:24.599973 store.go:266: apply set 4 /doozer/slot/1 a0019c85.9ac8ceaa 4 <nil>
doozer_regex = re.compile (r'^doozerd:.*(\d+):(\d+):(\d+.\d+) +(.*)')
doozer_hour_group = 1
doozer_min_group  = 2
doozer_sec_group  = 3
doozer_log_group  = 4

# assumes "strace -ttt -f"
mark_regex = re.compile (r'^\d+ +(\d+\.\d+) +access\("MARK: ([^:]*: )(.*)", F_OK.*')
mark_timestamp_group = 1
mark_program_group = 2
mark_log_group = 3

# 3273  1141862703.998196 execve("/usr/bin/dbus-launch", ["/usr/bin/dbus-launch", "--sh-syntax", "--exit-with-session", "/usr/X11R6/bin/gnome"], [/* 61 vars */]) = 0
# 3275  1141862704.003623 execve("/home/devel/bin/dbus-daemon", ["dbus-daemon", "--fork", "--print-pid", "8", "--print-address", "6", "--session"], [/* 61 vars */]) = -1 ENOENT (No such file or directory)
complete_exec_regex = re.compile (r'^(\d+) +(\d+\.\d+) +execve\("(.*)", \[".*= (0|-1 ENOENT \(No such file or directory\))$')
complete_exec_pid_group = 1
complete_exec_timestamp_group = 2
complete_exec_command_group = 3
complete_exec_result_group = 4

# 3283  1141862704.598008 execve("/opt/gnome/lib/GConf/2/gconf-sanity-check-2", ["/opt/gnome/lib/GConf/2/gconf-san"...], [/* 66 vars */] <unfinished ...>
unfinished_exec_regex = re.compile (r'^(\d+) +(\d+\.\d+) +execve\("(.*)", \[".*<unfinished \.\.\.>$')
unfinished_exec_pid_group = 1
unfinished_exec_timestamp_group = 2
unfinished_exec_command_group = 3

# 3283  1141862704.598704 <... execve resumed> ) = 0
# 3309  1141862707.027481 <... execve resumed> ) = -1 ENOENT (No such file or directory)
resumed_exec_regex = re.compile (r'^(\d+) +(\d+\.\d+) +<\.\.\. execve resumed.*= (0|-1 ENOENT \(No such file or directory\))$')
resumed_exec_pid_group = 1
resumed_exec_timestamp_group = 2
resumed_exec_result_group = 3

success_result = "0"

class BaseMark:
    colors = 0, 0, 0
    def __init__(self, timestamp, log):
        self.timestamp = timestamp
        self.log = log
        self.timestamp_ypos = 0
        self.log_ypos = 0

class SimpleMark(BaseMark):
    colors = 1.0, 0, 0
    pass

class AccessMark(BaseMark):
    pass

class LastMark(BaseMark):
    colors = 1.0, 0, 0

class FirstMark(BaseMark):
    colors = 1.0, 0, 0

class ExecMark(BaseMark):
#    colors = 0.75, 0.33, 0.33
    colors = (1.0, 0.0, 0.0)
    def __init__(self, timestamp, log, is_complete, is_resumed):
#        if is_complete:
        text = 'execve: '
#        elif is_resumed:
#            text = 'execve resumed: '
#        else:
#            text = 'execve started: '

        text = text + os.path.basename(log)
        BaseMark.__init__(self, timestamp, text)

class Metrics:
    def __init__(self):
        self.width = 0
        self.height = 0

# don't use black or red
palette = [
    (0.12, 0.29, 0.49),
    (0.36, 0.51, 0.71),
    (0.75, 0.31, 0.30),
    (0.62, 0.73, 0.38),
    (0.50, 0.40, 0.63),
    (0.29, 0.67, 0.78),
    (0.96, 0.62, 0.34),
    (1.0 - 0.12, 1.0 - 0.29, 1.0 - 0.49),
    (1.0 - 0.36, 1.0 - 0.51, 1.0 - 0.71),
    (1.0 - 0.75, 1.0 - 0.31, 1.0 - 0.30),
    (1.0 - 0.62, 1.0 - 0.73, 1.0 - 0.38),
    (1.0 - 0.50, 1.0 - 0.40, 1.0 - 0.63),
    (1.0 - 0.29, 1.0 - 0.67, 1.0 - 0.78),
    (1.0 - 0.96, 1.0 - 0.62, 1.0 - 0.34)
    ]

class SyscallParser:
    def __init__ (self):
        self.pending_execs = []
        self.syscalls = []

    def search_pending_execs (self, search_pid):
        n = len (self.pending_execs)
        for i in range (n):
            (pid, timestamp, command) = self.pending_execs[i]
            if pid == search_pid:
                return (i, timestamp, command)

        return (None, None, None)

    def add_line (self, str):
        m = doozer_regex.search (str)
        if m:
            H = int (m.group(doozer_hour_group))
            M = int (m.group(doozer_min_group))
            S = float (m.group(doozer_sec_group))

            timestamp = (H*3600)+(M*60)+(S)
            command = m.group (doozer_log_group)
            self.syscalls.append (SimpleMark (timestamp, command))

            return

        m = mark_regex.search (str)
        if m:
            timestamp = float (m.group (mark_timestamp_group))
            program = m.group (mark_program_group)
            text = program + m.group (mark_log_group)
            if text == 'last':
                self.syscalls.append (LastMark (timestamp, text))
            elif text == 'first':
                self.syscalls.append (FirstMark (timestamp, text))
            else:
#                if program == "nautilus: ":
                if not string_has_substrings (text, ignore_strings):
                    s = AccessMark (timestamp, text)
                    c = get_special_color (text)
                    if c:
                        s.colors = c
                    else:
                        program_hash = program.__hash__ ()
                        s.colors = palette[program_hash % len (palette)]

                    self.syscalls.append (s)

            return

        m = complete_exec_regex.search (str)
        if m:
            result = m.group (complete_exec_result_group)
            if result == success_result:
                pid = m.group (complete_exec_pid_group)
                timestamp = float (m.group (complete_exec_timestamp_group))
                command = m.group (complete_exec_command_group)
                self.syscalls.append (ExecMark (timestamp, command, True, False))

            return

        m = unfinished_exec_regex.search (str)
        if m:
            pid = m.group (unfinished_exec_pid_group)
            timestamp = float (m.group (unfinished_exec_timestamp_group))
            command = m.group (unfinished_exec_command_group)
            self.pending_execs.append ((pid, timestamp, command))
#            self.syscalls.append (ExecMark (timestamp, command, False, False))
            return

        m = resumed_exec_regex.search (str)
        if m:
            pid = m.group (resumed_exec_pid_group)
            timestamp = float (m.group (resumed_exec_timestamp_group))
            result = m.group (resumed_exec_result_group)

            (index, old_timestamp, command) = self.search_pending_execs (pid)
            if index == None:
                print("Didn't find pid %s in pending_execs!" % pid)
                sys.exit (1)

            del self.pending_execs[index]

            if result == success_result:
                self.syscalls.append (ExecMark (timestamp, command, False, True))

def parse_strace(filename):
    parser = SyscallParser ()

    for line in open(filename, "r").readlines():
        if line == "":
            break

        parser.add_line (line)

    return parser.syscalls

def normalize_timestamps(syscalls):

    first_timestamp = syscalls[0].timestamp

    for syscall in syscalls:
        syscall.timestamp -= first_timestamp

def compute_syscall_metrics(syscalls):
    num_syscalls = len(syscalls)

    metrics = Metrics()
    metrics.width = PLOT_WIDTH

    last_timestamp = syscalls[num_syscalls - 1].timestamp
    num_seconds = int(math.ceil(last_timestamp))
    metrics.height = max(num_seconds * PIXELS_PER_SECOND,
                         num_syscalls * PIXELS_PER_LINE)

    text_ypos = 0

    for syscall in syscalls:
        syscall.timestamp_ypos = syscall.timestamp * PIXELS_PER_SECOND
        syscall.log_ypos = text_ypos + FONT_SIZE

        text_ypos += PIXELS_PER_LINE

    return metrics

def plot_time_scale(surface, ctx, metrics):
    num_seconds = int((metrics.height + PIXELS_PER_SECOND - 1) / PIXELS_PER_SECOND)

    ctx.set_source_rgb(0.5, 0.5, 0.5)
    ctx.set_line_width(1.0)

    for i in range(num_seconds):
        ypos = i * PIXELS_PER_SECOND

        ctx.move_to(0, ypos + 0.5)
        ctx.line_to(TIME_SCALE_WIDTH, ypos + 0.5)
        ctx.stroke()

        ctx.move_to(0, ypos + 2 + FONT_SIZE)
        ctx.show_text("%d s" % i)

def plot_syscall(surface, ctx, syscall):
    ctx.set_source_rgb(*syscall.colors)

    # Line

    ctx.move_to(TIME_SCALE_WIDTH, syscall.timestamp_ypos)
    ctx.line_to(TIME_SCALE_WIDTH + SYSCALL_MARKER_WIDTH, syscall.timestamp_ypos)
    ctx.line_to(LOG_TEXT_XPOS - LOG_MARKER_WIDTH, syscall.log_ypos - FONT_SIZE / 2 + 0.5)
    ctx.line_to(LOG_TEXT_XPOS, syscall.log_ypos - FONT_SIZE / 2 + 0.5)
    ctx.stroke()

    # Log text

    ctx.move_to(LOG_TEXT_XPOS, syscall.log_ypos)
    ctx.show_text("%8.5f: %s" % (syscall.timestamp, syscall.log))

def plot_syscalls_to_surface(syscalls, metrics):
    num_syscalls = len(syscalls)

    surface = cairo.ImageSurface(cairo.FORMAT_RGB24,
                                 metrics.width, metrics.height)

    ctx = cairo.Context(surface)
    ctx.select_font_face(FONT_NAME)
    ctx.set_font_size(FONT_SIZE)

    # Background

    ctx.set_source_rgb (*BACKGROUND_COLOR)
    ctx.rectangle(0, 0, metrics.width, metrics.height)
    ctx.fill()

    # Time scale

    plot_time_scale(surface, ctx, metrics)

    # Contents

    ctx.set_line_width(1.0)

    for syscall in syscalls:
        plot_syscall(surface, ctx, syscall)

    return surface

def main(args):
    option_parser = optparse.OptionParser(
        usage="usage: %prog -o output.png <strace.txt>")
    option_parser.add_option("-o",
                             "--output", dest="output",
                             metavar="FILE",
                             help="Name of output file (output is a PNG file)")

    options, args = option_parser.parse_args()

    if not options.output:
        print('Please specify an output filename with "-o file.png" or "--output=file.png".')
        return 1

    if len(args) != 1:
        print('Please specify only one input filename, which is an strace log taken with "strace -ttt -f"')
        return 1

    in_filename = args[0]
    out_filename = options.output

    syscalls = []
    for syscall in parse_strace(in_filename):
        syscalls.append(syscall)
        if isinstance(syscall, FirstMark):
            syscalls = []
        elif isinstance(syscall, LastMark):
            break

    if not syscalls:
        print('No marks in %s, add access("MARK: ...", F_OK)' % in_filename)
        return 1

    normalize_timestamps(syscalls)
    metrics = compute_syscall_metrics(syscalls)

    surface = plot_syscalls_to_surface(syscalls, metrics)
    surface.write_to_png(out_filename)

    return 0

if __name__ == "__main__":
    sys.exit(main(sys.argv))