1 /*
2 * Copyright 2017 Google Inc.
3 *
4 * Use of this source code is governed by a BSD-style license that can be
5 * found in the LICENSE file.
6 */
7
8 #include "SkChromeTracingTracer.h"
9 #include "SkJSONWriter.h"
10 #include "SkThreadID.h"
11 #include "SkTraceEvent.h"
12 #include "SkOSFile.h"
13 #include "SkOSPath.h"
14 #include "SkStream.h"
15
16 #include <chrono>
17
18 namespace {
19
20 /**
21 * All events have a fixed block of information (TraceEvent), plus variable length payload:
22 * {TraceEvent} {TraceEventArgs} {Inline Payload}
23 */
24 struct TraceEventArg {
25 uint8_t fArgType;
26 const char* fArgName;
27 uint64_t fArgValue;
28 };
29
30 // These fields are ordered to minimize size due to alignment. Argument types could be packed
31 // better, but very few events have many arguments, so the net loss is pretty small.
32 struct TraceEvent {
33 char fPhase;
34 uint8_t fNumArgs;
35 uint32_t fSize;
36
37 const char* fName;
38 // TODO: Merge fID and fClockEnd (never used together)
39 uint64_t fID;
40 uint64_t fClockBegin;
41 uint64_t fClockEnd;
42 SkThreadID fThreadID;
43
next__anonb8ed95390111::TraceEvent44 TraceEvent* next() {
45 return reinterpret_cast<TraceEvent*>(reinterpret_cast<char*>(this) + fSize);
46 }
args__anonb8ed95390111::TraceEvent47 TraceEventArg* args() {
48 return reinterpret_cast<TraceEventArg*>(this + 1);
49 }
stringTable__anonb8ed95390111::TraceEvent50 char* stringTable() {
51 return reinterpret_cast<char*>(this->args() + fNumArgs);
52 }
53 };
54
55 }
56
SkChromeTracingTracer(const char * filename)57 SkChromeTracingTracer::SkChromeTracingTracer(const char* filename) : fFilename(filename) {
58 this->createBlock();
59 }
60
~SkChromeTracingTracer()61 SkChromeTracingTracer::~SkChromeTracingTracer() {
62 this->flush();
63 }
64
createBlock()65 void SkChromeTracingTracer::createBlock() {
66 fCurBlock.fBlock = BlockPtr(new uint8_t[kBlockSize]);
67 fCurBlock.fEventsInBlock = 0;
68 fCurBlockUsed = 0;
69 }
70
appendEvent(const void * data,size_t size)71 SkEventTracer::Handle SkChromeTracingTracer::appendEvent(const void* data, size_t size) {
72 SkASSERT(size > 0 && size <= kBlockSize);
73
74 SkAutoMutexAcquire lock(fMutex);
75 if (fCurBlockUsed + size > kBlockSize) {
76 fBlocks.push_back(std::move(fCurBlock));
77 this->createBlock();
78 }
79 memcpy(fCurBlock.fBlock.get() + fCurBlockUsed, data, size);
80 Handle handle = reinterpret_cast<Handle>(fCurBlock.fBlock.get() + fCurBlockUsed);
81 fCurBlockUsed += size;
82 fCurBlock.fEventsInBlock++;
83 return handle;
84 }
85
addTraceEvent(char phase,const uint8_t * categoryEnabledFlag,const char * name,uint64_t id,int numArgs,const char ** argNames,const uint8_t * argTypes,const uint64_t * argValues,uint8_t flags)86 SkEventTracer::Handle SkChromeTracingTracer::addTraceEvent(char phase,
87 const uint8_t* categoryEnabledFlag,
88 const char* name,
89 uint64_t id,
90 int numArgs,
91 const char** argNames,
92 const uint8_t* argTypes,
93 const uint64_t* argValues,
94 uint8_t flags) {
95 // TODO: Respect flags (or assert). INSTANT events encode scope in flags, should be stored
96 // using "s" key in JSON. COPY flag should be supported or rejected.
97
98 // Figure out how much extra storage we need for copied strings
99 int size = static_cast<int>(sizeof(TraceEvent) + numArgs * sizeof(TraceEventArg));
100 for (int i = 0; i < numArgs; ++i) {
101 if (TRACE_VALUE_TYPE_COPY_STRING == argTypes[i]) {
102 skia::tracing_internals::TraceValueUnion value;
103 value.as_uint = argValues[i];
104 size += strlen(value.as_string) + 1;
105 }
106 }
107
108 SkSTArray<128, uint8_t, true> storage;
109 uint8_t* storagePtr = storage.push_back_n(size);
110
111 TraceEvent* traceEvent = reinterpret_cast<TraceEvent*>(storagePtr);
112 traceEvent->fPhase = phase;
113 traceEvent->fNumArgs = numArgs;
114 traceEvent->fSize = size;
115 traceEvent->fName = name;
116 traceEvent->fID = id;
117 traceEvent->fClockBegin = std::chrono::steady_clock::now().time_since_epoch().count();
118 traceEvent->fClockEnd = 0;
119 traceEvent->fThreadID = SkGetThreadID();
120
121 TraceEventArg* traceEventArgs = traceEvent->args();
122 char* stringTableBase = traceEvent->stringTable();
123 char* stringTable = stringTableBase;
124 for (int i = 0; i < numArgs; ++i) {
125 traceEventArgs[i].fArgName = argNames[i];
126 traceEventArgs[i].fArgType = argTypes[i];
127 if (TRACE_VALUE_TYPE_COPY_STRING == argTypes[i]) {
128 // Just write an offset into the arguments array
129 traceEventArgs[i].fArgValue = stringTable - stringTableBase;
130
131 // Copy string into our buffer (and advance)
132 skia::tracing_internals::TraceValueUnion value;
133 value.as_uint = argValues[i];
134 while (*value.as_string) {
135 *stringTable++ = *value.as_string++;
136 }
137 *stringTable++ = 0;
138 } else {
139 traceEventArgs[i].fArgValue = argValues[i];
140 }
141 }
142
143 return this->appendEvent(storagePtr, size);
144 }
145
updateTraceEventDuration(const uint8_t * categoryEnabledFlag,const char * name,SkEventTracer::Handle handle)146 void SkChromeTracingTracer::updateTraceEventDuration(const uint8_t* categoryEnabledFlag,
147 const char* name,
148 SkEventTracer::Handle handle) {
149 // We could probably get away with not locking here, but let's be totally safe.
150 SkAutoMutexAcquire lock(fMutex);
151 TraceEvent* traceEvent = reinterpret_cast<TraceEvent*>(handle);
152 traceEvent->fClockEnd = std::chrono::steady_clock::now().time_since_epoch().count();
153 }
154
trace_value_to_json(SkJSONWriter * writer,uint64_t argValue,uint8_t argType,const char * stringTableBase)155 static void trace_value_to_json(SkJSONWriter* writer, uint64_t argValue, uint8_t argType,
156 const char* stringTableBase) {
157 skia::tracing_internals::TraceValueUnion value;
158 value.as_uint = argValue;
159
160 switch (argType) {
161 case TRACE_VALUE_TYPE_BOOL:
162 writer->appendBool(value.as_bool);
163 break;
164 case TRACE_VALUE_TYPE_UINT:
165 writer->appendU64(value.as_uint);
166 break;
167 case TRACE_VALUE_TYPE_INT:
168 writer->appendS64(value.as_int);
169 break;
170 case TRACE_VALUE_TYPE_DOUBLE:
171 writer->appendDouble(value.as_double);
172 break;
173 case TRACE_VALUE_TYPE_POINTER:
174 writer->appendPointer(value.as_pointer);
175 break;
176 case TRACE_VALUE_TYPE_STRING:
177 writer->appendString(value.as_string);
178 break;
179 case TRACE_VALUE_TYPE_COPY_STRING:
180 writer->appendString(stringTableBase + value.as_uint);
181 break;
182 default:
183 writer->appendString("<unknown type>");
184 break;
185 }
186 }
187
188 namespace {
189
190 struct TraceEventSerializationState {
TraceEventSerializationState__anonb8ed95390211::TraceEventSerializationState191 TraceEventSerializationState(uint64_t clockOffset)
192 : fClockOffset(clockOffset), fNextThreadID(0) {}
193
getShortThreadID__anonb8ed95390211::TraceEventSerializationState194 int getShortThreadID(SkThreadID id) {
195 if (int* shortIDPtr = fShortThreadIDMap.find(id)) {
196 return *shortIDPtr;
197 }
198 int shortID = fNextThreadID++;
199 fShortThreadIDMap.set(id, shortID);
200 return shortID;
201 }
202
203 uint64_t fClockOffset;
204 SkTHashMap<uint64_t, const char*> fBaseTypeResolver;
205 int fNextThreadID;
206 SkTHashMap<SkThreadID, int> fShortThreadIDMap;
207 };
208
209 }
210
trace_event_to_json(SkJSONWriter * writer,TraceEvent * traceEvent,TraceEventSerializationState * serializationState)211 static void trace_event_to_json(SkJSONWriter* writer, TraceEvent* traceEvent,
212 TraceEventSerializationState* serializationState) {
213 // We track the original (creation time) "name" of each currently live object, so we can
214 // automatically insert "base_name" fields in object snapshot events.
215 auto baseTypeResolver = &(serializationState->fBaseTypeResolver);
216 if (TRACE_EVENT_PHASE_CREATE_OBJECT == traceEvent->fPhase) {
217 SkASSERT(nullptr == baseTypeResolver->find(traceEvent->fID));
218 baseTypeResolver->set(traceEvent->fID, traceEvent->fName);
219 } else if (TRACE_EVENT_PHASE_DELETE_OBJECT == traceEvent->fPhase) {
220 SkASSERT(nullptr != baseTypeResolver->find(traceEvent->fID));
221 baseTypeResolver->remove(traceEvent->fID);
222 }
223
224 writer->beginObject();
225
226 char phaseString[2] = { traceEvent->fPhase, 0 };
227 writer->appendString("ph", phaseString);
228 writer->appendString("name", traceEvent->fName);
229 if (0 != traceEvent->fID) {
230 // IDs are (almost) always pointers
231 writer->appendPointer("id", reinterpret_cast<void*>(traceEvent->fID));
232 }
233
234 // Offset timestamps to reduce JSON length, then convert nanoseconds to microseconds
235 // (standard time unit for tracing JSON files).
236 uint64_t relativeTimestamp = static_cast<int64_t>(traceEvent->fClockBegin -
237 serializationState->fClockOffset);
238 writer->appendDoubleDigits("ts", static_cast<double>(relativeTimestamp) * 1E-3, 3);
239 if (0 != traceEvent->fClockEnd) {
240 double dur = static_cast<double>(traceEvent->fClockEnd - traceEvent->fClockBegin) * 1E-3;
241 writer->appendDoubleDigits("dur", dur, 3);
242 }
243
244 writer->appendS64("tid", serializationState->getShortThreadID(traceEvent->fThreadID));
245 // Trace events *must* include a process ID, but for internal tools this isn't particularly
246 // important (and certainly not worth adding a cross-platform API to get it).
247 writer->appendS32("pid", 0);
248
249 if (traceEvent->fNumArgs) {
250 writer->beginObject("args");
251 const char* stringTable = traceEvent->stringTable();
252 bool addedSnapshot = false;
253 if (TRACE_EVENT_PHASE_SNAPSHOT_OBJECT == traceEvent->fPhase &&
254 baseTypeResolver->find(traceEvent->fID) &&
255 0 != strcmp(*baseTypeResolver->find(traceEvent->fID), traceEvent->fName)) {
256 // Special handling for snapshots where the name differs from creation.
257 writer->beginObject("snapshot");
258 writer->appendString("base_type", *baseTypeResolver->find(traceEvent->fID));
259 addedSnapshot = true;
260 }
261
262 for (int i = 0; i < traceEvent->fNumArgs; ++i) {
263 const TraceEventArg* arg = traceEvent->args() + i;
264 // TODO: Skip '#'
265 writer->appendName(arg->fArgName);
266
267 if (arg->fArgName && '#' == arg->fArgName[0]) {
268 writer->beginObject();
269 writer->appendName("id_ref");
270 trace_value_to_json(writer, arg->fArgValue, arg->fArgType, stringTable);
271 writer->endObject();
272 } else {
273 trace_value_to_json(writer, arg->fArgValue, arg->fArgType, stringTable);
274 }
275 }
276
277 if (addedSnapshot) {
278 writer->endObject();
279 }
280
281 writer->endObject();
282 }
283
284 writer->endObject();
285 }
286
flush()287 void SkChromeTracingTracer::flush() {
288 SkAutoMutexAcquire lock(fMutex);
289
290 SkString dirname = SkOSPath::Dirname(fFilename.c_str());
291 if (!dirname.isEmpty() && !sk_exists(dirname.c_str(), kWrite_SkFILE_Flag)) {
292 if (!sk_mkdir(dirname.c_str())) {
293 SkDebugf("Failed to create directory.");
294 }
295 }
296
297 SkFILEWStream fileStream(fFilename.c_str());
298 SkJSONWriter writer(&fileStream, SkJSONWriter::Mode::kFast);
299 writer.beginArray();
300
301 uint64_t clockOffset = 0;
302 if (fBlocks.count() > 0) {
303 clockOffset = reinterpret_cast<TraceEvent*>(fBlocks[0].fBlock.get())->fClockBegin;
304 } else if (fCurBlock.fEventsInBlock > 0) {
305 clockOffset = reinterpret_cast<TraceEvent*>(fCurBlock.fBlock.get())->fClockBegin;
306 }
307
308 TraceEventSerializationState serializationState(clockOffset);
309
310 auto event_block_to_json = [](SkJSONWriter* writer, const TraceEventBlock& block,
311 TraceEventSerializationState* serializationState) {
312 TraceEvent* traceEvent = reinterpret_cast<TraceEvent*>(block.fBlock.get());
313 for (int i = 0; i < block.fEventsInBlock; ++i) {
314 trace_event_to_json(writer, traceEvent, serializationState);
315 traceEvent = traceEvent->next();
316 }
317 };
318
319 for (int i = 0; i < fBlocks.count(); ++i) {
320 event_block_to_json(&writer, fBlocks[i], &serializationState);
321 }
322 event_block_to_json(&writer, fCurBlock, &serializationState);
323
324 writer.endArray();
325 writer.flush();
326 fileStream.flush();
327 }
328