Faster, thread-safe implementation

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

7 files changed, 142 insertions, 53 deletions

diff --git a/bench/nanobench.cpp b/bench/nanobench.cpp
index 05c475a391..95e12118f3 100644
--- a/bench/nanobench.cpp
+++ b/bench/nanobench.cpp
@@ -1106,7 +1106,7 @@ static void start_keepalive() {
 int main(int argc, char** argv) {
     SkCommandLineFlags::Parse(argc, argv);
 
-    initializeEventTracingForTools(&FLAGS_threads);
+    initializeEventTracingForTools();
 
 #if defined(SK_BUILD_FOR_IOS)
     cd_Documents();
diff --git a/dm/DM.cpp b/dm/DM.cpp
index 94ac7f41b7..e8898a4c95 100644
--- a/dm/DM.cpp
+++ b/dm/DM.cpp
@@ -1280,7 +1280,7 @@ extern sk_sp<SkTypeface> (*gCreateTypefaceDelegate)(const char [], SkFontStyle )
 int main(int argc, char** argv) {
     SkCommandLineFlags::Parse(argc, argv);
 
-    initializeEventTracingForTools(&FLAGS_threads);
+    initializeEventTracingForTools();
 
 #if defined(SK_BUILD_FOR_IOS)
     cd_Documents();
diff --git a/tools/trace/SkChromeTracingTracer.cpp b/tools/trace/SkChromeTracingTracer.cpp
index 0cfb1bf5f9..4f424f8801 100644
--- a/tools/trace/SkChromeTracingTracer.cpp
+++ b/tools/trace/SkChromeTracingTracer.cpp
@@ -14,6 +14,31 @@
 
 #include <chrono>
 
+SkChromeTracingTracer::SkChromeTracingTracer(const char* filename) : fFilename(filename) {
+    fCurBlock = this->createBlock();
+    fEventsInCurBlock = 0;
+}
+
+SkChromeTracingTracer::~SkChromeTracingTracer() {
+    this->flush();
+}
+
+SkChromeTracingTracer::BlockPtr SkChromeTracingTracer::createBlock() {
+    return BlockPtr(new TraceEvent[kEventsPerBlock]);
+}
+
+SkChromeTracingTracer::TraceEvent* SkChromeTracingTracer::appendEvent(
+        const TraceEvent& traceEvent) {
+    SkAutoMutexAcquire lock(fMutex);
+    if (fEventsInCurBlock >= kEventsPerBlock) {
+        fBlocks.push_back(std::move(fCurBlock));
+        fCurBlock = this->createBlock();
+        fEventsInCurBlock = 0;
+    }
+    fCurBlock[fEventsInCurBlock] = traceEvent;
+    return &fCurBlock[fEventsInCurBlock++];
+}
+
 SkEventTracer::Handle SkChromeTracingTracer::addTraceEvent(char phase,
                                                            const uint8_t* categoryEnabledFlag,
                                                            const char* name,
@@ -26,74 +51,111 @@ 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.
 
-    Json::Value traceEvent;
-    char phaseString[2] = { phase, 0 };
-    traceEvent["ph"] = phaseString;
-    traceEvent["name"] = name;
-    traceEvent["cat"] = this->getCategoryGroupName(categoryEnabledFlag);
-    auto now = std::chrono::high_resolution_clock::now();
-    std::chrono::duration<double, std::nano> ns = now.time_since_epoch();
-    traceEvent["ts"] = ns.count() * 1E-3;
-    traceEvent["tid"] = static_cast<Json::Int64>(SkGetThreadID());
+    TraceEvent traceEvent;
+    traceEvent.fPhase = phase;
+    traceEvent.fNumArgs = numArgs;
+    traceEvent.fName = name;
+    traceEvent.fCategory = fCategories.getCategoryGroupName(categoryEnabledFlag);
+    traceEvent.fClockBegin = std::chrono::high_resolution_clock::now().time_since_epoch().count();
+    traceEvent.fClockEnd = 0;
+    traceEvent.fThreadID = SkGetThreadID();
 
+    for (int i = 0; i < numArgs; ++i) {
+        traceEvent.fArgNames[i] = argNames[i];
+        traceEvent.fArgTypes[i] = argTypes[i];
+        if (TRACE_VALUE_TYPE_COPY_STRING == argTypes[i]) {
+            skia::tracing_internals::TraceValueUnion value;
+            value.as_uint = argValues[i];
+            value.as_string = SkStrDup(value.as_string);
+            traceEvent.fArgValues[i] = value.as_uint;
+        } else {
+            traceEvent.fArgValues[i] = argValues[i];
+        }
+    }
+
+    return reinterpret_cast<Handle>(this->appendEvent(traceEvent));
+}
+
+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::high_resolution_clock::now().time_since_epoch().count();
+}
+
+Json::Value SkChromeTracingTracer::traceEventToJson(const TraceEvent& traceEvent) {
+    Json::Value json;
+    char phaseString[2] = { traceEvent.fPhase, 0 };
+    json["ph"] = phaseString;
+    json["name"] = traceEvent.fName;
+    json["cat"] = traceEvent.fCategory;
+    json["ts"] = static_cast<double>(traceEvent.fClockBegin) * 1E-3;
+    if (0 != traceEvent.fClockEnd) {
+        json["dur"] = static_cast<double>(traceEvent.fClockEnd - traceEvent.fClockBegin) * 1E-3;
+    }
+    json["tid"] = static_cast<Json::Int64>(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).
-    traceEvent["pid"] = 0;
-
-    if (numArgs) {
+    json["pid"] = 0;
+    if (traceEvent.fNumArgs) {
         Json::Value args;
         skia::tracing_internals::TraceValueUnion value;
-        for (int i = 0; i < numArgs; ++i) {
-            value.as_uint = argValues[i];
-            switch (argTypes[i]) {
+        for (int i = 0; i < traceEvent.fNumArgs; ++i) {
+            value.as_uint = traceEvent.fArgValues[i];
+            switch (traceEvent.fArgTypes[i]) {
                 case TRACE_VALUE_TYPE_BOOL:
-                    args[argNames[i]] = value.as_bool;
+                    args[traceEvent.fArgNames[i]] = value.as_bool;
                     break;
                 case TRACE_VALUE_TYPE_UINT:
-                    args[argNames[i]] = static_cast<Json::UInt64>(argValues[i]);
+                    args[traceEvent.fArgNames[i]] = static_cast<Json::UInt64>(value.as_uint);
                     break;
                 case TRACE_VALUE_TYPE_INT:
-                    args[argNames[i]] = static_cast<Json::Int64>(argValues[i]);
+                    args[traceEvent.fArgNames[i]] = static_cast<Json::Int64>(value.as_uint);
                     break;
                 case TRACE_VALUE_TYPE_DOUBLE:
-                    args[argNames[i]] = value.as_double;
+                    args[traceEvent.fArgNames[i]] = value.as_double;
                     break;
                 case TRACE_VALUE_TYPE_POINTER:
-                    args[argNames[i]] = value.as_pointer;
+                    args[traceEvent.fArgNames[i]] = value.as_pointer;
                     break;
                 case TRACE_VALUE_TYPE_STRING:
                 case TRACE_VALUE_TYPE_COPY_STRING:
-                    args[argNames[i]] = value.as_string;
+                    args[traceEvent.fArgNames[i]] = value.as_string;
                     break;
                 default:
-                    args[argNames[i]] = "<unknown type>";
+                    args[traceEvent.fArgNames[i]] = "<unknown type>";
                     break;
             }
         }
-        traceEvent["args"] = args;
+        json["args"] = args;
     }
-    Json::Value& newValue(fRoot.append(traceEvent));
-    return reinterpret_cast<Handle>(&newValue);
-}
-
-void SkChromeTracingTracer::updateTraceEventDuration(const uint8_t* categoryEnabledFlag,
-                                                     const char* name,
-                                                     SkEventTracer::Handle handle) {
-    Json::Value* traceEvent = reinterpret_cast<Json::Value*>(handle);
-    auto now = std::chrono::high_resolution_clock::now();
-    std::chrono::duration<double, std::nano> ns = now.time_since_epoch();
-    auto us = ns.count() * 1E-3;
-    (*traceEvent)["dur"] = us - (*traceEvent)["ts"].asDouble();
+    return json;
 }
 
 void SkChromeTracingTracer::flush() {
+    SkAutoMutexAcquire lock(fMutex);
+
+    Json::Value root(Json::arrayValue);
+
+    for (int i = 0; i < fBlocks.count(); ++i) {
+        for (int j = 0; j < kEventsPerBlock; ++j) {
+            root.append(this->traceEventToJson(fBlocks[i][j]));
+        }
+    }
+
+    for (int i = 0; i < fEventsInCurBlock; ++i) {
+        root.append(this->traceEventToJson(fCurBlock[i]));
+    }
+
     SkString dirname = SkOSPath::Dirname(fFilename.c_str());
-    if (!sk_exists(dirname.c_str(), kWrite_SkFILE_Flag)) {
+    if (!dirname.isEmpty() && !sk_exists(dirname.c_str(), kWrite_SkFILE_Flag)) {
         if (!sk_mkdir(dirname.c_str())) {
             SkDebugf("Failed to create directory.");
         }
     }
     SkFILEWStream stream(fFilename.c_str());
-    stream.writeText(Json::StyledWriter().write(fRoot).c_str());
+    stream.writeText(Json::FastWriter().write(root).c_str());
     stream.flush();
 }
diff --git a/tools/trace/SkChromeTracingTracer.h b/tools/trace/SkChromeTracingTracer.h
index 152771bef0..4a749081b9 100644
--- a/tools/trace/SkChromeTracingTracer.h
+++ b/tools/trace/SkChromeTracingTracer.h
@@ -11,6 +11,7 @@
 #include "SkEventTracer.h"
 #include "SkEventTracingPriv.h"
 #include "SkJSONCPP.h"
+#include "SkSpinlock.h"
 #include "SkString.h"
 
 /**
@@ -18,8 +19,8 @@
  */
 class SkChromeTracingTracer : public SkEventTracer {
 public:
-    SkChromeTracingTracer(const char* filename) : fRoot(Json::arrayValue), fFilename(filename) {}
-    ~SkChromeTracingTracer() override { this->flush(); }
+    SkChromeTracingTracer(const char* filename);
+    ~SkChromeTracingTracer() override;
 
     SkEventTracer::Handle addTraceEvent(char phase,
                                         const uint8_t* categoryEnabledFlag,
@@ -46,9 +47,43 @@ public:
 private:
     void flush();
 
-    Json::Value fRoot;
+    enum {
+        // Events are currently 80 bytes, assuming 64-bit pointers and reasonable packing.
+        // This is a first guess at a number that balances memory usage vs. time overhead of
+        // allocating blocks.
+        kEventsPerBlock = 10000,
+
+        // Our current tracing macros only support up to 2 arguments
+        kMaxArgs = 2,
+    };
+
+    struct TraceEvent {
+        // Fields are ordered to minimize size due to alignment
+        char fPhase;
+        uint8_t fNumArgs;
+        uint8_t fArgTypes[kMaxArgs];
+
+        const char* fName;
+        const char* fCategory;
+        uint64_t fClockBegin;
+        uint64_t fClockEnd;
+        SkThreadID fThreadID;
+
+        const char* fArgNames[kMaxArgs];
+        uint64_t fArgValues[kMaxArgs];
+    };
+
+    typedef std::unique_ptr<TraceEvent[]> BlockPtr;
+    BlockPtr createBlock();
+    TraceEvent* appendEvent(const TraceEvent&);
+    Json::Value traceEventToJson(const TraceEvent&);
+
     SkString fFilename;
+    SkSpinlock fMutex;
     SkEventTracingCategories fCategories;
+    BlockPtr fCurBlock;
+    int fEventsInCurBlock;
+    SkTArray<BlockPtr> fBlocks;
 };
 
 #endif
diff --git a/tools/trace/SkEventTracingPriv.cpp b/tools/trace/SkEventTracingPriv.cpp
index c4c793b06e..783cfeaa32 100644
--- a/tools/trace/SkEventTracingPriv.cpp
+++ b/tools/trace/SkEventTracingPriv.cpp
@@ -22,7 +22,7 @@ DEFINE_string(trace, "",
               "               trace events to specified file as JSON, for viewing\n"
               "               with chrome://tracing");
 
-void initializeEventTracingForTools(int32_t* threadsFlag) {
+void initializeEventTracingForTools() {
     if (FLAGS_trace.isEmpty()) {
         return;
     }
@@ -34,10 +34,6 @@ void initializeEventTracingForTools(int32_t* threadsFlag) {
     } else if (0 == strcmp(traceFlag, "debugf")) {
         eventTracer = new SkDebugfTracer();
     } else {
-        if (threadsFlag && *threadsFlag != 0) {
-            SkDebugf("JSON tracing is not yet thread-safe, disabling threading.\n");
-            *threadsFlag = 0;
-        }
         eventTracer = new SkChromeTracingTracer(traceFlag);
     }
 
diff --git a/tools/trace/SkEventTracingPriv.h b/tools/trace/SkEventTracingPriv.h
index a4f04caefb..aa3ee6d4d9 100644
--- a/tools/trace/SkEventTracingPriv.h
+++ b/tools/trace/SkEventTracingPriv.h
@@ -12,12 +12,8 @@
 
 /**
  * Construct and install an SkEventTracer, based on the 'trace' command line argument.
- *
- * @param threadsFlag Pointer to the FLAGS_threads variable (or nullptr). This is used to disable
- *                    threading when tracing to JSON. (Remove this param when JSON tracer is thread
- *                    safe).
  */
-void initializeEventTracingForTools(int32_t* threadsFlag);
+void initializeEventTracingForTools();
 
 /**
  * Helper class used by internal implementations of SkEventTracer to manage categories.
diff --git a/tools/viewer/Viewer.cpp b/tools/viewer/Viewer.cpp
index 6e20cbb4f9..72c2f6cb40 100644
--- a/tools/viewer/Viewer.cpp
+++ b/tools/viewer/Viewer.cpp
@@ -284,7 +284,7 @@ Viewer::Viewer(int argc, char** argv, void* platformData)
     SetResourcePath("/data/local/tmp/resources");
 #endif
 
-    initializeEventTracingForTools(&FLAGS_threads);
+    initializeEventTracingForTools();
     static SkTaskGroup::Enabler kTaskGroupEnabler(FLAGS_threads);
 
     fBackendType = get_backend_type(FLAGS_backend[0]);