diff --git a/lldb/source/Plugins/Trace/intel-pt/CMakeLists.txt b/lldb/source/Plugins/Trace/intel-pt/CMakeLists.txt --- a/lldb/source/Plugins/Trace/intel-pt/CMakeLists.txt +++ b/lldb/source/Plugins/Trace/intel-pt/CMakeLists.txt @@ -16,6 +16,7 @@ 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 --- a/lldb/source/Plugins/Trace/intel-pt/DecodedThread.h +++ b/lldb/source/Plugins/Trace/intel-pt/DecodedThread.h @@ -239,6 +239,8 @@ 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.h b/lldb/source/Plugins/Trace/intel-pt/TaskTimer.h new file mode 100644 --- /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/TaskTimer.cpp b/lldb/source/Plugins/Trace/intel-pt/TaskTimer.cpp new file mode 100644 --- /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/ThreadDecoder.cpp b/lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.cpp --- a/lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.cpp +++ b/lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.cpp @@ -30,15 +30,20 @@ } 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.h b/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.h --- 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 @@ /// return \a nullptr. Process *GetLiveProcess(); + /// \return + /// The timer object for this trace. + TaskTimer &GetTimer(); + private: friend class TraceIntelPTSessionFileParser; @@ -184,6 +189,7 @@ 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/source/Plugins/Trace/intel-pt/TraceIntelPT.cpp b/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.cpp --- a/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.cpp +++ b/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.cpp @@ -117,19 +117,32 @@ 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 @@ OnBinaryDataReadCallback callback) { return OnThreadBinaryDataRead(tid, "threadTraceBuffer", callback); } + +TaskTimer &TraceIntelPT::GetTimer() { return m_task_timer; } diff --git a/lldb/test/API/commands/trace/TestTraceDumpInfo.py b/lldb/test/API/commands/trace/TestTraceDumpInfo.py --- a/lldb/test/API/commands/trace/TestTraceDumpInfo.py +++ b/lldb/test/API/commands/trace/TestTraceDumpInfo.py @@ -38,9 +38,16 @@ 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 --- a/lldb/test/API/commands/trace/TestTraceLoad.py +++ b/lldb/test/API/commands/trace/TestTraceLoad.py @@ -36,12 +36,18 @@ 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()