add task timer

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: