Use native llvm JSON library for time profiler output

[anton-afanasyev]

Summary

Replace plain json text output with llvm JSON library wrapper using.

[anton-afanasyev]

Updated

[takuto.ikuta]

Thank you for follow up.

llvm/lib/Support/TimeProfiler.cpp

146

nit: I prefer to drop this new line.

[anton-afanasyev]

Deleted tailing '\n'

[anton-afanasyev]

In D60609#1465222, @takuto.ikuta wrote:

Thank you for follow up.

Thanks! I'm to push it after fixing one thing in JSON.h library which instantiates template function with warning.

llvm/lib/Support/TimeProfiler.cpp

146

Ok, done

[lebedev.ri]

I know this will sound redundant, but have you done performance measurements on this?
I recently had to revert a similar cleanup in D58584.

[anton-afanasyev]

In D60609#1465292, @lebedev.ri wrote:

I know this will sound redundant, but have you done performance measurements on this?
I recently had to revert a similar cleanup in D58584.

Wow, thanks to pointing this out! Using json library is obviously heavier than just streaming plain text, but I didn't suppose such perf regressions. I'm to measure it.

[takuto.ikuta]

I think it is true that json library is slower than just naive json output.
But this code run one time in a compile and should have relatively few json objects.
So visible performance effect will be low. Taking stats sounds good and I'm surprised if this patch change clang performance match.

[lebedev.ri]

In D60609#1465327, @takuto.ikuta wrote:

I think it is true that json library is slower than just naive json output.
But this code run one time in a compile and should have relatively few json objects.
So visible performance effect will be low. Taking stats sounds good and I'm surprised if this patch change clang performance match.

Yes, that is my hope too, but given history i'd like to be confident :)
This will really depend on the number of the entries in the output.
I'd like to see perf measurements on some large compiler invocation, with *many* of these entries in output json report.

[anton-afanasyev]

In D60609#1465351, @lebedev.ri wrote:

In D60609#1465327, @takuto.ikuta wrote:

I think it is true that json library is slower than just naive json output.
But this code run one time in a compile and should have relatively few json objects.
So visible performance effect will be low. Taking stats sounds good and I'm surprised if this patch change clang performance match.

Yes, that is my hope too, but given history i'd like to be confident :)
This will really depend on the number of the entries in the output.
I'd like to see perf measurements on some large compiler invocation, with *many* of these entries in output json report.

I've measured time performance for the large source file test-suite/SingleSource/Benchmarks/Misc-C++-EH/spirit.cpp.

Five tests: without time tracing, with time tracing for old/new json output, with small granularity for old/new json output. Small time granularity leads to many entries in json output (~32K vs ~2K for default granularity).
As one can see, json library is actually slower but it has no notable effect by default and I believe it's eligible price even for large number of entries.

perf stat -r 5 ./build_rel_base/bin/clang++ -w -S spirit.cpp
...
3362.032795      task-clock (msec)

perf stat -r 5 ./build_rel_base/bin/clang++ -w -S -ftime-trace spirit.cpp
...
3577.592945      task-clock (msec)

perf stat -r 5 ./build_rel_exp/bin/clang++ -w -S -ftime-trace spirit.cpp
...
3582.747398      task-clock (msec)

perf stat -r 5 ./build_rel_base/bin/clang++ -w -S -ftime-trace -mllvm -time-trace-granularity=0 spirit.cpp
...
3634.623793      task-clock (msec)

perf stat -r 5 ./build_rel_exp/bin/clang++ -w -S -ftime-trace -mllvm -time-trace-granularity=0 spirit.cpp
...
3995.315749      task-clock (msec)

[lebedev.ri]

In D60609#1466384, @anton-afanasyev wrote:

In D60609#1465351, @lebedev.ri wrote:

In D60609#1465327, @takuto.ikuta wrote:

I think it is true that json library is slower than just naive json output.
But this code run one time in a compile and should have relatively few json objects.
So visible performance effect will be low. Taking stats sounds good and I'm surprised if this patch change clang performance match.

