Skip to content

Commit 29d98c3

Browse files
bashbaugbashbaug
authored
generate proper json files for chrome tracing (#368)
* generate proper json files for chrome tracing * flush the chrome trace file before adding the eof metadata
1 parent e3d6ab5 commit 29d98c3

File tree

3 files changed

+92
-75
lines changed

3 files changed

+92
-75
lines changed

‎intercept/src/chrometracer.h

Lines changed: 26 additions & 26 deletions
Original file line numberDiff line numberDiff line change
@@ -28,6 +28,14 @@ class CChromeTracer
2828
~CChromeTracer()
2929
{
3030
flush();
31+
32+
// Add an eof metadata event without a trailing comma to properly end
33+
// the json file.
34+
m_TraceFile
35+
<< "{\"ph\":\"M\",\"name\":\"clintercept_eof\",\"pid\":" << m_ProcessId
36+
<< ",\"tid\":0"
37+
<< "}\n"
38+
<< "]\n";
3139
m_TraceFile.close();
3240
}
3341

@@ -38,13 +46,12 @@ class CChromeTracer
3846
bool addFlowEvents );
3947

4048
void addProcessMetadata(
41-
uint64_t threadId,
4249
const std::string& processName )
4350
{
4451
m_TraceFile
45-
<< "{\"ph\":\"M\", \"name\":\"process_name\", \"pid\":" << m_ProcessId
46-
<< ", \"tid\":" << threadId
47-
<< ", \"args\":{\"name\":\"" << processName
52+
<< "{\"ph\":\"M\",\"name\":\"process_name\",\"pid\":" << m_ProcessId
53+
<< ",\"tid\":0"
54+
<< ",\"args\":{\"name\":\"" << processName
4855
<< "\"}},\n";
4956
}
5057

@@ -53,25 +60,24 @@ class CChromeTracer
5360
uint32_t threadNumber )
5461
{
5562
m_TraceFile
56-
<< "{\"ph\":\"M\", \"name\":\"thread_name\", \"pid\":" << m_ProcessId
57-
<< ", \"tid\":" << threadId
58-
<< ", \"args\":{\"name\":\"Host Thread " << threadId
63+
<< "{\"ph\":\"M\",\"name\":\"thread_name\",\"pid\":" << m_ProcessId
64+
<< ",\"tid\":" << threadId
65+
<< ",\"args\":{\"name\":\"Host Thread " << threadId
5966
<< "\"}},\n";
6067
m_TraceFile
61-
<< "{\"ph\":\"M\", \"name\":\"thread_sort_index\", \"pid\":" << m_ProcessId
62-
<< ", \"tid\":" << threadId
63-
<< ", \"args\":{\"sort_index\":\"" << threadNumber + 10000
68+
<< "{\"ph\":\"M\",\"name\":\"thread_sort_index\",\"pid\":" << m_ProcessId
69+
<< ",\"tid\":" << threadId
70+
<< ",\"args\":{\"sort_index\":\"" << threadNumber + 10000
6471
<< "\"}},\n";
6572
}
6673

6774
void addStartTimeMetadata(
68-
uint64_t threadId,
6975
uint64_t startTime )
7076
{
7177
m_TraceFile
72-
<< "{\"ph\":\"M\", \"name\":\"clintercept_start_time\", \"pid\":" << m_ProcessId
73-
<< ", \"tid\":" << threadId
74-
<< ", \"args\":{\"start_time\":" << startTime
78+
<< "{\"ph\":\"M\",\"name\":\"clintercept_start_time\",\"pid\":" << m_ProcessId
79+
<< ",\"tid\":0"
80+
<< ",\"args\":{\"start_time\":" << startTime
7581
<< "}},\n";
7682
}
7783

