skia2/tools/trace/SkChromeTracingTracer.cpp
Brian Osman b6f8212bff Optimize the size of our JSON
Catapult (Chrome tracing) has a hard upper limit of 256 MB of JSON data.
This is independent of the number of events, because V8 can't store a
single string longer than that. Before these changes, longer traces
(eg all GL GMs, which was my test case) would be much larger (306 MB).

This CL includes four changes that help to reduce the text size:

1) Offset timestamps (saved 7.3 MB)
2) Limit timestamps and durations to 3 digits (saved 10.7 MB)
3) Shorten thread IDs (saved 7.2 MB)
4) Omit categories from JSON (saved 25.7 MB)

Note that category filtering still works, this just prevents us from
writing the categories to the JSON, which was of limited value.

At this point, my 306 MB file is now 255.3 MB, and loads.

Bug: skia:
Change-Id: Iaafc84025ddd52904f1ce9c1c2e9cbca65113079
Reviewed-on: https://skia-review.googlesource.com/35523
Reviewed-by: Mike Klein <mtklein@chromium.org>
Commit-Queue: Brian Osman <brianosman@google.com>
2017-08-17 11:51:26 +00:00

328 lines
12 KiB
C++

/*
* Copyright 2017 Google Inc.
*
* Use of this source code is governed by a BSD-style license that can be
* found in the LICENSE file.
*/
#include "SkChromeTracingTracer.h"
#include "SkJSONWriter.h"
#include "SkThreadID.h"
#include "SkTraceEvent.h"
#include "SkOSFile.h"
#include "SkOSPath.h"
#include "SkStream.h"
#include <chrono>
namespace {
/**
* All events have a fixed block of information (TraceEvent), plus variable length payload:
* {TraceEvent} {TraceEventArgs} {Inline Payload}
*/
struct TraceEventArg {
uint8_t fArgType;
const char* fArgName;
uint64_t fArgValue;
};
// These fields are ordered to minimize size due to alignment. Argument types could be packed
// better, but very few events have many arguments, so the net loss is pretty small.
struct TraceEvent {
char fPhase;
uint8_t fNumArgs;
uint32_t fSize;
const char* fName;
// TODO: Merge fID and fClockEnd (never used together)
uint64_t fID;
uint64_t fClockBegin;
uint64_t fClockEnd;
SkThreadID fThreadID;
TraceEvent* next() {
return reinterpret_cast<TraceEvent*>(reinterpret_cast<char*>(this) + fSize);
}
TraceEventArg* args() {
return reinterpret_cast<TraceEventArg*>(this + 1);
}
char* stringTable() {
return reinterpret_cast<char*>(this->args() + fNumArgs);
}
};
}
SkChromeTracingTracer::SkChromeTracingTracer(const char* filename) : fFilename(filename) {
this->createBlock();
}
SkChromeTracingTracer::~SkChromeTracingTracer() {
this->flush();
}
void SkChromeTracingTracer::createBlock() {
fCurBlock.fBlock = BlockPtr(new uint8_t[kBlockSize]);
fCurBlock.fEventsInBlock = 0;
fCurBlockUsed = 0;
}
SkEventTracer::Handle SkChromeTracingTracer::appendEvent(const void* data, size_t size) {
SkASSERT(size > 0 && size <= kBlockSize);
SkAutoMutexAcquire lock(fMutex);
if (fCurBlockUsed + size > kBlockSize) {
fBlocks.push_back(std::move(fCurBlock));
this->createBlock();
}
memcpy(fCurBlock.fBlock.get() + fCurBlockUsed, data, size);
Handle handle = reinterpret_cast<Handle>(fCurBlock.fBlock.get() + fCurBlockUsed);
fCurBlockUsed += size;
fCurBlock.fEventsInBlock++;
return handle;
}
SkEventTracer::Handle SkChromeTracingTracer::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) {
// TODO: Respect flags (or assert). INSTANT events encode scope in flags, should be stored
// using "s" key in JSON. COPY flag should be supported or rejected.
// Figure out how much extra storage we need for copied strings
int size = static_cast<int>(sizeof(TraceEvent) + numArgs * sizeof(TraceEventArg));
for (int i = 0; i < numArgs; ++i) {
if (TRACE_VALUE_TYPE_COPY_STRING == argTypes[i]) {
skia::tracing_internals::TraceValueUnion value;
value.as_uint = argValues[i];
size += strlen(value.as_string) + 1;
}
}
SkSTArray<128, uint8_t, true> storage;
uint8_t* storagePtr = storage.push_back_n(size);
TraceEvent* traceEvent = reinterpret_cast<TraceEvent*>(storagePtr);
traceEvent->fPhase = phase;
traceEvent->fNumArgs = numArgs;
traceEvent->fSize = size;
traceEvent->fName = name;
traceEvent->fID = id;
traceEvent->fClockBegin = std::chrono::steady_clock::now().time_since_epoch().count();
traceEvent->fClockEnd = 0;
traceEvent->fThreadID = SkGetThreadID();
TraceEventArg* traceEventArgs = traceEvent->args();
char* stringTableBase = traceEvent->stringTable();
char* stringTable = stringTableBase;
for (int i = 0; i < numArgs; ++i) {
traceEventArgs[i].fArgName = argNames[i];
traceEventArgs[i].fArgType = argTypes[i];
if (TRACE_VALUE_TYPE_COPY_STRING == argTypes[i]) {
// Just write an offset into the arguments array
traceEventArgs[i].fArgValue = stringTable - stringTableBase;
// Copy string into our buffer (and advance)
skia::tracing_internals::TraceValueUnion value;
value.as_uint = argValues[i];
while (*value.as_string) {
*stringTable++ = *value.as_string++;
}
*stringTable++ = 0;
} else {
traceEventArgs[i].fArgValue = argValues[i];
}
}
return this->appendEvent(storagePtr, size);
}
void SkChromeTracingTracer::updateTraceEventDuration(const uint8_t* categoryEnabledFlag,
const char* name,
SkEventTracer::Handle handle) {
// We could probably get away with not locking here, but let's be totally safe.
SkAutoMutexAcquire lock(fMutex);
TraceEvent* traceEvent = reinterpret_cast<TraceEvent*>(handle);
traceEvent->fClockEnd = std::chrono::steady_clock::now().time_since_epoch().count();
}
static void trace_value_to_json(SkJSONWriter* writer, uint64_t argValue, uint8_t argType,
const char* stringTableBase) {
skia::tracing_internals::TraceValueUnion value;
value.as_uint = argValue;
switch (argType) {
case TRACE_VALUE_TYPE_BOOL:
writer->appendBool(value.as_bool);
break;
case TRACE_VALUE_TYPE_UINT:
writer->appendU64(value.as_uint);
break;
case TRACE_VALUE_TYPE_INT:
writer->appendS64(value.as_int);
break;
case TRACE_VALUE_TYPE_DOUBLE:
writer->appendDouble(value.as_double);
break;
case TRACE_VALUE_TYPE_POINTER:
writer->appendPointer(value.as_pointer);
break;
case TRACE_VALUE_TYPE_STRING:
writer->appendString(value.as_string);
break;
case TRACE_VALUE_TYPE_COPY_STRING:
writer->appendString(stringTableBase + value.as_uint);
break;
default:
writer->appendString("<unknown type>");
break;
}
}
namespace {
struct TraceEventSerializationState {
TraceEventSerializationState(uint64_t clockOffset)
: fClockOffset(clockOffset), fNextThreadID(0) {}
int getShortThreadID(SkThreadID id) {
if (int* shortIDPtr = fShortThreadIDMap.find(id)) {
return *shortIDPtr;
}
int shortID = fNextThreadID++;
fShortThreadIDMap.set(id, shortID);
return shortID;
}
uint64_t fClockOffset;
SkTHashMap<uint64_t, const char*> fBaseTypeResolver;
int fNextThreadID;
SkTHashMap<SkThreadID, int> fShortThreadIDMap;
};
}
static void trace_event_to_json(SkJSONWriter* writer, TraceEvent* traceEvent,
TraceEventSerializationState* serializationState) {
// We track the original (creation time) "name" of each currently live object, so we can
// automatically insert "base_name" fields in object snapshot events.
auto baseTypeResolver = &(serializationState->fBaseTypeResolver);
if (TRACE_EVENT_PHASE_CREATE_OBJECT == traceEvent->fPhase) {
SkASSERT(nullptr == baseTypeResolver->find(traceEvent->fID));
baseTypeResolver->set(traceEvent->fID, traceEvent->fName);
} else if (TRACE_EVENT_PHASE_DELETE_OBJECT == traceEvent->fPhase) {
SkASSERT(nullptr != baseTypeResolver->find(traceEvent->fID));
baseTypeResolver->remove(traceEvent->fID);
}
writer->beginObject();
char phaseString[2] = { traceEvent->fPhase, 0 };
writer->appendString("ph", phaseString);
writer->appendString("name", traceEvent->fName);
if (0 != traceEvent->fID) {
// IDs are (almost) always pointers
writer->appendPointer("id", reinterpret_cast<void*>(traceEvent->fID));
}
// Offset timestamps to reduce JSON length, then convert nanoseconds to microseconds
// (standard time unit for tracing JSON files).
uint64_t relativeTimestamp = static_cast<int64_t>(traceEvent->fClockBegin -
serializationState->fClockOffset);
writer->appendDoubleDigits("ts", static_cast<double>(relativeTimestamp) * 1E-3, 3);
if (0 != traceEvent->fClockEnd) {
double dur = static_cast<double>(traceEvent->fClockEnd - traceEvent->fClockBegin) * 1E-3;
writer->appendDoubleDigits("dur", dur, 3);
}
writer->appendS64("tid", serializationState->getShortThreadID(traceEvent->fThreadID));
// Trace events *must* include a process ID, but for internal tools this isn't particularly
// important (and certainly not worth adding a cross-platform API to get it).
writer->appendS32("pid", 0);
if (traceEvent->fNumArgs) {
writer->beginObject("args");
const char* stringTable = traceEvent->stringTable();
bool addedSnapshot = false;
if (TRACE_EVENT_PHASE_SNAPSHOT_OBJECT == traceEvent->fPhase &&
baseTypeResolver->find(traceEvent->fID) &&
0 != strcmp(*baseTypeResolver->find(traceEvent->fID), traceEvent->fName)) {
// Special handling for snapshots where the name differs from creation.
writer->beginObject("snapshot");
writer->appendString("base_type", *baseTypeResolver->find(traceEvent->fID));
addedSnapshot = true;
}
for (int i = 0; i < traceEvent->fNumArgs; ++i) {
const TraceEventArg* arg = traceEvent->args() + i;
// TODO: Skip '#'
writer->appendName(arg->fArgName);
if (arg->fArgName && '#' == arg->fArgName[0]) {
writer->beginObject();
writer->appendName("id_ref");
trace_value_to_json(writer, arg->fArgValue, arg->fArgType, stringTable);
writer->endObject();
} else {
trace_value_to_json(writer, arg->fArgValue, arg->fArgType, stringTable);
}
}
if (addedSnapshot) {
writer->endObject();
}
writer->endObject();
}
writer->endObject();
}
void SkChromeTracingTracer::flush() {
SkAutoMutexAcquire lock(fMutex);
SkString dirname = SkOSPath::Dirname(fFilename.c_str());
if (!dirname.isEmpty() && !sk_exists(dirname.c_str(), kWrite_SkFILE_Flag)) {
if (!sk_mkdir(dirname.c_str())) {
SkDebugf("Failed to create directory.");
}
}
SkFILEWStream fileStream(fFilename.c_str());
SkJSONWriter writer(&fileStream, SkJSONWriter::Mode::kFast);
writer.beginArray();
uint64_t clockOffset = 0;
if (fBlocks.count() > 0) {
clockOffset = reinterpret_cast<TraceEvent*>(fBlocks[0].fBlock.get())->fClockBegin;
} else if (fCurBlock.fEventsInBlock > 0) {
clockOffset = reinterpret_cast<TraceEvent*>(fCurBlock.fBlock.get())->fClockBegin;
}
TraceEventSerializationState serializationState(clockOffset);
auto event_block_to_json = [](SkJSONWriter* writer, const TraceEventBlock& block,
TraceEventSerializationState* serializationState) {
TraceEvent* traceEvent = reinterpret_cast<TraceEvent*>(block.fBlock.get());
for (int i = 0; i < block.fEventsInBlock; ++i) {
trace_event_to_json(writer, traceEvent, serializationState);
traceEvent = traceEvent->next();
}
};
for (int i = 0; i < fBlocks.count(); ++i) {
event_block_to_json(&writer, fBlocks[i], &serializationState);
}
event_block_to_json(&writer, fCurBlock, &serializationState);
writer.endArray();
writer.flush();
fileStream.flush();
}