[trace][intelpt] Add task timer classes

[wallace]

Summary

I'm adding two new classes that can be used to measure the duration of long
tasks as process and thread level, e.g. decoding, fetching data from
lldb-server, etc. In this first patch, I'm using it to measure the time it takes
to decode each thread, which is printed out with the dump info command. In a
later patch I'll start adding process-level tasks and I might move these
classes to the upper Trace level, instead of having them in the intel-pt
plugin. I might need to do that anyway in the future when we have to
measure HTR. For now, I want to keep the impact of this change minimal.

With it, I was able to generate the following info of a very big trace:

(lldb) thread trace dump info                                                                                                            Trace technology: intel-pt

thread #1: tid = 616081
  Total number of instructions: 9729366

  Memory usage:
    Raw trace size: 1024 KiB
    Total approximate memory usage (excluding raw trace): 123517.34 KiB
    Average memory usage per instruction (excluding raw trace): 13.00 bytes

  Timing:
    Decoding instructions: 1.62s

  Errors:
    Number of TSC decoding errors: 0

As seen above, it took 1.62 seconds to decode 9.7M instructions. This is great
news, as we don't need to do any optimization work in this area.

[jj10306]

lldb/source/Plugins/Trace/intel-pt/DecodedThread.h

243

nit: Do you need an explicit initialization?

lldb/source/Plugins/Trace/intel-pt/TaskTimer.cpp

17

Should this be named to better reflect what this function is doing? It seems that this function is "getting" the ThreadTaskTimer associated with the tid and creates it if one doesn't already exist.
Maybe something like GetThreadTaskTimer, TimerForThread, TimerByThread ?

lldb/source/Plugins/Trace/intel-pt/TaskTimer.h

58

[wallace]

lldb/source/Plugins/Trace/intel-pt/DecodedThread.h

243

yes, otherwise m_total_decoding_time takes the value of now(). That's a little bit counterintuitive for me

lldb/source/Plugins/Trace/intel-pt/TaskTimer.h

58

DenseMaps can't hold strings, only const char * :(

[wallace]

Committed as bdf3e7e5b886ab690a82e8d34b4502d9c6c5d6a9

lldb/source/Plugins/Trace/intel-pt/CMakeLists.txt

 
 lldb_tablegen(TraceIntelPTCommandOptions.inc -gen-lldb-option-defs
   SOURCE TraceIntelPTOptions.td
   TARGET TraceIntelPTOptionsGen)
 
 add_lldb_library(lldbPluginTraceIntelPT PLUGIN
   CommandObjectTraceStartIntelPT.cpp
   DecodedThread.cpp
+  TaskTimer.cpp
   LibiptDecoder.cpp
   ThreadDecoder.cpp
   TraceCursorIntelPT.cpp
   TraceIntelPT.cpp
   TraceIntelPTJSONStructs.cpp
   TraceIntelPTSessionFileParser.cpp
   TraceIntelPTSessionSaver.cpp
 

lldb/source/Plugins/Trace/intel-pt/DecodedThread.h

private:
   // This variables stores the messages of all the error instructions in the
   // trace. It maps `instruction index -> error message`.
   llvm::DenseMap<uint64_t, std::string> m_errors;
   /// The size in bytes of the raw buffer before decoding. It might be None if
   /// the decoding failed.
   llvm::Optional<size_t> m_raw_trace_size;
   /// All occurrences of libipt errors when decoding TSCs.
   LibiptErrors m_tsc_errors;
+  /// Total amount of time spent decoding.
+  std::chrono::milliseconds m_total_decoding_time{0};
 };
 
 using DecodedThreadSP = std::shared_ptr<DecodedThread>;
 
 } // namespace trace_intel_pt
 } // namespace lldb_private
 
 #endif // LLDB_SOURCE_PLUGINS_TRACE_INTEL_PT_DECODEDTHREAD_H

lldb/source/Plugins/Trace/intel-pt/TaskTimer.h