@@ -80,14 +86,14 @@ class CChromeTracer
8086
const std::string& queueName )
8187
{
8288
m_TraceFile
83-
<< "{\"ph\":\"M\", \"name\":\"thread_name\", \"pid\":" << m_ProcessId
84-
<< ", \"tid\":" << queueNumber
85-
<< ".1, \"args\":{\"name\":\"" << queueName
89+
<< "{\"ph\":\"M\",\"name\":\"thread_name\",\"pid\":" << m_ProcessId
90+
<< ",\"tid\":" << queueNumber
91+
<< ".1,\"args\":{\"name\":\"" << queueName
8692
<< "\"}},\n";
8793
m_TraceFile
88-
<< "{\"ph\":\"M\", \"name\":\"thread_sort_index\", \"pid\":" << m_ProcessId
89-
<< ", \"tid\":" << queueNumber
90-
<< ".1, \"args\":{\"sort_index\":\"" << queueNumber
94+
<< "{\"ph\":\"M\",\"name\":\"thread_sort_index\",\"pid\":" << m_ProcessId
95+
<< ",\"tid\":" << queueNumber
96+
<< ".1,\"args\":{\"sort_index\":\"" << queueNumber
9197
<< "\"}},\n";
9298
}
9399

@@ -354,12 +360,6 @@ class CChromeTracer
354360
}
355361
}
356362

357-
// temp
358-
std::ostream& write( const char* str, std::streamsize count )
359-
{
360-
return m_TraceFile.write(str, count);
361-
}
362-
363363
std::ostream& flush()
364364
{
365365
if( m_RecordBuffer.size() > 0 )

‎intercept/src/intercept.cpp

Lines changed: 2 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -442,9 +442,8 @@ bool CLIntercept::init()
442442
bool addFlowEvents = m_Config.ChromeFlowEvents;
443443
m_ChromeTrace.init( fileName, processId, bufferSize, addFlowEvents );
444444

445-
uint64_t threadId = OS().GetThreadID();
446445
std::string processName = OS().GetProcessName();
447-
m_ChromeTrace.addProcessMetadata( threadId, processName );
446+
m_ChromeTrace.addProcessMetadata( processName );
448447
}
449448

450449
std::string name = "";
@@ -639,12 +638,10 @@ bool CLIntercept::init()
639638
if( m_Config.ChromeCallLogging ||
640639
m_Config.ChromePerformanceTiming )
641640
{
642-
uint64_t threadId = OS().GetThreadID();
643-
644641
using us = std::chrono::microseconds;
645642
uint64_t usStartTime =
646643
std::chrono::duration_cast<us>(m_StartTime.time_since_epoch()).count();
647-
m_ChromeTrace.addStartTimeMetadata( threadId, usStartTime );
644+
m_ChromeTrace.addStartTimeMetadata( usStartTime );
648645
}
649646

650647
log( "... loading complete.\n" );

‎scripts/combine_chrome_traces.py

Lines changed: 64 additions & 44 deletions
Original file line numberDiff line numberDiff line change
@@ -11,66 +11,82 @@
1111
import re
1212
import os
1313

14-
def main():
14+
def filter(filters, record):
15+
# Always filter non-records:
16+
if not "\"ph\":" in record: return False
17+
# Handle the case where there are no filters:
18+
if len(filters) == 0: return True
19+
# Always keep metadata records:
20+
if "\"ph\":\"M\"" in record: return True
21+
# Otherwise, check against all filters:
22+
for filter in filters:
23+
if filter in record: return True
24+
return False
25+
26+
def fixup(record):
27+
if not record.strip().endswith(','):
28+
record = record.strip() + ",\n"
29+
return record
1530

31+
def main():
1632
printHelp = False
1733

1834
if (len(sys.argv) < 4 or sys.argv[1] == '-h' or sys.argv[1] == '-?'):
1935
printHelp = True
2036

