generate proper json files for chrome tracing

intercept/src/chrometracer.h

@@ -28,6 +28,14 @@ class CChromeTracer
     ~CChromeTracer()
     {
         flush();
+
+        // Add an eof metadata event without a trailing comma to properly end
+        // the json file.
+        m_TraceFile
+            << "{\"ph\":\"M\",\"name\":\"clintercept_eof\",\"pid\":" << m_ProcessId
+            << ",\"tid\":0"
+            << "}\n"
+            << "]\n";
         m_TraceFile.close();
     }
 
@@ -38,13 +46,12 @@ class CChromeTracer
             bool addFlowEvents );
 
     void addProcessMetadata(
-            uint64_t threadId,
             const std::string& processName )
     {
         m_TraceFile
-            << "{\"ph\":\"M\", \"name\":\"process_name\", \"pid\":" << m_ProcessId
-            << ", \"tid\":" << threadId
-            << ", \"args\":{\"name\":\"" << processName
+            << "{\"ph\":\"M\",\"name\":\"process_name\",\"pid\":" << m_ProcessId
+            << ",\"tid\":0"
+            << ",\"args\":{\"name\":\"" << processName
             << "\"}},\n";
     }
 
@@ -53,25 +60,24 @@ class CChromeTracer
             uint32_t threadNumber )
     {
         m_TraceFile
-            << "{\"ph\":\"M\", \"name\":\"thread_name\", \"pid\":" << m_ProcessId
-            << ", \"tid\":" << threadId
-            << ", \"args\":{\"name\":\"Host Thread " << threadId
+            << "{\"ph\":\"M\",\"name\":\"thread_name\",\"pid\":" << m_ProcessId
+            << ",\"tid\":" << threadId
+            << ",\"args\":{\"name\":\"Host Thread " << threadId
             << "\"}},\n";
         m_TraceFile
-            << "{\"ph\":\"M\", \"name\":\"thread_sort_index\", \"pid\":" << m_ProcessId
-            << ", \"tid\":" << threadId
-            << ", \"args\":{\"sort_index\":\"" << threadNumber + 10000
+            << "{\"ph\":\"M\",\"name\":\"thread_sort_index\",\"pid\":" << m_ProcessId
+            << ",\"tid\":" << threadId
+            << ",\"args\":{\"sort_index\":\"" << threadNumber + 10000
             << "\"}},\n";
     }
 
     void addStartTimeMetadata(
-            uint64_t threadId,
             uint64_t startTime )
     {
         m_TraceFile
-            << "{\"ph\":\"M\", \"name\":\"clintercept_start_time\", \"pid\":" << m_ProcessId
-            << ", \"tid\":" << threadId
-            << ", \"args\":{\"start_time\":" << startTime
+            << "{\"ph\":\"M\",\"name\":\"clintercept_start_time\",\"pid\":" << m_ProcessId
+            << ",\"tid\":0"
+            << ",\"args\":{\"start_time\":" << startTime
             << "}},\n";
     }
 
@@ -80,14 +86,14 @@ class CChromeTracer
             const std::string& queueName )
     {
         m_TraceFile
-            << "{\"ph\":\"M\", \"name\":\"thread_name\", \"pid\":" << m_ProcessId
-            << ", \"tid\":" << queueNumber
-            << ".1, \"args\":{\"name\":\"" << queueName
+            << "{\"ph\":\"M\",\"name\":\"thread_name\",\"pid\":" << m_ProcessId
+            << ",\"tid\":" << queueNumber
+            << ".1,\"args\":{\"name\":\"" << queueName
             << "\"}},\n";
         m_TraceFile
-            << "{\"ph\":\"M\", \"name\":\"thread_sort_index\", \"pid\":" << m_ProcessId
-            << ", \"tid\":" << queueNumber
-            << ".1, \"args\":{\"sort_index\":\"" << queueNumber
+            << "{\"ph\":\"M\",\"name\":\"thread_sort_index\",\"pid\":" << m_ProcessId
+            << ",\"tid\":" << queueNumber
+            << ".1,\"args\":{\"sort_index\":\"" << queueNumber
             << "\"}},\n";
     }
 
@@ -354,12 +360,6 @@ class CChromeTracer
         }
     }
 
-    // temp
-    std::ostream& write( const char* str, std::streamsize count )
-    {
-        return m_TraceFile.write(str, count);
-    }
-
     std::ostream& flush()
     {
         if( m_RecordBuffer.size() > 0 )

intercept/src/intercept.cpp

@@ -442,9 +442,8 @@ bool CLIntercept::init()
         bool        addFlowEvents = m_Config.ChromeFlowEvents;
         m_ChromeTrace.init( fileName, processId, bufferSize, addFlowEvents );
 
-        uint64_t    threadId = OS().GetThreadID();
         std::string processName = OS().GetProcessName();
-        m_ChromeTrace.addProcessMetadata( threadId, processName );
+        m_ChromeTrace.addProcessMetadata( processName );
     }
 
     std::string name = "";
