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(sorted_trace):

[pasko, 2014/06/05 12:16:36]

I still think my function is easier to read. It passes your test.
Note, the function sorted() in python performs a stable sort.
Here we go:

  def GroupByProcessAndThreadId(input_trace):

    def Timestamp(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, address) in input_trace:
      (pid, tid) = PidAndTidFromString(pid_and_tid)
      if not pid in pid_first_seen:
        pid_first_seen[pid] = Timestamp(usec, sec)
      if not tid in tid_first_seen:
        tid_first_seen[tid] = Timestamp(usec, sec)

    def CompareEvents(event1, event2):
      (sec1, usec1, pid_and_tid, address1) = event1
      (pid1, tid1) = PidAndTidFromString(pid_and_tid)
      (sec2, usec2, pid_and_tid, address2) = 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(Timestamp(usec1, sec1), Timestamp(usec2, sec2))
    
    return sorted(input_trace, cmp=CompareEvents)

[Philippe, 2014/06/05 12:38:52]

Right :) I guess I had to see it to believe it. Thanks a lot for writing it!

+  """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).
+
+  This works by building a forest internally with three levels:
+      <PID 1> ..........................<PID N0>
+      /                                 /
+    <TID 1:1>...<TID 1:N1>   <TID N0:1>...<TID N0:N''>
+    /
+  <Trace 1:1:1>..<Trace 1:1:N2>
+
+  The nodes are inserted in the forest by order of occurence in |sorted_trace|
+  which is expected to be sorted by timestamp.
+
+  This forest is then flattened and returned as in:
+    <TID 1:1> <TID 1:2>...<TID 1:N>...<TID N':1> <TID N':2>...<TID N':N''>
+  """
+  # Array of (pid, [(tid, [trace])]). Not that arrays are used (as opposed to
+  # (un)ordered maps) to preserve order.
+  trace_arrays_for_processes = []
+
+  def _GetTraceArray(pid, tid):

[pasko, 2014/06/05 11:28:49]

This code operates on lists, there are no arrays.

It would be more readable to put 'trace_arrays_for_processes' as an explicit
parameter, and move it one level up in the scope.

Also, the function name is misleading, since it modifies the
'trace_arrays_for_processes'. The semantics of this function is a bit complex,
so please add a short docstring explaining the input types and what the function
does in 1-2 sentences.

[Philippe, 2014/06/05 12:38:52]

Done.

+    # TODO(pliard): This may require a cache if the linear search below turns
+    # out to be too slow.
+    found_process_index = -1

[pasko, 2014/06/05 11:28:49]

I am not a Python expert, but it seems more pythonic to use None.

[Philippe, 2014/06/05 12:38:52]

Done.

+
+    for i, (current_pid, current_trace_arrays) in enumerate(
+        trace_arrays_for_processes):
+      if current_pid != pid:
+        continue
+
+      found_process_index = i
+      for (current_tid, trace_array) in current_trace_arrays:
+        if current_tid == tid:
+          return trace_array
+      break
+
+    process_pair = None

[pasko, 2014/06/05 11:28:49]

I would appreciate a comment hee saying something like:
# Append (pid, [(tid, [])]) and return the reference to the innermost list.

[Philippe, 2014/06/05 12:38:52]

Done.

+    if found_process_index == -1:
+      process_pair = (pid, [])
+      trace_arrays_for_processes.append(process_pair)
+    else:
+      process_pair = trace_arrays_for_processes[found_process_index]
+
+    (_, trace_arrays) = process_pair
+    new_array = []
+    trace_arrays.append((tid, new_array))
+    return new_array
+
+  # Build the forest.
+  for trace in sorted_trace:
+    tokens = trace[2].split(':')
+    (pid, tid) = (int(tokens[0]), int(tokens[1]))
+    _GetTraceArray(pid, tid).append(trace)
+
+  # Flatten the forest.
+  flat_trace_array = []
+  for (_, current_trace_arrays) in trace_arrays_for_processes:
+    for (_, trace_array) in current_trace_arrays:
+      for trace in trace_array:
+        flat_trace_array.append(trace)
+
+  assert not HasDuplicates(flat_trace_array)
+
+  return flat_trace_array
+
 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
+
   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()