Yes, that is my hope too, but given history i'd like to be confident :)
This will really depend on the number of the entries in the output.
I'd like to see perf measurements on some large compiler invocation, with *many* of these entries in output json report.

I've measured time performance for the large source file test-suite/SingleSource/Benchmarks/Misc-C++-EH/spirit.cpp.

Thank you for doing the measurements.

Five tests: without time tracing, with time tracing for old/new json output, with small granularity for old/new json output.

Small time granularity leads to many entries in json output (~32K vs ~2K for default granularity).

It would be interested to see memory consumption changes (heaptrack),
but with this small maximal number of entries, pretty much anything should not be too noticeable.

As one can see, json library is actually slower but it has no notable effect by default and I believe it's eligible price even for large number of entries.

perf stat -r 5 ./build_rel_base/bin/clang++ -w -S spirit.cpp
...
3362.032795      task-clock (msec)

perf stat -r 5 ./build_rel_base/bin/clang++ -w -S -ftime-trace spirit.cpp
...
3577.592945      task-clock (msec)

+215 ms or +~6% (as compared to without -ftime-trace)

perf stat -r 5 ./build_rel_exp/bin/clang++ -w -S -ftime-trace spirit.cpp
...
3582.747398      task-clock (msec)

+220 ms or +~7% (as compared to without -ftime-trace, or +5ms/0.1% as compared to without this patch)

perf stat -r 5 ./build_rel_base/bin/clang++ -w -S -ftime-trace -mllvm -time-trace-granularity=0 spirit.cpp
...
3634.623793      task-clock (msec)

+273 ms or +~8% (as compared to without -ftime-trace)

perf stat -r 5 ./build_rel_exp/bin/clang++ -w -S -ftime-trace -mllvm -time-trace-granularity=0 spirit.cpp
...
3995.315749      task-clock (msec)

+733 ms or +19% (as compared to without -ftime-trace, or +360ms/+10% as compared to without this patch)

Okay, so the price increase in default config is reasonably small.
It is noticeably larger with bigger number of events though.
I don't like how non-thin of a wrapper "llvm/Support/JSON.h" is. :/

TLDR: Not horrible, but above what i would consider a reasonable price for abstraction.

llvm/lib/Support/TimeProfiler.cpp

84–87

There is no reserve() function in json::Array, thus you end up doing the memory dance *every* entry. :/
(alloc larger, move, delete previous)
I suspect this accounts for majority of the extra cost, although not all of it.

91

emplace_back() doesn't work?

[anton-afanasyev]

llvm/lib/Support/TimeProfiler.cpp

84–87

Good point to change in json lib.

91

It works (for explicitly given cons), I've changed it in a separate review: https://reviews.llvm.org/D60663

[anton-afanasyev]

llvm/lib/Support/TimeProfiler.cpp

91

Oops, that's another push_back(), I'm wrong.

[anton-afanasyev]

Updated

[anton-afanasyev]

Updated

[lebedev.ri]

llvm/lib/Support/TimeProfiler.cpp

84–87

If you don't intend to look into that (should be rather trivial),
can you please at least raise a bug about this, with those perf numbers?

[anton-afanasyev]

llvm/lib/Support/TimeProfiler.cpp

84–87

I've measured the perf effect of adding Array.reserve(33000) (changed JSON.h a bit), it gives 3845 msec (vs 3995 msec) for -time-trace-granularity=0. Effect is noticeable, but actual implementation need a smart heuristics to determine the entries number to reserve. For the default option (time-trace-granularity = 500 msec) this doesn't matter.

84–87

What do you mean by bug? Do you mean I should add Array.reserve(N) with N taken heuristically from different runs for different time-trace-granularity? Or would just Array.reserve(4000) be enough for default granularity?

[anton-afanasyev]

llvm/lib/Support/TimeProfiler.cpp

84–87

Also this result means that time taken by json output could be decreased by 40% (1 - (3845-3634)/(3995-3634)), but this is actual and significant only for time-trace-granularity=0. The effect of array reservation for the default option value is insignificant.

