l4/pkg/plr/tools/tsar/tsar

   1 #!/usr/bin/python
   2 # -*- coding: iso-8859-1 -*-
   3 #vi: ft=python
   4 #
   5 # TSAR - Trace Sequence AnalyzeR
   6 #        *     *        *      *
   7 # Tool to extract and analyze Romain event logs
   8 #
   9 # (c) 2012-2013 Björn Döbel <doebel@os.inf.tu-dresden.de>,
  10 #     economic rights: Technische Universität Dresden (Germany)
  11 #
  12 #  This file is part of TUD:OS and distributed under the terms of the
  13 #  GNU General Public License 2.
  14 #  Please see the COPYING-GPL-2 file for details.
  15
  16 import gzip
  17 import operator
  18 import os
  19 import re
  20 import sys
  21 import struct
  22 import tempfile
  23 import uu
  24
  25 import tsar_events
  26 import tsar_rules
  27
  28 #pylint: disable=C0103,R0903
  29
  30
  31 class EventFactory:
  32     """Event factory: random access to Event objects
  33        based on an underlying trace reader."""
  34
  35     def __init__(self, traceReader):
  36         self.reader = traceReader
  37         self.input = traceReader.raw_read()
  38         self.offset = 0
  39         self.idpfx = traceReader.prefix()
  40
  41         self.eventCount = len(self.input) / tsar_events.Event.EVENTSIZE
  42         #print self.idpfx
  43
  44     def uid(self, utcb):
  45         return "%s:%x" % (self.idpfx, utcb)
  46
  47     def reset(self):
  48         self.offset = 0
  49
  50     def print_status(self):
  51         sys.stderr.write("\033[34;46m\033[s%s: %8d / %8d\033[u" %
  52                          (self.reader.zipFile.name, self.offset,
  53                          self.eventCount))
  54
  55     def _build(self, start):
  56         """Get the Event object in the input stream
  57            at the given position"""
  58
  59         if start >= len(self.input):
  60             return None
  61
  62         eventTypes = [
  63             tsar_events.Event,
  64             tsar_events.SyscallEvent,
  65             tsar_events.PagefaultEvent,
  66             tsar_events.SwifiEvent,
  67             tsar_events.FooEvent,
  68             tsar_events.TrapEvent,
  69             tsar_events.ThreadStartEvent,
  70             tsar_events.ThreadStopEvent,
  71             tsar_events.LockingEvent,
  72             tsar_events.SHMLockingEvent,
  73             tsar_events.BarnesEvent,
  74         ]
  75
  76         #print "Input: %d bytes" % len(self.input)
  77
  78         (tsc, utcb, typ) = struct.unpack_from("QIB", self.input[start:])
  79         if (utcb == 0):
  80             return None
  81
  82         #print typ, self.uid(utcb)
  83
  84         try:
  85             return eventTypes[typ](self.input[start:], tsc, utcb,
  86                                    self.uid(utcb))
  87         except IndexError:
  88             print "Index error with event type %d" % typ
  89             sys.exit(1)
  90
  91     def nextEvent(self):
  92         """Get the next event in stream
  93
  94         Allows iterating over the stream."""
  95         start = self.offset * tsar_events.Event.EVENTSIZE
  96         if (self.offset % 1000 == 0) or (self.offset == self.eventCount):
  97             self.print_status()
  98
  99         self.offset += 1
 100         return self._build(start)
 101
 102     def eventAtOffset(self, offset):
 103         """Get event at a specified offset.
 104
 105         Random access to the stream."""
 106         start = offset * tsar_events.Event.EVENTSIZE
 107         return self._build(start)
 108
 109
 110 class TraceReader:
 111     """Reader for zipped uu-encoded data"""
 112
 113     def __init__(self, logfile):
 114         #tmp = tempfile.NamedTemporaryFile(mode="w+b")
 115         # XXX also print UID here
 116         tmp = file(logfile.readlines()[0].strip().split(" ")[2], "wb")
 117         sys.stderr.write("UUDecoding %s -> %s\n" % (logfile.name, tmp.name))
 118         logfile.seek(0)
 119         uu.decode(logfile.name, tmp.name)
 120         self.zipFile = gzip.open(tmp.name)
 121
 122         self.pfx = tmp.name.split(".")[0]
 123
 124     def prefix(self):
 125         return self.pfx
 126
 127     def raw_read(self):
 128         """Read the raw bytes from the underlying stream
 129            into a string."""
 130         decomp = ""
 131         bytes = self.zipFile.read(1024)
 132         while bytes != "":
 133             decomp += bytes
 134             bytes = self.zipFile.read(1024)
 135         sys.stderr.write("Read %d bytes.\n" % len(decomp))
 136
 137         return decomp
 138
 139
 140 class EventList:
 141     """
 142     Raw list of events from potentially multiple event stream sources
 143     """
 144     def __init__(self):
 145         self.streams = []
 146         self.stream_index = 0
 147
 148     def addStream(self, eventFactory):
 149         """Add another stream to the event sources"""
 150         self.streams += [eventFactory]
 151
 152     def reset(self):
 153         """Reset the event list"""
 154         for s in self.streams:
 155             s.reset()
 156         self.stream_index = 0
 157
 158     def next(self):
 159         """Return the next event.
 160
 161         Continuously calling this function iterates over the associated
 162         streams one at a time. Returns 'None' if no more events are to
 163         be found
 164         """
 165
 166         if self.stream_index >= len(self.streams):
 167             return None
 168
 169         ev = self.streams[self.stream_index].nextEvent()
 170
 171         if ev is None:
 172             sys.stderr.write("\033[0m\n")
 173             self.stream_index += 1
 174             return self.next()
 175
 176         return ev
 177
 178
 179 def print_plain(events):
 180     """Plain dump of an event list"""
 181     for e in events:
 182         print e
 183
 184
 185 def print_pretty(events):
 186     """Pretty-printed event list.
 187
 188     Prints a table. First column is a time stamp. Every other
 189     colunm represents one distinct replica
 190     """
 191     ids = []
 192     last_ts = 0
 193
 194     # first run to determine UTCB IDs
 195     for e in events:
 196         if e.type != 0 and e.uid() not in ids:
 197             ids += [e.uid()]
 198     ids.sort()
 199
 200     # header
 201     print "\033[32m%14s" % "Timestamp",
 202     for i in ids:
 203         print "| %20s" % ("UID %s" % i[0:16]),
 204     print "\033[0m"
 205
 206     # printing run
 207     for e in events:
 208         if e.type == 0:
 209             continue
 210
 211         # Uncomment if you need horizontal separators between events
 212         #print "." * 14,
 213         #for i in range(len(ids)):
 214         #    print "|",
 215         #    print "." * 20,
 216         #print
 217
 218         first = True
 219         for line in e.pretty():
 220             if first:
 221                 print "%14d" % (int(e.timestamp) - last_ts),
 222                 last_ts = int(e.timestamp)
 223                 first = False
 224             else:
 225                 print " " * 14,
 226
 227             idx = ids.index(e.uid())
 228
 229             for i in range(0, idx):
 230                 print "|",
 231                 print " " * 20,
 232             sys.stdout.write(" | %s" % line)
 233             remainder = 21 - len(remove_vt100(line))
 234             if remainder > 0:
 235                 sys.stdout.write(" " * remainder)
 236             for i in range(idx + 1, len(ids)):
 237                 print "|",
 238                 print " " * 20,
 239             print
 240
 241
 242 def remove_vt100(line):
 243     """Remoe any occurrence of a VT100 color sequence from a string"""
 244     return re.sub("\033\[\d+(;\d+)?m", "", line)
 245
 246
 247 def extractLogs(inputFile):
 248     """Take a QEMU log file (Fiasco serial output) and extract the
 249        UU-encoded trace dumps from it.
 250     """
 251     files = []         # list of trace files
 252     inLogFile = False  # are we currently operating on a dump?
 253
 254     for l in file(inputFile).readlines():
 255         v = remove_vt100(l)
 256
 257         # start and end indicators
 258         startmo = re.match("romain.*(begin 644 .*.gz)", v)
 259         endmo = re.match("romain.*end", v)
 260
 261         if startmo:
 262             curFile = tempfile.NamedTemporaryFile(mode="w+")
 263             inLogFile = True
 264
 265         # Write lines belonging to the dump to temporary file.
 266         # Remove L4Re's log prefix upfront
 267         if inLogFile:
 268             curFile.write(v.replace("romain  | ", ""))
 269
 270         if inLogFile and endmo:
 271             files += [curFile]
 272             inLogFile = False
 273
 274     return files
 275
 276
 277 def main():
 278     if len(sys.argv) < 2:
 279         print "Need at least 1 argument"
 280         sys.exit(1)
 281
 282     elist = EventList()
 283     evproc = tsar_rules.EventPreprocessor()
 284
 285     for f in extractLogs(sys.argv[1]):
 286         sys.stderr.write("=== %s ===\n" % f.name)
 287         f.seek(0)  # need to reset file seek ptr
 288         elist.addStream(EventFactory(TraceReader(f)))
 289
 290     events = []
 291
 292     e = elist.next()
 293     while e is not None:
 294         events += [evproc.process(e)]
 295         e = elist.next()
 296
 297     # events are not necessarily sorted by time right now!
 298     events.sort(key=operator.attrgetter('timestamp'))
 299
 300     #print_plain(events)
 301     print_pretty(events)
 302
 303
 304 if __name__ == "__main__":
 305     main()