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