Home | History | Annotate | Download | only in cygprofile 
      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()
    187