2137
# Help message
2238
if (printHelp):
23-
print("")
24-
print(" A script to combine multiple Chrome traces captured by the opencl-intercept-layer.")
25-
print(" The combined trace can be viewed on a common timeline in the Chrome browser.")
39+
print(r"")
40+
print(r" A script to combine multiple Chrome traces captured by the opencl-intercept-layer.")
41+
print(r" The combined trace can be viewed on a common timeline in the Chrome browser.")
2642
print()
27-
print(" This is useful for analyzing multi-process execution.")
28-
print(" Set CLI_AppendPid=1 when collecting Chrome traces to obtain separate per-process traces.")
29-
print(" Can also be useful to compare two or more single process executions on a common timeline.")
43+
print(r" This is useful for analyzing multi-process execution.")
44+
print(r" Set CLI_AppendPid=1 when collecting Chrome traces to obtain separate per-process traces.")
45+
print(r" Can also be useful to compare two or more single process executions on a common timeline.")
3046
print()
31-
print(" Use as:")
32-
print(" combine_chrome_traces.py <number of traces> <space-separated paths to all json traces> [space-separated event filters]")
47+
print(r" Use as:")
48+
print(r" combine_chrome_traces.py <number of traces> <space-separated paths to all json traces> [space-separated event filters]")
3349
print()
34-
print(" Optional arguments: event-filters are names of OpenCL kernels or OpenCL API calls")
35-
print(" that should be retained in the filtered output.")
50+
print(r" Optional arguments: event-filters are names of OpenCL kernels or OpenCL API calls")
51+
print(r" that should be retained in the filtered output.")
3652
print()
37-
print(" Example:" )
53+
print(r" Example:" )
3854
print()
39-
print(" combine_chrome_traces.py 4 \ # specifies 4 traces to combine")
40-
print(" CLIntercept_Dump.45682/clintercept_trace.json \ # paths to the four traces follow")
41-
print(" CLIntercept_Dump.45683/clintercept_trace.json \ ")
42-
print(" CLIntercept_Dump.45684/clintercept_trace.json \ ")
43-
print(" CLIntercept_Dump.45685/clintercept_trace.json \ ")
44-
print(" kernelA kernelB clEnqueueWriteBuffer clEnqueueReadBuffer # specifies kernel/API names as filters [optional]")
55+
print(r" combine_chrome_traces.py 4 \ # specifies 4 traces to combine")
56+
print(r" CLIntercept_Dump.45682/clintercept_trace.json \ # paths to the four traces follow")
57+
print(r" CLIntercept_Dump.45683/clintercept_trace.json \ ")
58+
print(r" CLIntercept_Dump.45684/clintercept_trace.json \ ")
59+
print(r" CLIntercept_Dump.45685/clintercept_trace.json \ ")
60+
print(r" kernelA kernelB clEnqueueWriteBuffer clEnqueueReadBuffer # specifies kernel/API names as filters [optional]")
4561
print()
46-
print(" Note: This script modifies events records so that all traces have a common epoch.")
62+
print(r" Note: This script modifies events records so that all traces have a common epoch.")
4763
print()
4864
sys.exit(0)
4965

5066
# Get input arguments
51-
numFiles = int(sys.argv[1]);
52-
numStrings = len(sys.argv) - numFiles - 2;
67+
files = sys.argv[2:2+int(sys.argv[1])]
68+
filters = sys.argv[2+int(sys.argv[1]):]
5369

5470
# Sanity checks
55-
if (numFiles < 2):
71+
if len(files) < 2:
5672
print("ERROR: you must specify at least two traces to combine.")
5773
sys.exit(1)
58-
for j in range(numFiles):
59-
if(not os.path.isfile(sys.argv[j+2])):
60-
print("ERROR: specified file "+sys.argv[j+2]+" cannot be found.")
74+
for filename in files:
75+
if not os.path.isfile(filename):
76+
print("ERROR: specified file {} cannot be found.".format(filename))
6177
sys.exit(1)
6278

6379
# Read input files
6480
inputFiles = []
65-
for j in range(numFiles):
66-
f = open(sys.argv[j+2],'r')
81+
for filename in files:
82+
f = open(filename,'r')
6783
currentFile = f.readlines()
6884
f.close()
6985
inputFiles.append(currentFile)
7086

