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     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__anon47fb72f30211::TraceEventSerializationState191     TraceEventSerializationState(uint64_t clockOffset)
192             : fClockOffset(clockOffset), fNextThreadID(0) {}
193 
getShortThreadID__anon47fb72f30211::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