scripts/gst-plot-timeline.py

   1 #!/usr/bin/env python
   2 #
   3 # based on plot-timeline.py by Federico Mena-Quintero <federico at ximian dotcom>
   4 # example:
   5 #   GST_DEBUG_COLOR_MODE=off GST_DEBUG="*:3" gst-launch-1.0 2>debug.log audiotestsrc num-buffers=10 ! audioconvert ! alsasink
   6 #   gst-plot-timeline.py debug.log --output=debug.png
   7
   8 import math
   9 import optparse
  10 import os
  11 import re
  12 import sys
  13
  14 import cairo
  15
  16 FONT_NAME = "Bitstream Vera Sans"
  17 FONT_SIZE = 8
  18 # how many pixels for a second on the timeline
  19 PIXELS_PER_SECOND = 300
  20 # how many pixels for one line of log
  21 PIXELS_PER_LINE = 10
  22 PLOT_WIDTH = 1400
  23 TIME_SCALE_WIDTH = 20
  24 SYSCALL_MARKER_WIDTH = 20
  25 LOG_TEXT_XPOS = 400
  26 LOG_MARKER_WIDTH = 20
  27 BACKGROUND_COLOR = (0, 0, 0)
  28
  29 # assumes GST_DEBUG_LOG_COLOR=1
  30 #                             timestamp          pid  thread        level   category,file,line,msg
  31 mark_regex = re.compile (r'^(\d+:\d+:\d+\.\d+) +\d+ +0?x?[0-9a-f]+ [A-Z]+ +([-a-zA-Z0-9_]+ )(.*)')
  32 mark_timestamp_group = 1
  33 mark_program_group = 2
  34 mark_log_group = 3
  35
  36 success_result = "0"
  37
  38 skip_lines = 0
  39 max_lines = 500
  40 filter_regex = re.compile ('')
  41 skip_regex = re.compile('')
  42
  43 class BaseMark:
  44     colors = 0, 0, 0
  45     def __init__(self, timestamp, log):
  46         self.timestamp = timestamp
  47         self.log = log
  48         self.timestamp_ypos = 0
  49         self.log_ypos = 0
  50
  51 class AccessMark(BaseMark):
  52     pass
  53
  54 class LastMark(BaseMark):
  55     colors = 1.0, 0, 0
  56
  57 class FirstMark(BaseMark):
  58     colors = 1.0, 0, 0
  59
  60 class ExecMark(BaseMark):
  61 #    colors = 0.75, 0.33, 0.33
  62     colors = (1.0, 0.0, 0.0)
  63     def __init__(self, timestamp, log):
  64         BaseMark.__init__(self, timestamp,
  65                           'execve: ' + os.path.basename(log))
  66
  67 class Metrics:
  68     def __init__(self):
  69         self.width = 0
  70         self.height = 0
  71
  72 # don't use black or red
  73 palette = [
  74     (0.12, 0.29, 0.49),
  75     (0.36, 0.51, 0.71),
  76     (0.75, 0.31, 0.30),
  77     (0.62, 0.73, 0.38),
  78     (0.50, 0.40, 0.63),
  79     (0.29, 0.67, 0.78),
  80     (0.96, 0.62, 0.34)
  81     ]
  82
  83 class SyscallParser:
  84     def __init__ (self):
  85         self.syscalls = []
  86
  87     def add_line (self, str):
  88         m = mark_regex.search (str)
  89         if m:
  90             timestr = m.group (mark_timestamp_group).split(':')
  91             timestamp = float (timestr[2]) + (float (timestr[1]) * 60.0) + (float (timestr[0]) * 3600.0)
  92             program = m.group (mark_program_group)
  93             text = program + m.group (mark_log_group)
  94             if text == 'last':
  95                 self.syscalls.append (LastMark (timestamp, text))
  96             elif text == 'first':
  97                 self.syscalls.append (FirstMark (timestamp, text))
  98             else:
  99                 s = AccessMark (timestamp, text)
 100                 program_hash = program.__hash__ ()
 101                 s.colors = palette[program_hash % len (palette)]
 102                 self.syscalls.append (s)
 103         else:
 104             print 'No log in %s' % str
 105             return
 106
 107 def parse_strace(filename):
 108     parser = SyscallParser ()
 109
 110     global skip_lines
 111     global max_lines
 112     global skip_regex
 113
 114     skip_found = False
 115
 116     for line in file(filename, "r").readlines():
 117         if line == "":
 118             break
 119
 120         if not skip_found:
 121             if skip_regex.search(line):
 122                 skip_found = True
 123             else:
 124                 continue
 125
 126         if skip_lines > 0:
 127             skip_lines -= 1
 128             continue
 129
 130         if len(parser.syscalls) >= max_lines:
 131             break
 132
 133         if filter_regex.search(line):
 134             parser.add_line (line)
 135
 136     return parser.syscalls
 137
 138 def normalize_timestamps(syscalls):
 139
 140     first_timestamp = syscalls[0].timestamp
 141
 142     for syscall in syscalls:
 143         syscall.timestamp -= first_timestamp
 144
 145 def compute_syscall_metrics(syscalls):
 146     global PIXELS_PER_SECOND
 147     global PIXELS_PER_LINE
 148
 149     num_syscalls = len(syscalls)
 150
 151     metrics = Metrics()
 152     metrics.width = PLOT_WIDTH
 153
 154     last_timestamp = syscalls[num_syscalls - 1].timestamp
 155
 156     time_height = int(math.ceil(last_timestamp * PIXELS_PER_SECOND))
 157     line_height = num_syscalls * PIXELS_PER_LINE
 158
 159     if time_height > line_height:
 160         metrics.height = time_height
 161         print "Adjusting PIXELS_PER_LINE = %d" % PIXELS_PER_LINE
 162         PIXELS_PER_LINE = metrics.height / num_syscalls
 163         print "          PIXELS_PER_LINE = %d" % PIXELS_PER_LINE
 164     else:
 165         metrics.height = line_height
 166         print "Adjusting PIXELS_PER_SECOND %d" % PIXELS_PER_SECOND
 167         PIXELS_PER_SECOND = int(math.ceil(metrics.height / last_timestamp))
 168         print "          PIXELS_PER_SECOND %d" % PIXELS_PER_SECOND
 169
 170     text_ypos = 0
 171
 172     for syscall in syscalls:
 173         syscall.timestamp_ypos = syscall.timestamp * PIXELS_PER_SECOND
 174         syscall.log_ypos = text_ypos + FONT_SIZE
 175
 176         text_ypos += PIXELS_PER_LINE
 177
 178     return metrics
 179
 180 def plot_time_scale(surface, ctx, metrics):
 181     num_seconds = (metrics.height + PIXELS_PER_SECOND - 1) / PIXELS_PER_SECOND
 182
 183     ctx.set_source_rgb(0.5, 0.5, 0.5)
 184     ctx.set_line_width(1.0)
 185
 186     for i in range(num_seconds):
 187         ypos = i * PIXELS_PER_SECOND
 188
 189         ctx.move_to(0, ypos + 0.5)
 190         ctx.line_to(TIME_SCALE_WIDTH, ypos + 0.5)
 191         ctx.stroke()
 192
 193         ctx.move_to(0, ypos + 2 + FONT_SIZE)
 194         ctx.show_text("%d s" % i)
 195
 196 def plot_syscall(surface, ctx, syscall):
 197     ctx.set_source_rgb(*syscall.colors)
 198
 199     # Line
 200
 201     ctx.move_to(TIME_SCALE_WIDTH, syscall.timestamp_ypos)
 202     ctx.line_to(TIME_SCALE_WIDTH + SYSCALL_MARKER_WIDTH, syscall.timestamp_ypos)
 203     ctx.line_to(LOG_TEXT_XPOS - LOG_MARKER_WIDTH, syscall.log_ypos - FONT_SIZE / 2 + 0.5)
 204     ctx.line_to(LOG_TEXT_XPOS, syscall.log_ypos - FONT_SIZE / 2 + 0.5)
 205     ctx.stroke()
 206
 207     # Log text
 208
 209     ctx.move_to(LOG_TEXT_XPOS, syscall.log_ypos)
 210     ctx.show_text("%8.5f: %s" % (syscall.timestamp, syscall.log))
 211
 212 def plot_syscalls_to_surface(syscalls, metrics):
 213     num_syscalls = len(syscalls)
 214
 215     print 'picture size: %d x %d' % (metrics.width, metrics.height);
 216
 217     surface = cairo.ImageSurface(cairo.FORMAT_RGB24,
 218                                  metrics.width, metrics.height)
 219
 220     ctx = cairo.Context(surface)
 221     ctx.select_font_face(FONT_NAME)
 222     ctx.set_font_size(FONT_SIZE)
 223
 224     # Background
 225
 226     ctx.set_source_rgb (*BACKGROUND_COLOR)
 227     ctx.rectangle(0, 0, metrics.width, metrics.height)
 228     ctx.fill()
 229
 230     # Time scale
 231
 232     plot_time_scale(surface, ctx, metrics)
 233
 234     # Contents
 235
 236     ctx.set_line_width(1.0)
 237
 238     for syscall in syscalls:
 239         plot_syscall(surface, ctx, syscall)
 240
 241     return surface
 242
 243 def main(args):
 244
 245     global skip_lines
 246     global max_lines
 247     global filter_regex
 248     global skip_regex
 249
 250     option_parser = optparse.OptionParser(
 251         usage="usage: %prog -o output.png <debug.log>")
 252     option_parser.add_option("-o",
 253                              "--output", dest="output",
 254                              metavar="FILE",
 255                              help="Name of output file (output is a PNG file)")
 256     option_parser.add_option("-s",
 257                              "--skip", dest="skip",
 258                              metavar="LINES",
 259                              help="Skip a number of loglines at the beginning of the file or wait till a regular expression happens")
 260     option_parser.add_option("-m",
 261                              "--max-lines", dest="max",
 262                              help="max lines that need to be plotted")
 263     option_parser.add_option("-f",
 264                              "--filter", dest="filter",
 265                              help="filter the log lines on a regular expression")
 266
 267     options, args = option_parser.parse_args()
 268
 269     if not options.output:
 270         print 'Please specify an output filename with "-o file.png" or "--output=file.png".'
 271         return 1
 272
 273     if len(args) != 1:
 274         print 'Please specify only one input filename, which is an debug log taken with "GST_DEBUG_COLOR_MODE=off GST_DEBUG=XXX <application>"'
 275         return 1
 276
 277     in_filename = args[0]
 278     out_filename = options.output
 279
 280     if options.skip:
 281         try:
 282             skip_lines = int(options.skip)
 283         except:
 284             skip_regex = re.compile(options.skip)
 285             skip_lines = 0
 286
 287     if options.max:
 288         max_lines = int(options.max)
 289
 290     if options.filter:
 291         filter_regex = re.compile(options.filter)
 292
 293     syscalls = []
 294     for syscall in parse_strace(in_filename):
 295         syscalls.append(syscall)
 296         if isinstance(syscall, FirstMark):
 297             syscalls = []
 298         elif isinstance(syscall, LastMark):
 299             break
 300
 301     if not syscalls:
 302         print 'No logs in %s' % in_filename
 303         return 1
 304
 305     normalize_timestamps(syscalls)
 306     metrics = compute_syscall_metrics(syscalls)
 307
 308     surface = plot_syscalls_to_surface(syscalls, metrics)
 309     surface.write_to_png(out_filename)
 310
 311     return 0
 312
 313 if __name__ == "__main__":
 314     sys.exit(main(sys.argv))