7187
# Figure out epoch (earliest start_time across all records)
7288
start_times = []
73-
for j in range(numFiles):
89+
for j in range(len(files)):
7490
for k in range(len(inputFiles[j])):
7591
if (inputFiles[j][k].find("start_time") != -1):
7692
start_times.append(int(inputFiles[j][2].split(":")[-1].split("}")[0].strip('"')))
@@ -79,39 +95,43 @@ def main():
7995
print("ERROR: start_time not found in trace file "+sys.argv[j+2]+". Please check if the trace is valid.")
8096
sys.exit(1)
8197
epoch = min(start_times)
98+
print("Found minimum start time {}".format(epoch))
8299

83-
# Perform filtering if necessary
100+
# Perform filtering
84101
filteredFiles = []
85-
if (numStrings == 0):
86-
filteredFiles = inputFiles
87-
else:
88-
for j in range(numFiles):
89-
flt = [i for i in inputFiles[j] if "\"ph\":\"M\"" in i] # copy metadata
90-
for k in range(numStrings):
91-
flt = flt + [i for i in inputFiles[j] if sys.argv[2+numFiles+k] in i]
92-
filteredFiles.append(flt)
102+
for j in range(len(files)):
103+
flt = [fixup(i) for i in inputFiles[j] if filter(filters, i)]
104+
filteredFiles.append(flt)
93105

94106
# Perform epoch normalization
95-
for j in range(numFiles):
107+
for j in range(len(files)):
96108
offset = start_times[j] - epoch
109+
print("Processing file {} with offset {}".format(files[j], offset))
97110
for k in range(len(filteredFiles[j])):
98111
if (filteredFiles[j][k].find("\"ts\"") != -1):
99-
ts = int(filteredFiles[j][k].split("\"ts\":")[-1].split(",")[0]) + offset
100-
filteredFiles[j][k] = re.sub("\"ts\":\d+", "\"ts\":"+str(ts), filteredFiles[j][k])
112+
ts = float(filteredFiles[j][k].split("\"ts\":")[-1].split(",")[0]) + offset
113+
#print('old record was: {}'.format(filteredFiles[j][k].strip()))
114+
filteredFiles[j][k] = re.sub("\"ts\":[\\d.]+", "\"ts\":"+str(ts), filteredFiles[j][k])
115+
#print('new record is: {}'.format(filteredFiles[j][k].strip()))
101116
elif (filteredFiles[j][k].find("start_time") != -1):
102-
filteredFiles[j][k] = re.sub('\"start_time\":["]?\d+["]?', "\"start_time\":"+str(epoch), filteredFiles[j][k])
103-
117+
#print('old record was: {}'.format(filteredFiles[j][k].strip()))
118+
filteredFiles[j][k] = re.sub('\"start_time\":["]?\\d+["]?', "\"start_time\":"+str(epoch), filteredFiles[j][k])
119+
#print('new record is: {}'.format(filteredFiles[j][k].strip()))
120+
104121
# Write to output file
105122
tstamp = datetime.datetime.now()
106123
fName = "merged_" + str(tstamp.year) + '-' + str(tstamp.month) + '-' + str(tstamp.day) \
107124
+ '-' + str(tstamp.hour) + '-' + str(tstamp.minute)+ '-' + str(tstamp.second) + ".json"
108-
print("Combining in "+fName)
125+
print("Writing to combined file "+fName)
109126
fo = open(fName, 'w')
110127
fo.write("[\n")
111-
for j in range(numFiles):
128+
for j in range(len(files)):
112129
for k in range(1,len(filteredFiles[j])):
113130
fo.write("%s" % filteredFiles[j][k])
131+
fo.write("{\"ph\":\"M\",\"name\":\"clintercept_merged_eof\",\"pid\":0,\"tid\":0}\n")
132+
fo.write("]\n")
114133
f.close()
134+
print("Done.")
115135

116136
if __name__ == "__main__":
117137
main()

0 commit comments

Comments
 (0)