Record all trace event data inline, with variable sized entries

Removes the need for strdup with copied strings, paves the way for
more (and richer) payload, and shrinks the average event way down.

Bug: skia:
Change-Id: I9604fe713c34cfc877dce84563af89c579abd65b
Reviewed-on: https://skia-review.googlesource.com/35166
Reviewed-by: Mike Klein <mtklein@google.com>
Reviewed-by: Brian Salomon <bsalomon@google.com>
Commit-Queue: Brian Osman <brianosman@google.com>

1 files changed, 140 insertions, 63 deletions

diff --git a/tools/trace/SkChromeTracingTracer.cpp b/tools/trace/SkChromeTracingTracer.cpp
index ced4f74fa9..7a78e4d6a5 100644
--- a/tools/trace/SkChromeTracingTracer.cpp
+++ b/tools/trace/SkChromeTracingTracer.cpp
@@ -15,29 +15,73 @@
 
 #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;
+    const char* fCategory;
+    // 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) {
-    fCurBlock = this->createBlock();
-    fEventsInCurBlock = 0;
+    this->createBlock();
 }
 
 SkChromeTracingTracer::~SkChromeTracingTracer() {
     this->flush();
 }
 
-SkChromeTracingTracer::BlockPtr SkChromeTracingTracer::createBlock() {
-    return BlockPtr(new TraceEvent[kEventsPerBlock]);
+void SkChromeTracingTracer::createBlock() {
+    fCurBlock.fBlock = BlockPtr(new uint8_t[kBlockSize]);
+    fCurBlock.fEventsInBlock = 0;
+    fCurBlockUsed = 0;
 }
 
-SkChromeTracingTracer::TraceEvent* SkChromeTracingTracer::appendEvent(
-        const TraceEvent& traceEvent) {
+SkEventTracer::Handle SkChromeTracingTracer::appendEvent(const void* data, size_t size) {
+    SkASSERT(size > 0 && size <= kBlockSize);
+
     SkAutoMutexAcquire lock(fMutex);
-    if (fEventsInCurBlock >= kEventsPerBlock) {
+    if (fCurBlockUsed + size > kBlockSize) {
         fBlocks.push_back(std::move(fCurBlock));
-        fCurBlock = this->createBlock();
-        fEventsInCurBlock = 0;
+        this->createBlock();
     }
-    fCurBlock[fEventsInCurBlock] = traceEvent;
-    return &fCurBlock[fEventsInCurBlock++];
+    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,
@@ -52,30 +96,53 @@ SkEventTracer::Handle SkChromeTracingTracer::addTraceEvent(char phase,
     // 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.
 
-    TraceEvent traceEvent;
-    traceEvent.fPhase = phase;
-    traceEvent.fNumArgs = numArgs;
-    traceEvent.fName = name;
-    traceEvent.fCategory = fCategories.getCategoryGroupName(categoryEnabledFlag);
-    traceEvent.fID = id;
-    traceEvent.fClockBegin = std::chrono::high_resolution_clock::now().time_since_epoch().count();
-    traceEvent.fClockEnd = 0;
-    traceEvent.fThreadID = SkGetThreadID();
+    // 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->fCategory = fCategories.getCategoryGroupName(categoryEnabledFlag);
+    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) {
-        traceEvent.fArgNames[i] = argNames[i];
-        traceEvent.fArgTypes[i] = argTypes[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];
-            value.as_string = SkStrDup(value.as_string);
-            traceEvent.fArgValues[i] = value.as_uint;
+            while (*value.as_string) {
+                *stringTable++ = *value.as_string++;
+            }
+            *stringTable++ = 0;
         } else {
-            traceEvent.fArgValues[i] = argValues[i];
+            traceEventArgs[i].fArgValue = argValues[i];
         }
     }
 
-    return reinterpret_cast<Handle>(this->appendEvent(traceEvent));
+    return this->appendEvent(storagePtr, size);
 }
 
 void SkChromeTracingTracer::updateTraceEventDuration(const uint8_t* categoryEnabledFlag,
@@ -84,10 +151,11 @@ void SkChromeTracingTracer::updateTraceEventDuration(const uint8_t* categoryEnab
     // 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::high_resolution_clock::now().time_since_epoch().count();
+    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) {
+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;
 
@@ -108,72 +176,77 @@ static void trace_value_to_json(SkJSONWriter* writer, uint64_t argValue, uint8_t
             writer->appendPointer(value.as_pointer);
             break;
         case TRACE_VALUE_TYPE_STRING:
-        case TRACE_VALUE_TYPE_COPY_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;
     }
 }
 
-void SkChromeTracingTracer::traceEventToJson(SkJSONWriter* writer, const TraceEvent& traceEvent,
-                                             BaseTypeResolver* baseTypeResolver) {
+typedef SkTHashMap<uint64_t, const char*> BaseTypeResolver;
+
+static void trace_event_to_json(SkJSONWriter* writer, TraceEvent* traceEvent,
+                                BaseTypeResolver* baseTypeResolver) {
     // We track the original (creation time) "name" of each currently live object, so we can
     // automatically insert "base_name" fields in object snapshot events.
-    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);
+    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 };
+    char phaseString[2] = { traceEvent->fPhase, 0 };
     writer->appendString("ph", phaseString);
-    writer->appendString("name", traceEvent.fName);
-    writer->appendString("cat", traceEvent.fCategory);
-    if (0 != traceEvent.fID) {
+    writer->appendString("name", traceEvent->fName);
+    writer->appendString("cat", traceEvent->fCategory);
+    if (0 != traceEvent->fID) {
         // IDs are (almost) always pointers
-        writer->appendPointer("id", reinterpret_cast<void*>(traceEvent.fID));
+        writer->appendPointer("id", reinterpret_cast<void*>(traceEvent->fID));
     }
     // Convert nanoseconds to microseconds (standard time unit for tracing JSON files)
-    writer->appendDouble("ts", static_cast<double>(traceEvent.fClockBegin) * 1E-3);
-    if (0 != traceEvent.fClockEnd) {
-        double dur = static_cast<double>(traceEvent.fClockEnd - traceEvent.fClockBegin) * 1E-3;
+    writer->appendDouble("ts", static_cast<double>(traceEvent->fClockBegin) * 1E-3);
+    if (0 != traceEvent->fClockEnd) {
+        double dur = static_cast<double>(traceEvent->fClockEnd - traceEvent->fClockBegin) * 1E-3;
         writer->appendDouble("dur", dur);
     }
-    writer->appendS64("tid", traceEvent.fThreadID);
+    writer->appendS64("tid", 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) {
+    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)) {
+        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));
+            writer->appendString("base_type", *baseTypeResolver->find(traceEvent->fID));
             addedSnapshot = true;
         }
 
-        for (int i = 0; i < traceEvent.fNumArgs; ++i) {
+        for (int i = 0; i < traceEvent->fNumArgs; ++i) {
+            const TraceEventArg* arg = traceEvent->args() + i;
             // TODO: Skip '#'
-            writer->appendName(traceEvent.fArgNames[i]);
+            writer->appendName(arg->fArgName);
 
-            if (traceEvent.fArgNames[i] && '#' == traceEvent.fArgNames[i][0]) {
+            if (arg->fArgName && '#' == arg->fArgName[0]) {
                 writer->beginObject();
                 writer->appendName("id_ref");
-                trace_value_to_json(writer, traceEvent.fArgValues[i], traceEvent.fArgTypes[i]);
+                trace_value_to_json(writer, arg->fArgValue, arg->fArgType, stringTable);
                 writer->endObject();
             } else {
-                trace_value_to_json(writer, traceEvent.fArgValues[i], traceEvent.fArgTypes[i]);
+                trace_value_to_json(writer, arg->fArgValue, arg->fArgType, stringTable);
             }
         }
 
@@ -203,15 +276,19 @@ void SkChromeTracingTracer::flush() {
 
     BaseTypeResolver baseTypeResolver;
 
-    for (int i = 0; i < fBlocks.count(); ++i) {
-        for (int j = 0; j < kEventsPerBlock; ++j) {
-            this->traceEventToJson(&writer, fBlocks[i][j], &baseTypeResolver);
+    auto event_block_to_json = [](SkJSONWriter* writer, const TraceEventBlock& block,
+                                  BaseTypeResolver* baseTypeResolver) {
+        TraceEvent* traceEvent = reinterpret_cast<TraceEvent*>(block.fBlock.get());
+        for (int i = 0; i < block.fEventsInBlock; ++i) {
+            trace_event_to_json(writer, traceEvent, baseTypeResolver);
+            traceEvent = traceEvent->next();
         }
-    }
+    };
 
-    for (int i = 0; i < fEventsInCurBlock; ++i) {
-        this->traceEventToJson(&writer, fCurBlock[i], &baseTypeResolver);
+    for (int i = 0; i < fBlocks.count(); ++i) {
+        event_block_to_json(&writer, fBlocks[i], &baseTypeResolver);
     }
+    event_block_to_json(&writer, fCurBlock, &baseTypeResolver);
 
     writer.endArray();
     writer.flush();