diff --git a/intercept/src/chrometracer.h b/intercept/src/chrometracer.h index db1b1bdb..bd97191b 100644 --- a/intercept/src/chrometracer.h +++ b/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 ) diff --git a/intercept/src/intercept.cpp b/intercept/src/intercept.cpp index f8b948f0..05854899 100644 --- a/intercept/src/intercept.cpp +++ b/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(m_StartTime.time_since_epoch()).count(); - m_ChromeTrace.addStartTimeMetadata( threadId, usStartTime ); + m_ChromeTrace.addStartTimeMetadata( usStartTime ); } log( "... loading complete.\n" ); diff --git a/scripts/combine_chrome_traces.py b/scripts/combine_chrome_traces.py index 6f5119c6..7fe731bf 100755 --- a/scripts/combine_chrome_traces.py +++ b/scripts/combine_chrome_traces.py @@ -11,8 +11,24 @@ 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] == '-?'): @@ -20,57 +36,57 @@ def main(): # 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 [space-separated event filters]") + print(r" Use as:") + print(r" combine_chrome_traces.py [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()