Time profiler: small fixes and optimizations

[anton-afanasyev]

Summary

Fixes from Roman's review here: https://reviews.llvm.org/D58675#1465336

[lebedev.ri]

Looks good ignoring the json bits.

Re license:

https://reviews.llvm.org/D58675
This is the first part of time tracing system, I have splitted them cause this part is mostly written by Aras Pranckevicius except of several minor fixes concerning formatting.

So i can't and won't claim any legal knowledge, but it maybe would be good for him to at least comment here, that he is ok with this?

llvm/lib/Support/TimeProfiler.cpp

20 ↗

(On Diff #195054)

Unused header?

37–38 ↗

(On Diff #195054)

Ah yes, they are allocated when created. Hmm.

47–48 ↗

(On Diff #195054)

Does

Stack.emplace_back(steady_clock::now(), {}, std::move(Name), Detail());

not work?
(also, the std::string returned from Detail function invocation is moved?)

57 ↗

(On Diff #195054)

I feel like this should be

static cl::opt<unsigned> TimeProfileGranularity(
    "time-profile-granularity",
    cl::desc("<fixme>"),
    cl::init(500));

?

65 ↗

(On Diff #195054)

Yes, good point.

[anton-afanasyev]

In D60663#1465721, @lebedev.ri wrote:

Looks good ignoring the json bits.

Re license:

https://reviews.llvm.org/D58675
This is the first part of time tracing system, I have splitted them cause this part is mostly written by Aras Pranckevicius except of several minor fixes concerning formatting.

So i can't and won't claim any legal knowledge, but it maybe would be good for him to at least comment here, that he is ok with this?

Oh, sure! @aras-p -- I have changed license header to fit it with current LLVM Relicensing state. Are you ok with this? (see https://reviews.llvm.org/D60663#change-jr7Lagn5WNFy)

llvm/lib/Support/TimeProfiler.cpp

20 ↗

(On Diff #195054)

Yes, thanks.

47–48 ↗

(On Diff #195054)

Ok, changed.

57 ↗

(On Diff #195054)

I planned to change this later together with unit tests (cause they need small time granularity), but can fix it now. Changed, thanks!

[anton-afanasyev]

Updated

[anton-afanasyev]

Updated

[anton-afanasyev]

In D60663#1465721, @lebedev.ri wrote:

Looks good ignoring the json bits.

Re license:

https://reviews.llvm.org/D58675
This is the first part of time tracing system, I have splitted them cause this part is mostly written by Aras Pranckevicius except of several minor fixes concerning formatting.

So i can't and won't claim any legal knowledge, but it maybe would be good for him to at least comment here, that he is ok with this?

I've communicated to Aras by mail, he is ok with new license header:

"Sure! I started my branch before the LLVM license change. The new one is fine."

[lebedev.ri]

Ok, LG, thank you!

llvm/lib/Support/TimeProfiler.cpp

30 ↗

(On Diff #195069)

microsecon*d*s

70–71 ↗

(On Diff #195069)

I *think* && are not needed.

92 ↗

(On Diff #195069)

This will only track events that are longer than TimeTraceGranularity, which i think conflicts
with the "Minimum time granularity (in microseconds) traced by time profiler"
So either >= or reword the description a bit?

156–157 ↗

(On Diff #195069)

Since TimeTraceProfiler will be always heap-allocated (so stack usage is not a concern)
i think this is safe, and maybe even bump it a bit, depending on the values you see in average profiles?

[aras-p]

So i can't and won't claim any legal knowledge, but it maybe would be good for him to at least comment here, that he is ok with this?

Yes, absolutely fine. The only reason why some files started with the old license blurb is because I started the branch before licensing switch kicked in.

[sammccall]

llvm/trunk/lib/Support/TimeProfiler.cpp

27

I know this is late, but... this shows up in the help for any tool that links in libSupport, many of which don't support the time profiler. Can you mark this as hidden or (preferably) move this to cc1_main?

[anton-afanasyev]

llvm/trunk/lib/Support/TimeProfiler.cpp

27

@sammccall Yes, thanks! Here is the fix https://reviews.llvm.org/D65202 , please, review it.

[sammccall]

llvm/trunk/lib/Support/TimeProfiler.cpp

27

Thanks! A few nits but that's a big improvement I think.

cfe/trunk/tools/driver/cc1_main.cpp

if (llvm::timeTraceProfilerEnabled()) {
     llvm::sys::path::replace_extension(Path, "json");
     auto profilerOutput =
         Clang->createOutputFile(Path.str(),
                                 /*Binary=*/false,
                                 /*RemoveFileOnSignal=*/false, "",
                                 /*Extension=*/"json",
                                 /*useTemporary=*/false);
 
-    llvm::timeTraceProfilerWrite(profilerOutput);
+    llvm::timeTraceProfilerWrite(*profilerOutput);
     llvm::timeTraceProfilerCleanup();
   }
 
   // Our error handler depends on the Diagnostics object, which we're
   // potentially about to delete. Uninstall the handler now so that any
   // later errors use the default handling behavior instead.
   llvm::remove_fatal_error_handler();
 
   // When running with -disable-free, don't do any destruction or shutdown.
   if (Clang->getFrontendOpts().DisableFree) {
     llvm::BuryPointer(std::move(Clang));
     return !Success;
   }
 
   return !Success;
 }

llvm/trunk/include/llvm/Support/TimeProfiler.h

 //===- llvm/Support/TimeProfiler.h - Hierarchical Time Profiler -*- C++ -*-===//
 //
-//                     The LLVM Compiler Infrastructure
-//
-// This file is distributed under the University of Illinois Open Source
-// License. See LICENSE.TXT for details.
+// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
+// See https://llvm.org/LICENSE.txt for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
 //
 //===----------------------------------------------------------------------===//
 
 #ifndef LLVM_SUPPORT_TIME_PROFILER_H
 #define LLVM_SUPPORT_TIME_PROFILER_H
 
 #include "llvm/Support/raw_ostream.h"
 

 /// Is the time trace profiler enabled, i.e. initialized?
 inline bool timeTraceProfilerEnabled() {
   return TimeTraceProfilerInstance != nullptr;
 }
 
 /// Write profiling data to output file.
 /// Data produced is JSON, in Chrome "Trace Event" format, see
 /// https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview
-void timeTraceProfilerWrite(std::unique_ptr<raw_pwrite_stream> &OS);
+void timeTraceProfilerWrite(raw_pwrite_stream &OS);
 
 /// Manually begin a time section, with the given \p Name and \p Detail.
 /// Profiler copies the string data, so the pointers can be given into
 /// temporaries. Time sections can be hierarchical; every Begin must have a
 /// matching End pair but they can nest.
 void timeTraceProfilerBegin(StringRef Name, StringRef Detail);
 void timeTraceProfilerBegin(StringRef Name,
                             llvm::function_ref<std::string()> Detail);
 
 /// Manually end the last time section.
 void timeTraceProfilerEnd();
 
 /// The TimeTraceScope is a helper class to call the begin and end functions
 /// of the time trace profiler.  When the object is constructed, it begins
 /// the section; and when it is destroyed, it stops it. If the time profiler
 /// is not initialized, the overhead is a single branch.
 struct TimeTraceScope {
+
+  TimeTraceScope() = delete;
+  TimeTraceScope(const TimeTraceScope &) = delete;
+  TimeTraceScope &operator=(const TimeTraceScope &) = delete;
+  TimeTraceScope(TimeTraceScope &&) = delete;
+  TimeTraceScope &operator=(TimeTraceScope &&) = delete;
+
   TimeTraceScope(StringRef Name, StringRef Detail) {
     if (TimeTraceProfilerInstance != nullptr)
       timeTraceProfilerBegin(Name, Detail);
   }
   TimeTraceScope(StringRef Name, llvm::function_ref<std::string()> Detail) {
     if (TimeTraceProfilerInstance != nullptr)
       timeTraceProfilerBegin(Name, Detail);
   }

llvm/trunk/lib/Support/TimeProfiler.cpp

 //===-- TimeProfiler.cpp - Hierarchical Time Profiler ---------------------===//
 //
-//                     The LLVM Compiler Infrastructure
-//
-// This file is distributed under the University of Illinois Open Source
-// License. See LICENSE.TXT for details.
+// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
+// See https://llvm.org/LICENSE.txt for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
 //
 //===----------------------------------------------------------------------===//
 //
-/// \file Hierarchical time profiler implementation.
+// This file implements hierarchical time profiler.
 //
 //===----------------------------------------------------------------------===//
 
 #include "llvm/Support/TimeProfiler.h"
 #include "llvm/ADT/StringExtras.h"
 #include "llvm/ADT/StringMap.h"
+#include "llvm/Support/CommandLine.h"
 #include "llvm/Support/FileSystem.h"
 #include <cassert>
 #include <chrono>
 #include <string>
-#include <unordered_map>
 #include <vector>
 
 using namespace std::chrono;
 
 namespace llvm {
 
+static cl::opt<unsigned> TimeTraceGranularity(
+    "time-trace-granularity",
+    cl::desc(
+        "Minimum time granularity (in microseconds) traced by time profiler"),
+    cl::init(500));
+
 TimeTraceProfiler *TimeTraceProfilerInstance = nullptr;
 
 static std::string escapeString(StringRef Src) {
   std::string OS;
   for (const unsigned char &C : Src) {
     switch (C) {
     case '"':
     case '/':

 typedef std::pair<std::string, CountAndDurationType>
     NameAndCountAndDurationType;
 
 struct Entry {
   time_point<steady_clock> Start;
   DurationType Duration;
   std::string Name;
   std::string Detail;
+
+  Entry(time_point<steady_clock> &&S, DurationType &&D, std::string &&N,
+        std::string &&Dt)
+      : Start(std::move(S)), Duration(std::move(D)), Name(std::move(N)),
+        Detail(std::move(Dt)){};
 };
 
 struct TimeTraceProfiler {
   TimeTraceProfiler() {
-    Stack.reserve(8);
-    Entries.reserve(128);
     StartTime = steady_clock::now();
   }
 
   void begin(std::string Name, llvm::function_ref<std::string()> Detail) {
-    Entry E = {steady_clock::now(), {}, Name, Detail()};
-    Stack.push_back(std::move(E));
+    Stack.emplace_back(steady_clock::now(), DurationType{}, std::move(Name),
+                       Detail());
   }
 
   void end() {
     assert(!Stack.empty() && "Must call begin() first");
     auto &E = Stack.back();
     E.Duration = steady_clock::now() - E.Start;
 
-    // Only include sections longer than 500us.
-    if (duration_cast<microseconds>(E.Duration).count() > 500)
+    // Only include sections longer than TimeTraceGranularity msec.
+    if (duration_cast<microseconds>(E.Duration).count() > TimeTraceGranularity)
       Entries.emplace_back(E);
 
     // Track total time taken by each "name", but only the topmost levels of
     // them; e.g. if there's a template instantiation that instantiates other
     // templates from within, we only want to add the topmost one. "topmost"
     // happens to be the ones that don't have any currently open entries above
     // itself.
     if (std::find_if(++Stack.rbegin(), Stack.rend(), [&](const Entry &Val) {
           return Val.Name == E.Name;
         }) == Stack.rend()) {
       auto &CountAndTotal = CountAndTotalPerName[E.Name];
       CountAndTotal.first++;
       CountAndTotal.second += E.Duration;
     }
 
     Stack.pop_back();
   }
 
-  void Write(std::unique_ptr<raw_pwrite_stream> &OS) {
+  void Write(raw_pwrite_stream &OS) {
     assert(Stack.empty() &&
            "All profiler sections should be ended when calling Write");
 
-    *OS << "{ \"traceEvents\": [\n";
+    OS << "{ \"traceEvents\": [\n";
 
     // 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";
+      OS << "{ \"pid\":1, \"tid\":0, \"ph\":\"X\", \"ts\":" << StartUs
     }
 
     // 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) {
+    for (const auto &E : CountAndTotalPerName)
       SortedTotals.emplace_back(E.getKey(), E.getValue());
-    }
-    std::sort(SortedTotals.begin(), SortedTotals.end(),
+
+    llvm::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";
+      OS << "{ \"pid\":1, \"tid\":" << Tid << ", \"ph\":\"X\", \"ts\":" << 0
       ++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";
+    OS << "{ \"cat\":\"\", \"pid\":1, \"tid\":0, \"ts\":0, \"ph\":\"M\", "
+    OS << "] }\n";
   }
 
-  std::vector<Entry> Stack;
-  std::vector<Entry> Entries;
+  SmallVector<Entry, 16> Stack;
+  SmallVector<Entry, 128> Entries;
   StringMap<CountAndDurationType> CountAndTotalPerName;
   time_point<steady_clock> StartTime;
 };
 
 void timeTraceProfilerInitialize() {
   assert(TimeTraceProfilerInstance == nullptr &&
          "Profiler should not be initialized");
   TimeTraceProfilerInstance = new TimeTraceProfiler();
 }
 
 void timeTraceProfilerCleanup() {
   delete TimeTraceProfilerInstance;
   TimeTraceProfilerInstance = nullptr;
 }
 
-void timeTraceProfilerWrite(std::unique_ptr<raw_pwrite_stream> &OS) {
+void timeTraceProfilerWrite(raw_pwrite_stream &OS) {
   assert(TimeTraceProfilerInstance != nullptr &&
          "Profiler object can't be null");
   TimeTraceProfilerInstance->Write(OS);
 }
 
 void timeTraceProfilerBegin(StringRef Name, StringRef Detail) {
   if (TimeTraceProfilerInstance != nullptr)
     TimeTraceProfilerInstance->begin(Name, [&]() { return Detail; });