Fix bug in mergetraces.py.

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 string
+import sets
 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 109 matching lines @@
       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 MakeTimestamp(sec, usec):
+    return sec * 1000000 + usec
 
   def PidAndTidFromString(pid_and_tid):
     strings = pid_and_tid.split(':')
     return (int(strings[0]), int(strings[1]))
 
+  tid_to_pids_map = {}
   pid_first_seen = {}
   tid_first_seen = {}
+
   for (sec, usec, pid_and_tid, _) in input_trace:
     (pid, tid) = PidAndTidFromString(pid_and_tid)
+
+    # Make sure that thread IDs are unique since this a property we rely on.

[pasko, 2014/06/06 09:41:44]

s/this/this is/

[Philippe, 2014/06/06 09:50:23]

Done.

[Philippe, 2014/06/06 09:50:23]

Done.

+    pids_for_tid = tid_to_pids_map.setdefault(tid, sets.Set())
+    pids_for_tid.add(pid)
+    if len(pids_for_tid) > 1:
+      raise Exception('Thread IDs should be unique.')

[pasko, 2014/06/06 09:41:44]

in this context we actually have the tid and two pids, would be useful to print
them as part of the message.

This looks simpler:

tid_to_pids_map.setdefault(tid, pid)
if tid_to_pids_map[tid] != pid:
  raise Exception('...')

[Philippe, 2014/06/06 09:50:23]

Yeah :) I haven't slept much last night :)

+
     if not pid in pid_first_seen:
-      pid_first_seen[pid] = MakeTimestamp(usec, sec)
+      pid_first_seen[pid] = MakeTimestamp(sec, usec)
     if not tid in tid_first_seen:
-      tid_first_seen[tid] = MakeTimestamp(usec, sec)
+      tid_first_seen[tid] = MakeTimestamp(sec, usec)
 
   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 cmp(MakeTimestamp(sec1, usec1), MakeTimestamp(sec2, usec2))
 
   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.
@@ skipping 35 matching lines @@
   grouped_trace = GroupByProcessAndThreadId(merged_trace)
 
   print "0-ffffffff r-xp 00000000 xx:00 00000 ./"
   print "secs\tusecs\tpid:threadid\tfunc"
   for call in grouped_trace:
     print (str(call[0]) + "\t" + str(call[1]) + "\t" + call[2] + "\t" +
            hex(call[3]))
 
 if __name__ == '__main__':
   main()