[Lldb-commits] [lldb] bdf3e7e - [trace][intelpt] Add task timer classes
Walter Erquinigo via lldb-commits
lldb-commits at lists.llvm.org
Tue Apr 12 13:08:14 PDT 2022
Author: Walter Erquinigo
Date: 2022-04-12T13:08:03-07:00
New Revision: bdf3e7e5b886ab690a82e8d34b4502d9c6c5d6a9
URL: https://github.com/llvm/llvm-project/commit/bdf3e7e5b886ab690a82e8d34b4502d9c6c5d6a9
DIFF: https://github.com/llvm/llvm-project/commit/bdf3e7e5b886ab690a82e8d34b4502d9c6c5d6a9.diff
LOG: [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
Added:
lldb/source/Plugins/Trace/intel-pt/TaskTimer.cpp
lldb/source/Plugins/Trace/intel-pt/TaskTimer.h
Modified:
lldb/source/Plugins/Trace/intel-pt/CMakeLists.txt
lldb/source/Plugins/Trace/intel-pt/DecodedThread.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
Removed:
################################################################################
diff --git a/lldb/source/Plugins/Trace/intel-pt/CMakeLists.txt b/lldb/source/Plugins/Trace/intel-pt/CMakeLists.txt
index 78d64d509b8cc..71ca916190fe6 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 dae69c90816d8..c89abcbcf4391 100644
--- a/lldb/source/Plugins/Trace/intel-pt/DecodedThread.h
+++ b/lldb/source/Plugins/Trace/intel-pt/DecodedThread.h
@@ -239,6 +239,8 @@ class DecodedThread : public std::enable_shared_from_this<DecodedThread> {
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>;
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 0000000000000..33887389cde29
--- /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<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;
+}
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 0000000000000..c419b9f2b35a6
--- /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 <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
diff --git a/lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.cpp b/lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.cpp
index 1ffa4d197c853..50e76ee2a9ee0 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<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;
}
diff --git a/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.cpp b/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.cpp
index 325bcb9acc163..10a542652ddfd 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 3b93374029d0b..ca855f1abccdb 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 @@ class TraceIntelPT : public Trace {
/// return \a nullptr.
Process *GetLiveProcess();
+ /// \return
+ /// The timer object for this trace.
+ TaskTimer &GetTimer();
+
private:
friend class TraceIntelPTSessionFileParser;
@@ -184,6 +189,7 @@ class TraceIntelPT : public Trace {
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
diff --git a/lldb/test/API/commands/trace/TestTraceDumpInfo.py b/lldb/test/API/commands/trace/TestTraceDumpInfo.py
index 1e26ed44c1678..059b22f9b6f4d 100644
--- a/lldb/test/API/commands/trace/TestTraceDumpInfo.py
+++ b/lldb/test/API/commands/trace/TestTraceDumpInfo.py
@@ -38,9 +38,16 @@ def testDumpRawTraceSize(self):
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 af55462c25a0c..47f7726f52824 100644
--- a/lldb/test/API/commands/trace/TestTraceLoad.py
+++ b/lldb/test/API/commands/trace/TestTraceLoad.py
@@ -36,12 +36,18 @@ def testLoadTrace(self):
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()
More information about the lldb-commits
mailing list