[LLD][ELF] Add time-trace to ELF LLD (1/2)

[russell.gallop]

Summary

Following on from RFC here: https://reviews.llvm.org/D69043

This patch extends the TimeProfiler to support multiple threads (for ThinLTO) by making TimeTraceProfilerInstance thread local. timeTraceProfilerFinishThread() moves the thread local instance to a global vector of instances and timeTraceProfilerWrite() writes recorded trace data from all instances. This reduces locking over the initial implementation presented in the RFC and is much quicker even on relatively modest 6 core machine.

In the generated trace, threads are identified based on their thread ids. Totals are reported with artificial thread ids higher than the real ones.

[anton-afanasyev]

LGTM, thanks!

[anton-afanasyev]

Btw, is it planned to add test for multithreading?

[russell.gallop]

In D71059#1776620, @anton-afanasyev wrote:

Btw, is it planned to add test for multithreading?

Thanks for the review.

There are tests for multi-threaded ThinLto using this within LLD in the next review (https://reviews.llvm.org/D71060).

Were you thinking of this, or of unit tests?

[anton-afanasyev]

In D71059#1776893, @russell.gallop wrote:

In D71059#1776620, @anton-afanasyev wrote:

Btw, is it planned to add test for multithreading?

Thanks for the review.

There are tests for multi-threaded ThinLto using this within LLD in the next review (https://reviews.llvm.org/D71060).

Were you thinking of this, or of unit tests?

I mean the test like clang/test/Driver/check-time-trace.cpp, but for the multithreaded invocation. Yes, for instance, for ThinLTO (but I see no tests in the D71060).

[russell.gallop]

In D71059#1776973, @anton-afanasyev wrote:

I mean the test like clang/test/Driver/check-time-trace.cpp, but for the multithreaded invocation. Yes, for instance, for ThinLTO (but I see no tests in the D71060).

Ah, my mistake. They should be on D71060 but it looks like they got lost somewhere along the way! I'll add them.

[ruiu]

Can you share an example output of lld with this patch?

[russell.gallop]

In D71059#1778898, @ruiu wrote:

Can you share an example output of lld with this patch?

This patch doesn't change lld, just provides support to D71060. I'll add an example to that review.

[ruiu]

LGTM

[Kai]

This PR requires TLS support even if LLVM_ENABLE_THREADS is set to OFF. Is this intended?

[russell.gallop]

In D71059#1785471, @Kai wrote:

This PR requires TLS support even if LLVM_ENABLE_THREADS is set to OFF. Is this intended?

I hadn't considered that, thanks. I'll fix this to work with LLVM_ENABLE_THREADS=OFF.

[• Quuxplusone]

This patch breaks the build on Apple Clang (Mac OSX 10.13.6).

$ ninja clang
[27/2870] Building CXX object lib/Support/CMakeFiles/LLVMSupport.dir/TimeProfiler.cpp.o
FAILED: lib/Support/CMakeFiles/LLVMSupport.dir/TimeProfiler.cpp.o 
/Applications/Xcode.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin/c++  -DGTEST_HAS_RTTI=0 -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Ilib/Support -I/llvm-project/llvm/lib/Support -I/usr/include/libxml2 -Iinclude -I/llvm-project/llvm/include -fPIC -fvisibility-inlines-hidden -Werror=date-time -Wall -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -pedantic -Wno-long-long -Wimplicit-fallthrough -Wcovered-switch-default -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wstring-conversion -fdiagnostics-color -O2 -g -DNDEBUG   -std=c++14  -fno-exceptions -fno-rtti -MD -MT lib/Support/CMakeFiles/LLVMSupport.dir/TimeProfiler.cpp.o -MF lib/Support/CMakeFiles/LLVMSupport.dir/TimeProfiler.cpp.o.d -o lib/Support/CMakeFiles/LLVMSupport.dir/TimeProfiler.cpp.o -c /llvm-project/llvm/lib/Support/TimeProfiler.cpp
In file included from /llvm-project/llvm/lib/Support/TimeProfiler.cpp:13:
/llvm-project/llvm/include/llvm/Support/TimeProfiler.h:17:8: error: thread-local storage is not supported for the current target
extern thread_local std::unique_ptr<TimeTraceProfiler>
       ^
/llvm-project/llvm/lib/Support/TimeProfiler.cpp:36:1: error: thread-local storage is not supported for the current target
thread_local std::unique_ptr<TimeTraceProfiler> TimeTraceProfilerInstance =
^
2 errors generated.

I guess this is related to the LLVM_ENABLE_THREADS issue mentioned above.

[russell.gallop]

In D71059#1785750, @Quuxplusone wrote:

This patch breaks the build on Apple Clang (Mac OSX 10.13.6).

$ ninja clang
[27/2870] Building CXX object lib/Support/CMakeFiles/LLVMSupport.dir/TimeProfiler.cpp.o
FAILED: lib/Support/CMakeFiles/LLVMSupport.dir/TimeProfiler.cpp.o 
/Applications/Xcode.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin/c++  -DGTEST_HAS_RTTI=0 -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Ilib/Support -I/llvm-project/llvm/lib/Support -I/usr/include/libxml2 -Iinclude -I/llvm-project/llvm/include -fPIC -fvisibility-inlines-hidden -Werror=date-time -Wall -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -pedantic -Wno-long-long -Wimplicit-fallthrough -Wcovered-switch-default -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wstring-conversion -fdiagnostics-color -O2 -g -DNDEBUG   -std=c++14  -fno-exceptions -fno-rtti -MD -MT lib/Support/CMakeFiles/LLVMSupport.dir/TimeProfiler.cpp.o -MF lib/Support/CMakeFiles/LLVMSupport.dir/TimeProfiler.cpp.o.d -o lib/Support/CMakeFiles/LLVMSupport.dir/TimeProfiler.cpp.o -c /llvm-project/llvm/lib/Support/TimeProfiler.cpp
In file included from /llvm-project/llvm/lib/Support/TimeProfiler.cpp:13:
/llvm-project/llvm/include/llvm/Support/TimeProfiler.h:17:8: error: thread-local storage is not supported for the current target
extern thread_local std::unique_ptr<TimeTraceProfiler>
       ^
/llvm-project/llvm/lib/Support/TimeProfiler.cpp:36:1: error: thread-local storage is not supported for the current target
thread_local std::unique_ptr<TimeTraceProfiler> TimeTraceProfilerInstance =
^
2 errors generated.

I guess this is related to the LLVM_ENABLE_THREADS issue mentioned above.

I've put a fix up here: https://reviews.llvm.org/D71548 that I think should work. I don't have a system where it fails to build with LLVM_ENABLE_THREADS=OFF.

[russell.gallop]

I reverted this at the end of last year MacOS build issues.

This new version fixes some build issues on various platforms and with LLVM_ENABLE_THREADS=OFF by using LLVM_THREAD_LOCAL.

Not all minimum host toolchains [1] support thread_local (i.e. Apple Clang 6.0) so this falls back to thread on MacOS and other platforms which don't advertise it with has_feature(cxx_thread_local) (even if they support thread_local like gcc). On Windows this uses __declspec(thread) which (from vs2017) is effectively thread_local [2].

This involved rolling back use of unique_ptr to raw pointers.

In time (with higher minimum host tools) LLVM_THREAD_LOCAL could become:

#if LLVM_ENABLE_THREADS
#define LLVM_THREAD_LOCAL thread_local
#else
#define LLVM_THREAD_LOCAL
#endif

and this change should still work.

Tested with Linux with clang and gcc host compiler and Windows with MSVC2017. Also tested with LLVM_ENABLE_THREADS=OFF.

Please take another look. Thanks.

[1] https://llvm.org/docs/GettingStarted.html#host-c-toolchain-both-compiler-and-standard-library
[2] https://docs.microsoft.com/en-us/cpp/cpp/thread?view=vs-2017

[• Quuxplusone]

llvm/lib/Support/TimeProfiler.cpp

255–266

Can TimeTraceProfilerInstance ever actually be non-null here?
If so, are you at all worried that this unguarded access in timeTraceProfilerCleanup() might race with the guarded access in timeTraceProfilerFinishThread()?

264

Once this new'ed pointer gets into the vector, I don't see any codepath that ever calls delete on the pointers in the vector — timeTraceProfilerCleanup() just calls clear() and drops them on the floor without deleting. Am I missing something?

[russell.gallop]

Fix memory leak.

[russell.gallop]

llvm/lib/Support/TimeProfiler.cpp

255–266

It looks like Phabricator has lost the location of your comments since I updated the patch. This comment was made against timeTraceProfilerCleanup().

Can TimeTraceProfilerInstance ever actually be non-null here?

Yes, it is the instance used on the main thread (rather than worker threads from the thread pool) so it will be non-null when time-trace is enabled.

If so, are you at all worried that this unguarded access in timeTraceProfilerCleanup() might race with the guarded access in timeTraceProfilerFinishThread()?

Do you mean unguarded access to TimeTraceProfilerInstance? TimeTraceProfilerInstance does not need guarding as it is not shared, ThreadTimeTraceProfilerInstances does.

With LLVM_ENABLE_THREADS=ON TimeTraceProfilerInstance is thread local so no guard is required. With LLVM_ENABLE_THREADS=OFF there are no other threads calling timeTraceProfilerFinishThread() to race.

I'll add a comment to timeTraceProfilerCleanup() to try and clarify.

264

Ah, you're right. Fixed. Thanks.

[russell.gallop]

Add comment to clarify usage of timeTraceProfilerCleanup.

[russell.gallop]

Ping. Okay to land new version?

Thanks

[• Quuxplusone]

I'm not qualified to comment on the functionality. This seems like it'll be OK with respect to thread_local on Mac OSX. No further comments from me.

llvm/lib/Support/TimeProfiler.cpp

133

const auto &E?

[russell.gallop]

Add consts to references in lambda functions.

[russell.gallop]

Thanks, added const.

[russell.gallop]

In D71059#1838862, @Quuxplusone wrote:

I'm not qualified to comment on the functionality. This seems like it'll be OK with respect to thread_local on Mac OSX. No further comments from me.

Thanks. As those were the recent changes and it was signed off before I'll recommit next week (unless anyone objects).

llvm/include/llvm/Support/TimeProfiler.h

 //===- llvm/Support/TimeProfiler.h - Hierarchical Time Profiler -*- C++ -*-===//
 //
 // 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"
 
 namespace llvm {
 
 struct TimeTraceProfiler;
-extern TimeTraceProfiler *TimeTraceProfilerInstance;
+extern LLVM_THREAD_LOCAL TimeTraceProfiler *TimeTraceProfilerInstance;
 
 /// Initialize the time trace profiler.
 /// This sets up the global \p TimeTraceProfilerInstance
 /// variable to be the profiler instance.
 void timeTraceProfilerInitialize(unsigned TimeTraceGranularity,
                                  StringRef ProcName);
 
 /// Cleanup the time trace profiler, if it was initialized.
 void timeTraceProfilerCleanup();
 
+/// Finish a time trace profiler running on a worker thread.
+void timeTraceProfilerFinishThread();
+
 /// 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

llvm/lib/Support/TimeProfiler.cpp

 //
 //===----------------------------------------------------------------------===//
 
 #include "llvm/Support/TimeProfiler.h"
 #include "llvm/ADT/StringMap.h"
 #include "llvm/Support/CommandLine.h"
 #include "llvm/Support/JSON.h"
 #include "llvm/Support/Path.h"
+#include "llvm/Support/Threading.h"
+#include <algorithm>
 #include <cassert>
 #include <chrono>
+#include <mutex>
 #include <string>
 #include <vector>
 
 using namespace std::chrono;
 
+namespace {
+std::mutex Mu;
+std::vector<llvm::TimeTraceProfiler *>
+    ThreadTimeTraceProfilerInstances; // guarded by Mu
+} // namespace
+
 namespace llvm {
 
-TimeTraceProfiler *TimeTraceProfilerInstance = nullptr;
+LLVM_THREAD_LOCAL TimeTraceProfiler *TimeTraceProfilerInstance = nullptr;
 
 typedef duration<steady_clock::rep, steady_clock::period> DurationType;
 typedef time_point<steady_clock> TimePointType;
 typedef std::pair<size_t, DurationType> CountAndDurationType;
 typedef std::pair<std::string, CountAndDurationType>
     NameAndCountAndDurationType;
 
 struct Entry {
return (time_point_cast<microseconds>(End) -
             time_point_cast<microseconds>(Start))
         .count();
   }
 };
 
 struct TimeTraceProfiler {
   TimeTraceProfiler(unsigned TimeTraceGranularity = 0, StringRef ProcName = "")
       : StartTime(steady_clock::now()), ProcName(ProcName),
-        TimeTraceGranularity(TimeTraceGranularity) {}
+        Tid(llvm::get_threadid()), TimeTraceGranularity(TimeTraceGranularity) {}
 
   void begin(std::string Name, llvm::function_ref<std::string()> Detail) {
     Stack.emplace_back(steady_clock::now(), TimePointType(), std::move(Name),
                        Detail());
   }
 
   void end() {
     assert(!Stack.empty() && "Must call begin() first");
if (std::find_if(++Stack.rbegin(), Stack.rend(), [&](const Entry &Val) {
       auto &CountAndTotal = CountAndTotalPerName[E.Name];
       CountAndTotal.first++;
       CountAndTotal.second += Duration;
     }
 
     Stack.pop_back();
   }
 
+  // Write events from this TimeTraceProfilerInstance and
+  // ThreadTimeTraceProfilerInstances.
   void Write(raw_pwrite_stream &OS) {
+    // Acquire Mutex as reading ThreadTimeTraceProfilerInstances.
+    std::lock_guard<std::mutex> Lock(Mu);
     assert(Stack.empty() &&
            "All profiler sections should be ended when calling Write");
+    assert(std::all_of(ThreadTimeTraceProfilerInstances.begin(),
+                       ThreadTimeTraceProfilerInstances.end(),
+                       [](const auto &TTP) { return TTP->Stack.empty(); }) &&
+           "All profiler sections should be ended when calling Write");
+
     json::OStream J(OS);
     J.objectBegin();
     J.attributeBegin("traceEvents");
     J.arrayBegin();
 
     // Emit all events for the main flame graph.
-    for (const auto &E : Entries) {
+    auto writeEvent = [&](const auto &E, uint64_t Tid) {
       auto StartUs = E.getFlameGraphStartUs(StartTime);
       auto DurUs = E.getFlameGraphDurUs();
 
       J.object([&]{
         J.attribute("pid", 1);
-        J.attribute("tid", 0);
+        J.attribute("tid", int64_t(Tid));
         J.attribute("ph", "X");
         J.attribute("ts", StartUs);
         J.attribute("dur", DurUs);
         J.attribute("name", E.Name);
         if (!E.Detail.empty()) {
           J.attributeObject("args", [&] { J.attribute("detail", E.Detail); });
         }
       });
+    };
+    for (const auto &E : Entries) {
+      writeEvent(E, this->Tid);
+    }
+    for (const auto &TTP : ThreadTimeTraceProfilerInstances) {
+      for (const auto &E : TTP->Entries) {
+        writeEvent(E, TTP->Tid);
+      }
     }
 
     // Emit totals by section name as additional "thread" events, sorted from
     // longest one.
-    int Tid = 1;
+    // Find highest used thread id.
+    uint64_t MaxTid = this->Tid;
+    for (const auto &TTP : ThreadTimeTraceProfilerInstances) {
+      MaxTid = std::max(MaxTid, TTP->Tid);
+    }
+
+    // Combine all CountAndTotalPerName from threads into one.
+    StringMap<CountAndDurationType> AllCountAndTotalPerName;
+    auto combineStat = [&](const auto &Stat) {
+      std::string Key = Stat.getKey();
+      auto Value = Stat.getValue();
+      auto &CountAndTotal = AllCountAndTotalPerName[Key];
+      CountAndTotal.first += Value.first;
+      CountAndTotal.second += Value.second;
+    };
+    for (const auto &Stat : CountAndTotalPerName) {
+      combineStat(Stat);
+    }
+    for (const auto &TTP : ThreadTimeTraceProfilerInstances) {
+      for (const auto &Stat : TTP->CountAndTotalPerName) {
+        combineStat(Stat);
+      }
+    }
+
     std::vector<NameAndCountAndDurationType> SortedTotals;
-    SortedTotals.reserve(CountAndTotalPerName.size());
-    for (const auto &E : CountAndTotalPerName)
-      SortedTotals.emplace_back(E.getKey(), E.getValue());
+    SortedTotals.reserve(AllCountAndTotalPerName.size());
+    for (const auto &Total : AllCountAndTotalPerName)
+      SortedTotals.emplace_back(Total.getKey(), Total.getValue());
 
     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;
+
+    // Report totals on separate threads of tracing file.
+    uint64_t TotalTid = MaxTid + 1;
+    for (const auto &Total : SortedTotals) {
+      auto DurUs = duration_cast<microseconds>(Total.second.second).count();
+      auto Count = AllCountAndTotalPerName[Total.first].first;
 
       J.object([&]{
         J.attribute("pid", 1);
-        J.attribute("tid", Tid);
+        J.attribute("tid", int64_t(TotalTid));
         J.attribute("ph", "X");
         J.attribute("ts", 0);
         J.attribute("dur", DurUs);
-        J.attribute("name", "Total " + E.first);
+        J.attribute("name", "Total " + Total.first);
         J.attributeObject("args", [&] {
           J.attribute("count", int64_t(Count));
           J.attribute("avg ms", int64_t(DurUs / Count / 1000));
         });
       });
 
-      ++Tid;
+      ++TotalTid;
     }
 
     // Emit metadata event with process name.
     J.object([&] {
       J.attribute("cat", "");
       J.attribute("pid", 1);
       J.attribute("tid", 0);
       J.attribute("ts", 0);
       J.attribute("ph", "M");
       J.attribute("name", "process_name");
       J.attributeObject("args", [&] { J.attribute("name", ProcName); });
     });
 
     J.arrayEnd();
     J.attributeEnd();
     J.objectEnd();
   }
 
   SmallVector<Entry, 16> Stack;
   SmallVector<Entry, 128> Entries;
   StringMap<CountAndDurationType> CountAndTotalPerName;
   const TimePointType StartTime;
   const std::string ProcName;
+  const uint64_t Tid;
 
   // Minimum time granularity (in microseconds)
   const unsigned TimeTraceGranularity;
 };
 
 void timeTraceProfilerInitialize(unsigned TimeTraceGranularity,
                                  StringRef ProcName) {
   assert(TimeTraceProfilerInstance == nullptr &&
          "Profiler should not be initialized");
   TimeTraceProfilerInstance = new TimeTraceProfiler(
       TimeTraceGranularity, llvm::sys::path::filename(ProcName));
 }
 
+// Removes all TimeTraceProfilerInstances.
+// Called from main thread.
 void timeTraceProfilerCleanup() {
   delete TimeTraceProfilerInstance;
+  std::lock_guard<std::mutex> Lock(Mu);
+  for (auto TTP : ThreadTimeTraceProfilerInstances)
+    delete TTP;
+  ThreadTimeTraceProfilerInstances.clear();
+}
+
+// Finish TimeTraceProfilerInstance on a worker thread.
+// This doesn't remove the instance, just moves the pointer to global vector.
+void timeTraceProfilerFinishThread() {
+  std::lock_guard<std::mutex> Lock(Mu);
+  ThreadTimeTraceProfilerInstances.push_back(TimeTraceProfilerInstance);
   TimeTraceProfilerInstance = nullptr;
 }
 
 void timeTraceProfilerWrite(raw_pwrite_stream &OS) {
   assert(TimeTraceProfilerInstance != nullptr &&
          "Profiler object can't be null");
   TimeTraceProfilerInstance->Write(OS);
 }