From bdf3e7e5b886ab690a82e8d34b4502d9c6c5d6a9 Mon Sep 17 00:00:00 2001 From: Walter Erquinigo Date: Thu, 7 Apr 2022 20:24:25 -0700 Subject: [PATCH] [trace][intelpt] Add task timer classes 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. Differential Revision: https://reviews.llvm.org/D123357 --- lldb/source/Plugins/Trace/intel-pt/CMakeLists.txt | 1 + lldb/source/Plugins/Trace/intel-pt/DecodedThread.h | 2 + lldb/source/Plugins/Trace/intel-pt/TaskTimer.cpp | 22 +++++++ lldb/source/Plugins/Trace/intel-pt/TaskTimer.h | 75 ++++++++++++++++++++++ .../Plugins/Trace/intel-pt/ThreadDecoder.cpp | 25 +++++--- .../source/Plugins/Trace/intel-pt/TraceIntelPT.cpp | 27 ++++++-- lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.h | 6 ++ lldb/test/API/commands/trace/TestTraceDumpInfo.py | 15 +++-- lldb/test/API/commands/trace/TestTraceLoad.py | 14 ++-- 9 files changed, 163 insertions(+), 24 deletions(-) create mode 100644 lldb/source/Plugins/Trace/intel-pt/TaskTimer.cpp create mode 100644 lldb/source/Plugins/Trace/intel-pt/TaskTimer.h diff --git a/lldb/source/Plugins/Trace/intel-pt/CMakeLists.txt b/lldb/source/Plugins/Trace/intel-pt/CMakeLists.txt index 78d64d5..71ca916 100644 --- a/lldb/source/Plugins/Trace/intel-pt/CMakeLists.txt +++ b/lldb/source/Plugins/Trace/intel-pt/CMakeLists.txt @@ -16,6 +16,7 @@ lldb_tablegen(TraceIntelPTCommandOptions.inc -gen-lldb-option-defs add_lldb_library(lldbPluginTraceIntelPT PLUGIN CommandObjectTraceStartIntelPT.cpp DecodedThread.cpp + TaskTimer.cpp LibiptDecoder.cpp ThreadDecoder.cpp TraceCursorIntelPT.cpp diff --git a/lldb/source/Plugins/Trace/intel-pt/DecodedThread.h b/lldb/source/Plugins/Trace/intel-pt/DecodedThread.h index dae69c9..c89abcb 100644 --- a/lldb/source/Plugins/Trace/intel-pt/DecodedThread.h +++ b/lldb/source/Plugins/Trace/intel-pt/DecodedThread.h @@ -239,6 +239,8 @@ private: llvm::Optional 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; diff --git a/lldb/source/Plugins/Trace/intel-pt/TaskTimer.cpp b/lldb/source/Plugins/Trace/intel-pt/TaskTimer.cpp new file mode 100644 index 0000000..3388738 --- /dev/null +++ b/lldb/source/Plugins/Trace/intel-pt/TaskTimer.cpp @@ -0,0 +1,22 @@ +#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 + 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; +} diff --git a/lldb/source/Plugins/Trace/intel-pt/TaskTimer.h b/lldb/source/Plugins/Trace/intel-pt/TaskTimer.h new file mode 100644 index 0000000..c419b9f --- /dev/null +++ b/lldb/source/Plugins/Trace/intel-pt/TaskTimer.h @@ -0,0 +1,75 @@ +//===-- 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 +#include +#include + +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 R TimeTask(llvm::StringRef name, std::function 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(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 + callback); + +private: + std::unordered_map 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 m_thread_timers; +}; + +} // namespace trace_intel_pt +} // namespace lldb_private + +#endif // LLDB_SOURCE_PLUGINS_TRACE_INTEL_PT_TASKTIMER_H diff --git a/lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.cpp b/lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.cpp index 1ffa4d1..50e76ee 100644 --- a/lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.cpp +++ b/lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.cpp @@ -30,15 +30,20 @@ DecodedThreadSP ThreadDecoder::Decode() { } DecodedThreadSP ThreadDecoder::DoDecode() { - DecodedThreadSP decoded_thread_sp = - std::make_shared(m_thread_sp); - - Error err = m_trace.OnThreadBufferRead( - m_thread_sp->GetID(), [&](llvm::ArrayRef data) { - DecodeTrace(*decoded_thread_sp, m_trace, data); - return Error::success(); + return m_trace.GetTimer() + .ForThread(m_thread_sp->GetID()) + .TimeTask("Decoding instructions", [&]() { + DecodedThreadSP decoded_thread_sp = + std::make_shared(m_thread_sp); + + Error err = m_trace.OnThreadBufferRead( + m_thread_sp->GetID(), [&](llvm::ArrayRef data) { + DecodeTrace(*decoded_thread_sp, m_trace, data); + return Error::success(); + }); + + if (err) + decoded_thread_sp->AppendError(std::move(err)); + return decoded_thread_sp; }); - if (err) - decoded_thread_sp->AppendError(std::move(err)); - return decoded_thread_sp; } diff --git a/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.cpp b/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.cpp index 325bcb9..10a5426 100644 --- a/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.cpp +++ b/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.cpp @@ -117,19 +117,32 @@ void TraceIntelPT::DumpTraceInfo(Thread &thread, Stream &s, bool verbose) { 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", + (double)mem_used / 1024); 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); } } @@ -358,3 +371,5 @@ Error TraceIntelPT::OnThreadBufferRead(lldb::tid_t tid, OnBinaryDataReadCallback callback) { return OnThreadBinaryDataRead(tid, "threadTraceBuffer", callback); } + +TaskTimer &TraceIntelPT::GetTimer() { return m_task_timer; } diff --git a/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.h b/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.h index 3b93374..ca855f1 100644 --- a/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.h +++ b/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.h @@ -9,6 +9,7 @@ #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" @@ -150,6 +151,10 @@ public: /// return \a nullptr. Process *GetLiveProcess(); + /// \return + /// The timer object for this trace. + TaskTimer &GetTimer(); + private: friend class TraceIntelPTSessionFileParser; @@ -184,6 +189,7 @@ private: std::map> m_thread_decoders; /// Error gotten after a failed live process update, if any. llvm::Optional m_live_refresh_error; + TaskTimer m_task_timer; }; } // namespace trace_intel_pt diff --git a/lldb/test/API/commands/trace/TestTraceDumpInfo.py b/lldb/test/API/commands/trace/TestTraceDumpInfo.py index 1e26ed4..059b22f 100644 --- a/lldb/test/API/commands/trace/TestTraceDumpInfo.py +++ b/lldb/test/API/commands/trace/TestTraceDumpInfo.py @@ -38,9 +38,16 @@ class TestTraceDumpInfo(TraceIntelPTTestCaseBase): 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"]) diff --git a/lldb/test/API/commands/trace/TestTraceLoad.py b/lldb/test/API/commands/trace/TestTraceLoad.py index af55462..47f7726 100644 --- a/lldb/test/API/commands/trace/TestTraceLoad.py +++ b/lldb/test/API/commands/trace/TestTraceLoad.py @@ -36,12 +36,18 @@ class TestTraceLoad(TraceIntelPTTestCaseBase): 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''']) def testLoadInvalidTraces(self): src_dir = self.getSourceDir() -- 2.7.4