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__anon47fb72f30111::TraceEvent44 TraceEvent* next() {
45 return reinterpret_cast<TraceEvent*>(reinterpret_cast<char*>(this) + fSize);
46 }
args__anon47fb72f30111::TraceEvent47 TraceEventArg* args() {
48 return reinterpret_cast<TraceEventArg*>(this + 1);
49 }
stringTable__anon47fb72f30111::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 size = SkAlign8(size);
109
110 SkSTArray<128, uint8_t, true> storage;
111 uint8_t* storagePtr = storage.push_back_n(size);
112
113 TraceEvent* traceEvent = reinterpret_cast<TraceEvent*>(storagePtr);
114 traceEvent->fPhase = phase;
115 traceEvent->fNumArgs = numArgs;
116 traceEvent->fSize = size;
117 traceEvent->fName = name;
118 traceEvent->fID = id;
119 traceEvent->fClockBegin = std::chrono::steady_clock::now().time_since_epoch().count();
120 traceEvent->fClockEnd = 0;
121 traceEvent->fThreadID = SkGetThreadID();
122
123 TraceEventArg* traceEventArgs = traceEvent->args();
124 char* stringTableBase = traceEvent->stringTable();
125 char* stringTable = stringTableBase;
126 for (int i = 0; i < numArgs; ++i) {
127 traceEventArgs[i].fArgName = argNames[i];
128 traceEventArgs[i].fArgType = argTypes[i];
129 if (TRACE_VALUE_TYPE_COPY_STRING == argTypes[i]) {
130 // Just write an offset into the arguments array
131 traceEventArgs[i].fArgValue = stringTable - stringTableBase;
132
133 // Copy string into our buffer (and advance)
134 skia::tracing_internals::TraceValueUnion value;
135 value.as_uint = argValues[i];
136 while (*value.as_string) {
137 *stringTable++ = *value.as_string++;
138 }
139 *stringTable++ = 0;
140 } else {
141 traceEventArgs[i].fArgValue = argValues[i];
142 }
143 }
144
145 return this->appendEvent(storagePtr, size);
146 }
147
updateTraceEventDuration(const uint8_t * categoryEnabledFlag,const char * name,SkEventTracer::Handle handle)148 void SkChromeTracingTracer::updateTraceEventDuration(const uint8_t* categoryEnabledFlag,
149 const char* name,
150 SkEventTracer::Handle handle) {
151 // We could probably get away with not locking here, but let's be totally safe.
152 SkAutoMutexAcquire lock(fMutex);
153 TraceEvent* traceEvent = reinterpret_cast<TraceEvent*>(handle);
154 traceEvent->fClockEnd = std::chrono::steady_clock::now().time_since_epoch().count();
155 }
156
trace_value_to_json(SkJSONWriter * writer,uint64_t argValue,uint8_t argType,const char * stringTableBase)157 static void trace_value_to_json(SkJSONWriter* writer, uint64_t argValue, uint8_t argType,
158 const char* stringTableBase) {
159 skia::tracing_internals::TraceValueUnion value;
160 value.as_uint = argValue;
161
162 switch (argType) {
163 case TRACE_VALUE_TYPE_BOOL:
164 writer->appendBool(value.as_bool);
165 break;
166 case TRACE_VALUE_TYPE_UINT:
167 writer->appendU64(value.as_uint);
168 break;
169 case TRACE_VALUE_TYPE_INT:
170 writer->appendS64(value.as_int);
171 break;
172 case TRACE_VALUE_TYPE_DOUBLE:
173 writer->appendDouble(value.as_double);
174 break;
175 case TRACE_VALUE_TYPE_POINTER:
176 writer->appendPointer(value.as_pointer);
177 break;
178 case TRACE_VALUE_TYPE_STRING:
179 writer->appendString(value.as_string);
180 break;
181 case TRACE_VALUE_TYPE_COPY_STRING:
182 writer->appendString(stringTableBase + value.as_uint);
183 break;
184 default:
185 writer->appendString("<unknown type>");
186 break;
187 }
188 }
189
190 namespace {
191
192 struct TraceEventSerializationState {
TraceEventSerializationState__anon47fb72f30211::TraceEventSerializationState193 TraceEventSerializationState(uint64_t clockOffset)
194 : fClockOffset(clockOffset), fNextThreadID(0) {}
195
getShortThreadID__anon47fb72f30211::TraceEventSerializationState196 int getShortThreadID(SkThreadID id) {
197 if (int* shortIDPtr = fShortThreadIDMap.find(id)) {
198 return *shortIDPtr;
199 }
200 int shortID = fNextThreadID++;
201 fShortThreadIDMap.set(id, shortID);
202 return shortID;
203 }
204
205 uint64_t fClockOffset;
206 SkTHashMap<uint64_t, const char*> fBaseTypeResolver;
207 int fNextThreadID;
208 SkTHashMap<SkThreadID, int> fShortThreadIDMap;
209 };
210
211 }
212
trace_event_to_json(SkJSONWriter * writer,TraceEvent * traceEvent,TraceEventSerializationState * serializationState)213 static void trace_event_to_json(SkJSONWriter* writer, TraceEvent* traceEvent,
214 TraceEventSerializationState* serializationState) {
215 // We track the original (creation time) "name" of each currently live object, so we can
216 // automatically insert "base_name" fields in object snapshot events.
217 auto baseTypeResolver = &(serializationState->fBaseTypeResolver);
218 if (TRACE_EVENT_PHASE_CREATE_OBJECT == traceEvent->fPhase) {
219 SkASSERT(nullptr == baseTypeResolver->find(traceEvent->fID));
220 baseTypeResolver->set(traceEvent->fID, traceEvent->fName);
221 } else if (TRACE_EVENT_PHASE_DELETE_OBJECT == traceEvent->fPhase) {
222 SkASSERT(nullptr != baseTypeResolver->find(traceEvent->fID));
223 baseTypeResolver->remove(traceEvent->fID);
224 }
225
226 writer->beginObject();
227
228 char phaseString[2] = { traceEvent->fPhase, 0 };
229 writer->appendString("ph", phaseString);
230 writer->appendString("name", traceEvent->fName);
231 if (0 != traceEvent->fID) {
232 // IDs are (almost) always pointers
233 writer->appendPointer("id", reinterpret_cast<void*>(traceEvent->fID));
234 }
235
236 // Offset timestamps to reduce JSON length, then convert nanoseconds to microseconds
237 // (standard time unit for tracing JSON files).
238 uint64_t relativeTimestamp = static_cast<int64_t>(traceEvent->fClockBegin -
239 serializationState->fClockOffset);
240 writer->appendDoubleDigits("ts", static_cast<double>(relativeTimestamp) * 1E-3, 3);
241 if (0 != traceEvent->fClockEnd) {
242 double dur = static_cast<double>(traceEvent->fClockEnd - traceEvent->fClockBegin) * 1E-3;
243 writer->appendDoubleDigits("dur", dur, 3);
244 }
245
246 writer->appendS64("tid", serializationState->getShortThreadID(traceEvent->fThreadID));
247 // Trace events *must* include a process ID, but for internal tools this isn't particularly
248 // important (and certainly not worth adding a cross-platform API to get it).
249 writer->appendS32("pid", 0);
250
251 if (traceEvent->fNumArgs) {
252 writer->beginObject("args");
253 const char* stringTable = traceEvent->stringTable();
254 bool addedSnapshot = false;
255 if (TRACE_EVENT_PHASE_SNAPSHOT_OBJECT == traceEvent->fPhase &&
256 baseTypeResolver->find(traceEvent->fID) &&
257 0 != strcmp(*baseTypeResolver->find(traceEvent->fID), traceEvent->fName)) {
258 // Special handling for snapshots where the name differs from creation.
259 writer->beginObject("snapshot");
260 writer->appendString("base_type", *baseTypeResolver->find(traceEvent->fID));
261 addedSnapshot = true;
262 }
263
264 for (int i = 0; i < traceEvent->fNumArgs; ++i) {
265 const TraceEventArg* arg = traceEvent->args() + i;
266 // TODO: Skip '#'
267 writer->appendName(arg->fArgName);
268
269 if (arg->fArgName && '#' == arg->fArgName[0]) {
270 writer->beginObject();
271 writer->appendName("id_ref");
272 trace_value_to_json(writer, arg->fArgValue, arg->fArgType, stringTable);
273 writer->endObject();
274 } else {
275 trace_value_to_json(writer, arg->fArgValue, arg->fArgType, stringTable);
276 }
277 }
278
279 if (addedSnapshot) {
280 writer->endObject();
281 }
282
283 writer->endObject();
284 }
285
286 writer->endObject();
287 }
288
flush()289 void SkChromeTracingTracer::flush() {
290 SkAutoMutexAcquire lock(fMutex);
291
292 SkString dirname = SkOSPath::Dirname(fFilename.c_str());
293 if (!dirname.isEmpty() && !sk_exists(dirname.c_str(), kWrite_SkFILE_Flag)) {
294 if (!sk_mkdir(dirname.c_str())) {
295 SkDebugf("Failed to create directory.");
296 }
297 }
298
299 SkFILEWStream fileStream(fFilename.c_str());
300 SkJSONWriter writer(&fileStream, SkJSONWriter::Mode::kFast);
301 writer.beginArray();
302
303 uint64_t clockOffset = 0;
304 if (fBlocks.count() > 0) {
305 clockOffset = reinterpret_cast<TraceEvent*>(fBlocks[0].fBlock.get())->fClockBegin;
306 } else if (fCurBlock.fEventsInBlock > 0) {
307 clockOffset = reinterpret_cast<TraceEvent*>(fCurBlock.fBlock.get())->fClockBegin;
308 }
309
310 TraceEventSerializationState serializationState(clockOffset);
311
312 auto event_block_to_json = [](SkJSONWriter* writer, const TraceEventBlock& block,
313 TraceEventSerializationState* serializationState) {
314 TraceEvent* traceEvent = reinterpret_cast<TraceEvent*>(block.fBlock.get());
315 for (int i = 0; i < block.fEventsInBlock; ++i) {
316 trace_event_to_json(writer, traceEvent, serializationState);
317 traceEvent = traceEvent->next();
318 }
319 };
320
321 for (int i = 0; i < fBlocks.count(); ++i) {
322 event_block_to_json(&writer, fBlocks[i], &serializationState);
323 }
324 event_block_to_json(&writer, fCurBlock, &serializationState);
325
326 writer.endArray();
327 writer.flush();
328 fileStream.flush();
329 }
330