[lebedev.ri]

llvm/lib/Support/TimeProfiler.cpp

84–87

What do you mean by bug?

The lack of json::array::reserve()

Do you mean I should add Array.reserve(N) with N taken heuristically from different runs for different time-trace-granularity? Or would just Array.reserve(4000) be enough for default granularity?

Hm?
You know how many Events in json::Array you will end up with - Entries.size() + CountAndTotalPerName.size() + 1.
You can even assert that in the end.

[anton-afanasyev]

llvm/lib/Support/TimeProfiler.cpp

84–87

Ooops, you're right! Here is fix for json Array: https://reviews.llvm.org/D60788

[lebedev.ri]

llvm/lib/Support/TimeProfiler.cpp

84–87

Not 40% though.
It's calculated as abs(old-new)/old = 5.49%

[anton-afanasyev]

llvm/lib/Support/TimeProfiler.cpp

84–87

These are different metrics. I'm talking about time portion taken by Array of whole time taken by json lib using.

[lebedev.ri]

llvm/lib/Support/TimeProfiler.cpp

84–87

Ah, right, sorry.

[anton-afanasyev]

llvm/lib/Support/TimeProfiler.cpp

84–87

My metrics results relates to your words that majority or all extra cost is taken by "dancing" with Array. Actually not the majority but ~40% -- still significant number.

[lebedev.ri]

llvm/lib/Support/TimeProfiler.cpp

84–87

The problem is that every entry in std::vector inside of json::array is json::Value,
and json::Value internally is likely a json::object,
and json::object is internally a llvm::densemap

So you have an array of densemaps... Naturally, there is quite a bit of overhead.
Not all of it comes from dancing around due to the lack of reserve() of json::array.

[sammccall]

Just wanted to note I'm going to look at drafting a lower-level streaming output API so cases like this can avoid materializing all those expensive objects.

That said I don't claim any special expertise in this area, if someone else wants to jump on it, go ahead.

llvm/lib/Support/TimeProfiler.cpp

84

Sorry, I was vaguely aware of this patch but hadn't looked at the detail.
As there's likely to be lots of events, I'd suggest still writing the {"traceEvents":[ / ]} container by hand and the "," separator between events if you care about performance.
You can still use the JSON lib for composing and serializing each individual event.
This is what we do in clangd.

This will reduce peak mem usage, but also the repeated allocation/deallocation of similar structures may make allocation cheaper (I know it does a lot with tcmalloc).

Not sure how much this will help, as always with performance, measuring is a good idea.

[anton-afanasyev]

llvm/lib/Support/TimeProfiler.cpp

84

Hmm, good point, thanks. I'm to try and measure it. My preliminary thought is that json::Array reserving has already got rid of this time extra cost (not memory peak usage though).

llvm/lib/Support/TimeProfiler.cpp

 /// \file Hierarchical time profiler implementation.
 //
 //===----------------------------------------------------------------------===//
 
 #include "llvm/Support/TimeProfiler.h"
 #include "llvm/ADT/StringExtras.h"
 #include "llvm/ADT/StringMap.h"
 #include "llvm/Support/FileSystem.h"
