Make cygprofile order functions by process and thread ID.

tools/cygprofile/mergetraces.py

 #!/usr/bin/python
 # Copyright 2013 The Chromium Authors. All rights reserved.
 # Use of this source code is governed by a BSD-style license that can be
 # found in the LICENSE file.
 
 # Use: ../mergetraces.py `ls cyglog.* -Sr` > merged_cyglog
 
 """"Merge multiple logs files from different processes into a single log.
 
 Given two log files of execution traces, merge the traces into a single trace.
 Merging will use timestamps (i.e. the first two columns of logged calls) to
 create a single log that is an ordered trace of calls by both processes.
 """
 
 import optparse
-import os
 import string
-import subprocess
 import sys
 
 def ParseLogLines(lines):
   """Parse log file lines.
 
   Args:
     lines: lines from log file produced by profiled run
 
     Below is an example of a small log file:
     5086e000-52e92000 r-xp 00000000 b3:02 51276      libchromeview.so
@@ skipping 19 matching lines @@
   vm_end = int (lines[0][dash_index+1:space_index], 16)
   for line in lines[2:]:
     line = line.strip()
     # print hex (vm_start)
     fields = line.split()
     call_lines.append (fields)
 
   return (call_lines, vm_start, vm_end)
 
 def HasDuplicates(calls):
-  """Funcition is a sanity check to make sure that calls are only logged once.
+  """Makes sure that calls are only logged once.
 
   Args:
     calls: list of calls logged
 
   Returns:
     boolean indicating if calls has duplicate calls
   """
-  seen = []
+  seen = set([])
   for call in calls:
     if call[3] in seen:
-      return true
-    else:
-      seen.append(call[3])
+      return True
+    seen.add(call[3])
+  return False
 
 def CheckTimestamps(calls):
   """Prints warning to stderr if the call timestamps are not in order.
 
   Args:
     calls: list of calls logged
   """
   index = 0
   last_timestamp_secs = -1
   last_timestamp_us = -1
@@ skipping 48 matching lines @@
     tracemap: the tracemap
     trace: the trace
 
   """
   for trace_entry in trace:
     call = trace_entry[3]
     if (not call in tracemap) or (
         Timestamp(tracemap[call]) > Timestamp(trace_entry)):
       tracemap[call] = trace_entry
 
+def GroupByProcessAndThreadId(input_trace):
+  """Returns an array of traces grouped by pid and tid.
+
+  This is used to make the order of functions not depend on thread scheduling
+  which can be greatly impacted when profiling is done with cygprofile. As a
+  result each thread has its own contiguous segment of code (ordered by
+  timestamp) and processes also have their code isolated (i.e. not interleaved).
+  """
+  def MakeTimestamp(usec, sec):
+    return usec * 1000000 + sec
+
+  def PidAndTidFromString(pid_and_tid):
+    strings = pid_and_tid.split(':')
+    return (int(strings[0]), int(strings[1]))
+
+  pid_first_seen = {}
+  tid_first_seen = {}
+  for (sec, usec, pid_and_tid, _) in input_trace:
+    (pid, tid) = PidAndTidFromString(pid_and_tid)
+    if not pid in pid_first_seen:
+      pid_first_seen[pid] = MakeTimestamp(usec, sec)
+    if not tid in tid_first_seen:
+      tid_first_seen[tid] = MakeTimestamp(usec, sec)
+
+  def CompareEvents(event1, event2):
+    (sec1, usec1, pid_and_tid, _) = event1
+    (pid1, tid1) = PidAndTidFromString(pid_and_tid)
+    (sec2, usec2, pid_and_tid, _) = event2
+    (pid2, tid2) = PidAndTidFromString(pid_and_tid)
+
+    pid_cmp = cmp(pid_first_seen[pid1], pid_first_seen[pid2])
+    if pid_cmp != 0:
+      return pid_cmp
+    tid_cmp = cmp(tid_first_seen[tid1], tid_first_seen[tid2])
+    if tid_cmp != 0:
+      return tid_cmp
+    return cmp(MakeTimestamp(usec1, sec1), MakeTimestamp(usec2, sec2))
+
+  return sorted(input_trace, cmp=CompareEvents)
+
 def main():
   """Merge two traces for code in specified library and write to stdout.
 
   Merges the two traces and coverts the virtual addresses to the offsets in the
   library.  First line of merged trace has dummy virtual address of 0-ffffffff
   so that symbolizing the addresses uses the addresses in the log, since the
   addresses have already been converted to static offsets.
   """
   parser = optparse.OptionParser('usage: %prog trace1 ... traceN')
   (_, args) = parser.parse_args()
   if len(args) <= 1:
     parser.error('expected at least the following args: trace1 trace2')
 
   step = 0
+
+  # Maps function addresses to their corresponding trace entry.
   tracemap = dict()
+
   for trace_file in args:
     step += 1
     sys.stderr.write("    " + str(step) + "/" + str(len(args)) +
                      ": " + trace_file + ":\n")
 
     trace_lines = map(string.rstrip, open(trace_file).readlines())
     (trace_calls, trace_start, trace_end) = ParseLogLines(trace_lines)
     CheckTimestamps(trace_calls)
     sys.stderr.write("Len: " + str(len(trace_calls)) +
                      ". Start: " + hex(trace_start) +
                      ", end: " + hex(trace_end) + '\n')
 
     trace_calls = Convert(trace_calls, trace_start, trace_end)
     sys.stderr.write("Converted len: " + str(len(trace_calls)) + "\n")
 
     AddTrace(tracemap, trace_calls)
     sys.stderr.write("Merged len: " + str(len(tracemap)) + "\n")
 
   # Extract the resulting trace from the tracemap
   merged_trace = []
   for call in tracemap:
     merged_trace.append(tracemap[call])
   merged_trace.sort(key=Timestamp)
 
+  grouped_trace = GroupByProcessAndThreadId(merged_trace)
+  merged_trace = None

[pasko, 2014/06/05 12:50:10]

nit: seems not necessary

[Philippe, 2014/06/05 13:00:45]

Done.

+
   print "0-ffffffff r-xp 00000000 xx:00 00000 ./"
   print "secs\tusecs\tpid:threadid\tfunc"
-  for call in merged_trace:
+  for call in grouped_trace:
     print (str(call[0]) + "\t" + str(call[1]) + "\t" + call[2] + "\t" +
            hex(call[3]))
 
 if __name__ == '__main__':
   main()