+//===-- TaskTimer.h ---------------------------------------------*- 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 LLDB_SOURCE_PLUGINS_TRACE_INTEL_PT_TASKTIMER_H
+#define LLDB_SOURCE_PLUGINS_TRACE_INTEL_PT_TASKTIMER_H
+
+#include "lldb/lldb-types.h"
+
+#include "llvm/ADT/DenseMap.h"
+#include "llvm/ADT/StringRef.h"
+
+#include <chrono>
+#include <functional>
+#include <unordered_map>
+
+namespace lldb_private {
+namespace trace_intel_pt {
+
+/// Class used to track the duration of long running tasks related to a single
+/// thread for reporting.
+class ThreadTaskTimer {
+public:
+  /// Execute the given \p task and record its duration.
+  ///
+  /// \param[in] name
+  ///     The name used to identify this task for reporting.
+  ///
+  /// \param[in] task
+  ///     The task function.
+  ///
+  /// \return
+  ///     The return value of the task.
+  template <class R> R TimeTask(llvm::StringRef name, std::function<R()> task) {
+    auto start = std::chrono::steady_clock::now();
+    R result = task();
+    auto end = std::chrono::steady_clock::now();
+    std::chrono::milliseconds duration =
+        std::chrono::duration_cast<std::chrono::milliseconds>(end - start);
+    m_timed_tasks.insert({name.str(), duration});
+    return result;
+  }
+
+  /// Executive the given \p callback on each recorded task.
+  ///
+  /// \param[in] callback
+  ///     The first parameter of the callback is the name of the recorded task,
+  ///     and the second parameter is the duration of that task.
+  void ForEachTimedTask(std::function<void(const std::string &name,
+                                           std::chrono::milliseconds duration)>
+                            callback);
+
+private:
+  std::unordered_map<std::string, std::chrono::milliseconds> m_timed_tasks;
+};
+
+/// Class used to track the duration of long running tasks for reporting.
+class TaskTimer {
+public:
+  /// \return
+  ///     The timer object for the given thread.
+  ThreadTaskTimer &ForThread(lldb::tid_t tid);
+
+private:
+  llvm::DenseMap<lldb::tid_t, ThreadTaskTimer> m_thread_timers;
+};
+
+} // namespace trace_intel_pt
+} // namespace lldb_private
+
+#endif // LLDB_SOURCE_PLUGINS_TRACE_INTEL_PT_TASKTIMER_H

lldb/source/Plugins/Trace/intel-pt/TaskTimer.cpp

+#include "TaskTimer.h"
+
+using namespace lldb;
+using namespace lldb_private;
+using namespace lldb_private::trace_intel_pt;
+using namespace llvm;
+
+void ThreadTaskTimer::ForEachTimedTask(
+    std::function<void(const std::string &event,
+                       std::chrono::milliseconds duration)>
+        callback) {
+  for (const auto &kv : m_timed_tasks) {
+    callback(kv.first, kv.second);
+  }
+}
+
+ThreadTaskTimer &TaskTimer::ForThread(lldb::tid_t tid) {
+  auto it = m_thread_timers.find(tid);
+  if (it == m_thread_timers.end())
+    it = m_thread_timers.try_emplace(tid, ThreadTaskTimer{}).first;
+  return it->second;
+}

lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.cpp

 
 DecodedThreadSP ThreadDecoder::Decode() {
   if (!m_decoded_thread.hasValue())
     m_decoded_thread = DoDecode();
   return *m_decoded_thread;
 }
 
 DecodedThreadSP ThreadDecoder::DoDecode() {
+  return m_trace.GetTimer()
+      .ForThread(m_thread_sp->GetID())
+      .TimeTask<DecodedThreadSP>("Decoding instructions", [&]() {
         DecodedThreadSP decoded_thread_sp =
             std::make_shared<DecodedThread>(m_thread_sp);
 
         Error err = m_trace.OnThreadBufferRead(
             m_thread_sp->GetID(), [&](llvm::ArrayRef<uint8_t> data) {
               DecodeTrace(*decoded_thread_sp, m_trace, data);
               return Error::success();
             });
+
         if (err)
           decoded_thread_sp->AppendError(std::move(err));
         return decoded_thread_sp;
+      });
 }

lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.h

 //===-- TraceIntelPT.h ------------------------------------------*- 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 LLDB_SOURCE_PLUGINS_TRACE_INTEL_PT_TRACEINTELPT_H
 #define LLDB_SOURCE_PLUGINS_TRACE_INTEL_PT_TRACEINTELPT_H
 
+#include "TaskTimer.h"
 #include "ThreadDecoder.h"
 #include "TraceIntelPTSessionFileParser.h"
 #include "lldb/Utility/FileSpec.h"
 #include "lldb/lldb-types.h"
 #include "llvm/Support/raw_ostream.h"
 
 namespace lldb_private {
 namespace trace_intel_pt {
public:
 
   /// Get the current traced live process.
   ///
   /// \return
   ///     The current traced live process. If it's not a live process,
   ///     return \a nullptr.
   Process *GetLiveProcess();
 
+  /// \return
+  ///     The timer object for this trace.
+  TaskTimer &GetTimer();
+
 private:
   friend class TraceIntelPTSessionFileParser;
 
   llvm::Expected<pt_cpu> GetCPUInfoForLiveProcess();
 
   /// \param[in] trace_threads
   ///     ThreadTrace instances, which are not live-processes and whose trace
   ///     files are fixed.
private:
   DecodedThreadSP Decode(Thread &thread);
 
   /// It is provided by either a session file or a live process' "cpuInfo"
   /// binary data.
   llvm::Optional<pt_cpu> m_cpu_info;
   std::map<lldb::tid_t, std::unique_ptr<ThreadDecoder>> m_thread_decoders;
   /// Error gotten after a failed live process update, if any.
   llvm::Optional<std::string> m_live_refresh_error;
+  TaskTimer m_task_timer;
 };
 
 } // namespace trace_intel_pt
 } // namespace lldb_private
 
 #endif // LLDB_SOURCE_PLUGINS_TRACE_INTEL_PT_TRACEINTELPT_H

lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.cpp