@@ -639,12 +638,10 @@ bool CLIntercept::init()
     if( m_Config.ChromeCallLogging ||
         m_Config.ChromePerformanceTiming )
     {
-        uint64_t    threadId = OS().GetThreadID();
-
         using us = std::chrono::microseconds;
         uint64_t    usStartTime =
             std::chrono::duration_cast<us>(m_StartTime.time_since_epoch()).count();
-        m_ChromeTrace.addStartTimeMetadata( threadId, usStartTime );
+        m_ChromeTrace.addStartTimeMetadata( usStartTime );
     }
 
     log( "... loading complete.\n" );

scripts/combine_chrome_traces.py

@@ -11,66 +11,82 @@
 import re
 import os
 
-def main():
+def filter(filters, record):
+    # Always filter non-records:
+    if not "\"ph\":" in record: return False
+    # Handle the case where there are no filters:
+    if len(filters) == 0: return True
+    # Always keep metadata records:
+    if "\"ph\":\"M\"" in record: return True
+    # Otherwise, check against all filters:
+    for filter in filters:
+        if filter in record: return True
+    return False
+
+def fixup(record):
+    if not record.strip().endswith(','):
+        record = record.strip() + ",\n"
+    return record
 
+def main():
     printHelp = False
 
     if (len(sys.argv) < 4 or sys.argv[1] == '-h' or sys.argv[1] == '-?'):
         printHelp = True
 
     # Help message
     if (printHelp):
-        print("")
-        print("    A script to combine multiple Chrome traces captured by the opencl-intercept-layer.")
-        print("    The combined trace can be viewed on a common timeline in the Chrome browser.")
+        print(r"")
+        print(r"    A script to combine multiple Chrome traces captured by the opencl-intercept-layer.")
+        print(r"    The combined trace can be viewed on a common timeline in the Chrome browser.")
         print()
-        print("    This is useful for analyzing multi-process execution.")
-        print("    Set CLI_AppendPid=1 when collecting Chrome traces to obtain separate per-process traces.")
-        print("    Can also be useful to compare two or more single process executions on a common timeline.")
+        print(r"    This is useful for analyzing multi-process execution.")
+        print(r"    Set CLI_AppendPid=1 when collecting Chrome traces to obtain separate per-process traces.")
+        print(r"    Can also be useful to compare two or more single process executions on a common timeline.")
         print()
-        print("    Use as:")
-        print("    combine_chrome_traces.py <number of traces> <space-separated paths to all json traces> [space-separated event filters]")
+        print(r"    Use as:")
+        print(r"    combine_chrome_traces.py <number of traces> <space-separated paths to all json traces> [space-separated event filters]")
         print()
-        print("        Optional arguments: event-filters are names of OpenCL kernels or OpenCL API calls")
-        print("                            that should be retained in the filtered output.")
+        print(r"        Optional arguments: event-filters are names of OpenCL kernels or OpenCL API calls")
+        print(r"                            that should be retained in the filtered output.")
         print()
-        print("    Example:" )
+        print(r"    Example:" )
         print()
-        print("    combine_chrome_traces.py 4 \ # specifies 4 traces to combine")
-        print("    CLIntercept_Dump.45682/clintercept_trace.json \ # paths to the four traces follow")
-        print("    CLIntercept_Dump.45683/clintercept_trace.json \ ")
-        print("    CLIntercept_Dump.45684/clintercept_trace.json \ ")
-        print("    CLIntercept_Dump.45685/clintercept_trace.json \ ")
-        print("    kernelA kernelB clEnqueueWriteBuffer clEnqueueReadBuffer # specifies kernel/API names as filters [optional]")
+        print(r"    combine_chrome_traces.py 4 \ # specifies 4 traces to combine")
+        print(r"    CLIntercept_Dump.45682/clintercept_trace.json \ # paths to the four traces follow")
+        print(r"    CLIntercept_Dump.45683/clintercept_trace.json \ ")
+        print(r"    CLIntercept_Dump.45684/clintercept_trace.json \ ")
+        print(r"    CLIntercept_Dump.45685/clintercept_trace.json \ ")
+        print(r"    kernelA kernelB clEnqueueWriteBuffer clEnqueueReadBuffer # specifies kernel/API names as filters [optional]")
         print()
-        print("    Note: This script modifies events records so that all traces have a common epoch.")
+        print(r"    Note: This script modifies events records so that all traces have a common epoch.")
         print()
         sys.exit(0)
 
     # Get input arguments