+#include "llvm/Support/JSON.h"
 #include <cassert>
 #include <chrono>
 #include <string>
 #include <unordered_map>
 #include <vector>
 
 using namespace std::chrono;
 
 namespace llvm {
 
 TimeTraceProfiler *TimeTraceProfilerInstance = nullptr;
 
-static std::string escapeString(StringRef Src) {
-  std::string OS;
-  for (const unsigned char &C : Src) {
-    switch (C) {
-    case '"':
-    case '/':
-    case '\\':
-    case '\b':
-    case '\f':
-    case '\n':
-    case '\r':
-    case '\t':
-      OS += '\\';
-      OS += C;
-      break;
-    default:
-      if (isPrint(C)) {
-        OS += C;
-      }
-    }
-  }
-  return OS;
-}
-
 typedef duration<steady_clock::rep, steady_clock::period> DurationType;
 typedef std::pair<size_t, DurationType> CountAndDurationType;
 typedef std::pair<std::string, CountAndDurationType>
     NameAndCountAndDurationType;
 
 struct Entry {
   time_point<steady_clock> Start;
   DurationType Duration;
void end() {
 
     Stack.pop_back();
   }
 
   void Write(std::unique_ptr<raw_pwrite_stream> &OS) {
     assert(Stack.empty() &&
            "All profiler sections should be ended when calling Write");
 
-    *OS << "{ \"traceEvents\": [\n";
+    json::Array Events;
 
     // Emit all events for the main flame graph.
     for (const auto &E : Entries) {
       auto StartUs = duration_cast<microseconds>(E.Start - StartTime).count();
       auto DurUs = duration_cast<microseconds>(E.Duration).count();
-      *OS << "{ \"pid\":1, \"tid\":0, \"ph\":\"X\", \"ts\":" << StartUs
-          << ", \"dur\":" << DurUs << ", \"name\":\"" << escapeString(E.Name)
-          << "\", \"args\":{ \"detail\":\"" << escapeString(E.Detail)
-          << "\"} },\n";
+
+      Events.push_back(json::Object{
+          {"pid", 1},
+          {"tid", 0},
+          {"ph", "X"},
+          {"ts", StartUs},
+          {"dur", DurUs},
+          {"name", E.Name},
+          {"args", json::Object{{"detail", E.Detail}}},
+      });
     }
 
     // Emit totals by section name as additional "thread" events, sorted from
     // longest one.
     int Tid = 1;
     std::vector<NameAndCountAndDurationType> SortedTotals;
     SortedTotals.reserve(CountAndTotalPerName.size());
     for (const auto &E : CountAndTotalPerName) {
       SortedTotals.emplace_back(E.getKey(), E.getValue());
     }
     std::sort(SortedTotals.begin(), SortedTotals.end(),
               [](const NameAndCountAndDurationType &A,
                  const NameAndCountAndDurationType &B) {
                 return A.second.second > B.second.second;
               });
     for (const auto &E : SortedTotals) {
       auto DurUs = duration_cast<microseconds>(E.second.second).count();
       auto Count = CountAndTotalPerName[E.first].first;
-      *OS << "{ \"pid\":1, \"tid\":" << Tid << ", \"ph\":\"X\", \"ts\":" << 0
-          << ", \"dur\":" << DurUs << ", \"name\":\"Total "
-          << escapeString(E.first) << "\", \"args\":{ \"count\":" << Count
-          << ", \"avg ms\":" << (DurUs / Count / 1000) << "} },\n";
+
+      Events.push_back(json::Object{
+          {"pid", 1},
+          {"tid", Tid},
+          {"ph", "X"},
+          {"ts", 0},
+          {"dur", DurUs},
+          {"name", "Total " + E.first},
+          {"args",
+           json::Object{{"count", Count}, {"avg ms", DurUs / Count / 1000}}},
+      });
+
       ++Tid;
     }
 
     // Emit metadata event with process name.
-    *OS << "{ \"cat\":\"\", \"pid\":1, \"tid\":0, \"ts\":0, \"ph\":\"M\", "
-           "\"name\":\"process_name\", \"args\":{ \"name\":\"clang\" } }\n";
-    *OS << "] }\n";
+    Events.push_back(json::Object{
+        {"cat", ""},
+        {"pid", 1},
+        {"tid", 0},
+        {"ts", 0},
+        {"ph", "M"},
+        {"name", "process_name"},
+        {"args", json::Object{{"name", "clang"}}},
+    });
+
+    *OS << formatv("{0:2}", json::Value(json::Object(
+                                {{"traceEvents", std::move(Events)}})))
+        << "\n";
   }
 
   std::vector<Entry> Stack;
   std::vector<Entry> Entries;
   StringMap<CountAndDurationType> CountAndTotalPerName;
   time_point<steady_clock> StartTime;
 };