if (!raw_size) {
     s << ", not traced\n";
     return;
   }
   s << "\n";
   DecodedThreadSP decoded_trace_sp = Decode(thread);
   size_t insn_len = decoded_trace_sp->GetInstructionsCount();
   size_t mem_used = decoded_trace_sp->CalculateApproximateMemoryUsage();
 
-  s.Format("  Raw trace size: {0} KiB\n", *raw_size / 1024);
   s.Format("  Total number of instructions: {0}\n", insn_len);
-  s.Format("  Total approximate memory usage: {0:2} KiB\n",
-           (double)mem_used / 1024);
+
+  s.PutCString("\n  Memory usage:\n");
+  s.Format("    Raw trace size: {0} KiB\n", *raw_size / 1024);
+  s.Format(
+      "    Total approximate memory usage (excluding raw trace): {0:2} KiB\n",
   if (insn_len != 0)
-    s.Format("  Average memory usage per instruction: {0:2} bytes\n",
+    s.Format("    Average memory usage per instruction (excluding raw trace): "
+             "{0:2} bytes\n",
              (double)mem_used / insn_len);
 
+  s.PutCString("\n  Timing:\n");
+  GetTimer()
+      .ForThread(thread.GetID())
+      .ForEachTimedTask(
+          [&](const std::string &name, std::chrono::milliseconds duration) {
+            s.Format("    {0}: {1:2}s\n", name, duration.count() / 1000.0);
+          });
+
+  s.PutCString("\n  Errors:\n");
   const DecodedThread::LibiptErrors &tsc_errors =
       decoded_trace_sp->GetTscErrors();
-  s.Format("\n  Number of TSC decoding errors: {0}\n", tsc_errors.total_count);
+  s.Format("    Number of TSC decoding errors: {0}\n", tsc_errors.total_count);
   for (const auto &error_message_to_count : tsc_errors.libipt_errors) {
-    s.Format("    {0}: {1}\n", error_message_to_count.first,
+    s.Format("      {0}: {1}\n", error_message_to_count.first,
              error_message_to_count.second);
   }
 }
 
 Optional<size_t> TraceIntelPT::GetRawTraceSize(Thread &thread) {
   if (IsTraced(thread.GetID()))
     return Decode(thread)->GetRawTraceSize();
   else
Error TraceIntelPT::Start(llvm::ArrayRef<lldb::tid_t> tids,
 
   return Start(tids, thread_buffer_size, enable_tsc, psb_period);
 }
 
 Error TraceIntelPT::OnThreadBufferRead(lldb::tid_t tid,
                                        OnBinaryDataReadCallback callback) {
   return OnThreadBinaryDataRead(tid, "threadTraceBuffer", callback);
 }
+
+TaskTimer &TraceIntelPT::GetTimer() { return m_task_timer; }

lldb/test/API/commands/trace/TestTraceDumpInfo.py

def testDumpRawTraceSize(self):
         self.expect("trace load -v " +
         os.path.join(self.getSourceDir(), "intelpt-trace", "trace.json"),
         substrs=["intel-pt"])
 
         self.expect("thread trace dump info",
             substrs=['''Trace technology: intel-pt
 
 thread #1: tid = 3842849
-  Raw trace size: 4 KiB
   Total number of instructions: 21
-  Total approximate memory usage: 0.27 KiB
-  Average memory usage per instruction: 13.00 bytes
 
-  Number of TSC decoding errors: 0'''])
+  Memory usage:
+    Raw trace size: 4 KiB
+    Total approximate memory usage (excluding raw trace): 0.27 KiB
+    Average memory usage per instruction (excluding raw trace): 13.00 bytes
+
+  Timing:
+    Decoding instructions: ''', '''s
+
+  Errors:
+    Number of TSC decoding errors: 0'''],
+            patterns=["Decoding instructions: \d.\d\ds"])

lldb/test/API/commands/trace/TestTraceLoad.py

def testLoadTrace(self):
         self.assertEqual("6AA9A4E2-6F28-2F33-377D-59FECE874C71-5B41261A", module.GetUUIDString())
 
         # check that the Process and Thread objects were created correctly
         self.expect("thread info", substrs=["tid = 3842849"])
         self.expect("thread list", substrs=["Process 1234 stopped", "tid = 3842849"])
         self.expect("thread trace dump info", substrs=['''Trace technology: intel-pt
 
 thread #1: tid = 3842849
-  Raw trace size: 4 KiB
   Total number of instructions: 21
-  Total approximate memory usage: 0.27 KiB
-  Average memory usage per instruction: 13.00 bytes
 
+  Memory usage:
+    Raw trace size: 4 KiB
+    Total approximate memory usage (excluding raw trace): 0.27 KiB
+    Average memory usage per instruction (excluding raw trace): 13.00 bytes
+
+  Timing:
+    Decoding instructions: ''', '''s
+
+  Errors:
     Number of TSC decoding errors: 0'''])
 
     def testLoadInvalidTraces(self):
         src_dir = self.getSourceDir()
         # We test first an invalid type
         self.expect("trace load -v " + os.path.join(src_dir, "intelpt-trace", "trace_bad.json"), error=True,
           substrs=['''error: expected object at traceSession.processes[0]
 
 Context: