tools/cygprofile/mergetraces.py

   1 #!/usr/bin/python
   2 # Copyright 2013 The Chromium Authors. All rights reserved.
   3 # Use of this source code is governed by a BSD-style license that can be
   4 # found in the LICENSE file.
   5
   6 # Use: ../mergetraces.py `ls cyglog.* -Sr` > merged_cyglog
   7
   8 """"Merge multiple logs files from different processes into a single log.
   9
  10 Given two log files of execution traces, merge the traces into a single trace.
  11 Merging will use timestamps (i.e. the first two columns of logged calls) to
  12 create a single log that is an ordered trace of calls by both processes.
  13 """
  14
  15 import optparse
  16 import os
  17 import string
  18 import subprocess
  19 import sys
  20
  21 def ParseLogLines(lines):
  22   """Parse log file lines.
  23
  24   Args:
  25     lines: lines from log file produced by profiled run
  26
  27     Below is an example of a small log file:
  28     5086e000-52e92000 r-xp 00000000 b3:02 51276      libchromeview.so
  29     secs       msecs      pid:threadid    func
  30     START
  31     1314897086 795828     3587:1074648168 0x509e105c
  32     1314897086 795874     3587:1074648168 0x509e0eb4
  33     1314897086 796326     3587:1074648168 0x509e0e3c
  34     1314897086 796552     3587:1074648168 0x509e07bc
  35     END
  36
  37   Returns:
  38     tuple conisiting of 1) an ordered list of the logged calls, as an array of
  39     fields, 2) the virtual start address of the library, used to compute the
  40     offset of the symbol in the library and 3) the virtual end address
  41   """
  42   call_lines = []
  43   vm_start = 0
  44   vm_end = 0
  45   dash_index = lines[0].find ('-')
  46   space_index = lines[0].find (' ')
  47   vm_start = int (lines[0][:dash_index], 16)
  48   vm_end = int (lines[0][dash_index+1:space_index], 16)
  49   for line in lines[2:]:
  50     line = line.strip()
  51     # print hex (vm_start)
  52     fields = line.split()
  53     call_lines.append (fields)
  54
  55   return (call_lines, vm_start, vm_end)
  56
  57 def HasDuplicates(calls):
  58   """Funcition is a sanity check to make sure that calls are only logged once.
  59
  60   Args:
  61     calls: list of calls logged
  62
  63   Returns:
  64     boolean indicating if calls has duplicate calls
  65   """
  66   seen = []
  67   for call in calls:
  68     if call[3] in seen:
  69       return true
  70     else:
  71       seen.append(call[3])
  72
  73 def CheckTimestamps(calls):
  74   """Prints warning to stderr if the call timestamps are not in order.
  75
  76   Args:
  77     calls: list of calls logged
  78   """
  79   index = 0
  80   last_timestamp_secs = -1
  81   last_timestamp_ms = -1
  82   while (index < len (calls)):
  83     timestamp_secs = int (calls[index][0])
  84     timestamp_ms = int (calls[index][1])
  85     timestamp = (timestamp_secs * 1000000) + timestamp_ms
  86     last_timestamp = (last_timestamp_secs * 1000000) + last_timestamp_ms
  87     if (timestamp < last_timestamp):
  88       sys.stderr.write("WARNING: last_timestamp: " + str(last_timestamp_secs)
  89                        + " " + str(last_timestamp_ms) + " timestamp: "
  90                        + str(timestamp_secs) + " " + str(timestamp_ms) + "\n")
  91     last_timestamp_secs = timestamp_secs
  92     last_timestamp_ms = timestamp_ms
  93     index = index + 1
  94
  95 def Convert (call_lines, startAddr, endAddr):
  96   """Converts the call addresses to static offsets and removes invalid calls.
  97
  98   Removes profiled calls not in shared library using start and end virtual
  99   addresses, converts strings to integer values, coverts virtual addresses to
 100   address in shared library.
 101
 102   Returns:
 103      list of calls as tuples (sec, msec, pid:tid, callee)
 104   """
 105   converted_calls = []
 106   call_addresses = []
 107   for fields in call_lines:
 108     secs = int (fields[0])
 109     msecs = int (fields[1])
 110     callee = int (fields[3], 16)
 111     # print ("callee: " + hex (callee) + " start: " + hex (startAddr) + " end: "
 112     #        + hex (endAddr))
 113     if (callee >= startAddr and callee < endAddr
 114         and (not callee in call_addresses)):
 115       converted_calls.append((secs, msecs, fields[2], (callee - startAddr)))
 116       call_addresses.append(callee)
 117   return converted_calls
 118
 119 def Timestamp(trace_entry):
 120   return int (trace_entry[0]) * 1000000 + int(trace_entry[1])
 121
 122 def AddTrace (tracemap, trace):
 123   """Adds a trace to the tracemap.
 124
 125   Adds entries in the trace to the tracemap. All new calls will be added to
 126   the tracemap. If the calls already exist in the tracemap then they will be
 127   replaced if they happened sooner in the new trace.
 128
 129   Args:
 130     tracemap: the tracemap
 131     trace: the trace
 132
 133   """
 134   for trace_entry in trace:
 135     call = trace_entry[3]
 136     if (not call in tracemap) or (
 137         Timestamp(tracemap[call]) > Timestamp(trace_entry)):
 138       tracemap[call] = trace_entry
 139
 140 def main():
 141   """Merge two traces for code in specified library and write to stdout.
 142
 143   Merges the two traces and coverts the virtual addresses to the offsets in the
 144   library.  First line of merged trace has dummy virtual address of 0-ffffffff
 145   so that symbolizing the addresses uses the addresses in the log, since the
 146   addresses have already been converted to static offsets.
 147   """
 148   parser = optparse.OptionParser('usage: %prog trace1 ... traceN')
 149   (_, args) = parser.parse_args()
 150   if len(args) <= 1:
 151     parser.error('expected at least the following args: trace1 trace2')
 152
 153   step = 0
 154   tracemap = dict()
 155   for trace_file in args:
 156     step += 1
 157     sys.stderr.write("    " + str(step) + "/" + str(len(args)) +
 158                      ": " + trace_file + ":\n")
 159
 160     trace_lines = map(string.rstrip, open(trace_file).readlines())
 161     (trace_calls, trace_start, trace_end) = ParseLogLines(trace_lines)
 162     CheckTimestamps(trace_calls)
 163     sys.stderr.write("Len: " + str(len(trace_calls)) +
 164                      ". Start: " + hex(trace_start) +
 165                      ", end: " + hex(trace_end) + '\n')
 166
 167     trace_calls = Convert(trace_calls, trace_start, trace_end)
 168     sys.stderr.write("Converted len: " + str(len(trace_calls)) + "\n")
 169
 170     AddTrace(tracemap, trace_calls)
 171     sys.stderr.write("Merged len: " + str(len(tracemap)) + "\n")
 172
 173   # Extract the resulting trace from the tracemap
 174   merged_trace = []
 175   for call in tracemap:
 176     merged_trace.append(tracemap[call])
 177   merged_trace.sort(key=Timestamp)
 178
 179   print "0-ffffffff r-xp 00000000 xx:00 00000 ./"
 180   print "secs\tmsecs\tpid:threadid\tfunc"
 181   for call in merged_trace:
 182     print (str(call[0]) + "\t" + str(call[1]) + "\t" + call[2] + "\t" +
 183            hex(call[3]))
 184
 185 if __name__ == '__main__':
 186   main()