wallace created this revision. Herald added a subscriber: mgorny. Herald added a project: All. wallace requested review of this revision. Herald added a project: LLDB. Herald added a subscriber: lldb-commits.
Repository: rG LLVM Github Monorepo https://reviews.llvm.org/D123356 Files: lldb/source/Plugins/Trace/intel-pt/CMakeLists.txt lldb/source/Plugins/Trace/intel-pt/DecodedThread.h lldb/source/Plugins/Trace/intel-pt/TaskTimer.cpp lldb/source/Plugins/Trace/intel-pt/TaskTimer.h lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.cpp lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.cpp lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.h lldb/test/API/commands/trace/TestTraceDumpInfo.py lldb/test/API/commands/trace/TestTraceLoad.py
Index: lldb/test/API/commands/trace/TestTraceLoad.py =================================================================== --- lldb/test/API/commands/trace/TestTraceLoad.py +++ 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() Index: lldb/test/API/commands/trace/TestTraceDumpInfo.py =================================================================== --- lldb/test/API/commands/trace/TestTraceDumpInfo.py +++ 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"]) Index: lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.h =================================================================== --- lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.h +++ 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<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 Index: lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.cpp =================================================================== --- lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.cpp +++ 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; } Index: lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.cpp =================================================================== --- lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.cpp +++ lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.cpp @@ -30,15 +30,20 @@ } DecodedThreadSP ThreadDecoder::DoDecode() { - 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(); + 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; }); - if (err) - decoded_thread_sp->AppendError(std::move(err)); - return decoded_thread_sp; } Index: lldb/source/Plugins/Trace/intel-pt/TaskTimer.h =================================================================== --- /dev/null +++ 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 <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 Index: lldb/source/Plugins/Trace/intel-pt/TaskTimer.cpp =================================================================== --- /dev/null +++ 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<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; +} Index: lldb/source/Plugins/Trace/intel-pt/DecodedThread.h =================================================================== --- lldb/source/Plugins/Trace/intel-pt/DecodedThread.h +++ lldb/source/Plugins/Trace/intel-pt/DecodedThread.h @@ -239,6 +239,8 @@ 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>; Index: lldb/source/Plugins/Trace/intel-pt/CMakeLists.txt =================================================================== --- lldb/source/Plugins/Trace/intel-pt/CMakeLists.txt +++ 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
_______________________________________________ lldb-commits mailing list lldb-commits@lists.llvm.org https://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-commits