-    numFiles = int(sys.argv[1]);
-    numStrings = len(sys.argv) - numFiles - 2;
+    files = sys.argv[2:2+int(sys.argv[1])]
+    filters = sys.argv[2+int(sys.argv[1]):]
 
     # Sanity checks
-    if (numFiles < 2):
+    if len(files) < 2:
         print("ERROR: you must specify at least two traces to combine.")
         sys.exit(1)
-    for j in range(numFiles):
-        if(not os.path.isfile(sys.argv[j+2])):
-            print("ERROR: specified file "+sys.argv[j+2]+" cannot be found.")
+    for filename in files:
+        if not os.path.isfile(filename):
+            print("ERROR: specified file {} cannot be found.".format(filename))
             sys.exit(1)
 
     # Read input files
     inputFiles = []
-    for j in range(numFiles):
-        f = open(sys.argv[j+2],'r')
+    for filename in files:
+        f = open(filename,'r')
         currentFile = f.readlines()
         f.close()
         inputFiles.append(currentFile)
 
     # Figure out epoch (earliest start_time across all records)
     start_times = []
-    for j in range(numFiles):
+    for j in range(len(files)):
         for k in range(len(inputFiles[j])):
             if (inputFiles[j][k].find("start_time") != -1):
                 start_times.append(int(inputFiles[j][2].split(":")[-1].split("}")[0].strip('"')))
@@ -79,39 +95,43 @@ def main():
             print("ERROR: start_time not found in trace file "+sys.argv[j+2]+". Please check if the trace is valid.")
             sys.exit(1)
     epoch = min(start_times)
+    print("Found minimum start time {}".format(epoch))
 
-    # Perform filtering if necessary
+    # Perform filtering
     filteredFiles = []
-    if (numStrings == 0):
-        filteredFiles = inputFiles
-    else:
-        for j in range(numFiles):
-            flt = [i for i in inputFiles[j] if "\"ph\":\"M\"" in i] # copy metadata
-            for k in range(numStrings):
-                flt = flt + [i for i in inputFiles[j] if sys.argv[2+numFiles+k] in i]
-            filteredFiles.append(flt)
+    for j in range(len(files)):
+        flt = [fixup(i) for i in inputFiles[j] if filter(filters, i)]
+        filteredFiles.append(flt)
 
     # Perform epoch normalization
-    for j in range(numFiles):
+    for j in range(len(files)):
         offset = start_times[j] - epoch
+        print("Processing file {} with offset {}".format(files[j], offset))
         for k in range(len(filteredFiles[j])):
             if (filteredFiles[j][k].find("\"ts\"") != -1):
-                ts = int(filteredFiles[j][k].split("\"ts\":")[-1].split(",")[0]) + offset
-                filteredFiles[j][k] = re.sub("\"ts\":\d+", "\"ts\":"+str(ts), filteredFiles[j][k])
+                ts = float(filteredFiles[j][k].split("\"ts\":")[-1].split(",")[0]) + offset
+                #print('old record was: {}'.format(filteredFiles[j][k].strip()))
+                filteredFiles[j][k] = re.sub("\"ts\":[\\d.]+", "\"ts\":"+str(ts), filteredFiles[j][k])
+                #print('new record is:  {}'.format(filteredFiles[j][k].strip()))
             elif (filteredFiles[j][k].find("start_time") != -1):
-                filteredFiles[j][k] = re.sub('\"start_time\":["]?\d+["]?', "\"start_time\":"+str(epoch), filteredFiles[j][k])
-
+                #print('old record was: {}'.format(filteredFiles[j][k].strip()))
+                filteredFiles[j][k] = re.sub('\"start_time\":["]?\\d+["]?', "\"start_time\":"+str(epoch), filteredFiles[j][k])
+                #print('new record is:  {}'.format(filteredFiles[j][k].strip()))
+
     # Write to output file
     tstamp = datetime.datetime.now()
     fName = "merged_" + str(tstamp.year) + '-' + str(tstamp.month) + '-' + str(tstamp.day) \
             + '-' + str(tstamp.hour) + '-' + str(tstamp.minute)+ '-' + str(tstamp.second) + ".json"
-    print("Combining in "+fName)
+    print("Writing to combined file "+fName)
     fo = open(fName, 'w')
     fo.write("[\n")
-    for j in range(numFiles):
+    for j in range(len(files)):
       for k in range(1,len(filteredFiles[j])):
           fo.write("%s" % filteredFiles[j][k])
+    fo.write("{\"ph\":\"M\",\"name\":\"clintercept_merged_eof\",\"pid\":0,\"tid\":0}\n")
+    fo.write("]\n")
     f.close()
+    print("Done.")
 
 if __name__ == "__main__":
     main()