From 9b79187c96a3bc2c245ab54d49accc12336f0cee Mon Sep 17 00:00:00 2001 From: Jakob Johnson Date: Tue, 22 Mar 2022 06:15:56 -0700 Subject: [PATCH] [trace][intelpt] Server side changes for TSC to wall time conversion Update the response schema of the TraceGetState packet and add Intel PT specific response structure that contains the TSC conversion, if it exists. The IntelPTCollector loads the TSC conversion and caches it to prevent unnecessary calls to perf_event_open. Move the TSC conversion calculation from Perf.h to TraceIntelPTGDBRemotePackets.h to remove dependency on Linux specific headers. Differential Revision: https://reviews.llvm.org/D122246 --- lldb/docs/lldb-gdb-remote.txt | 27 ++++- .../lldb/Utility/TraceGDBRemotePackets.h | 26 +++++ .../Utility/TraceIntelPTGDBRemotePackets.h | 58 ++++++++++ .../Process/Linux/IntelPTCollector.cpp | 11 ++ .../Plugins/Process/Linux/IntelPTCollector.h | 4 +- lldb/source/Plugins/Process/Linux/Perf.cpp | 22 +--- lldb/source/Plugins/Process/Linux/Perf.h | 25 +---- .../Plugins/Process/POSIX/ProcessPOSIXLog.h | 3 +- .../Utility/TraceIntelPTGDBRemotePackets.cpp | 64 +++++++++++ lldb/unittests/Process/Linux/PerfTests.cpp | 7 +- lldb/unittests/Utility/CMakeLists.txt | 1 + .../Utility/TraceGDBRemotePacketsTest.cpp | 101 ++++++++++++++++++ 12 files changed, 301 insertions(+), 48 deletions(-) create mode 100644 lldb/unittests/Utility/TraceGDBRemotePacketsTest.cpp diff --git a/lldb/docs/lldb-gdb-remote.txt b/lldb/docs/lldb-gdb-remote.txt index 980dc77c86f5..2ddc3183b80e 100644 --- a/lldb/docs/lldb-gdb-remote.txt +++ b/lldb/docs/lldb-gdb-remote.txt @@ -451,7 +451,12 @@ read packet: OK/E;AAAAAAAAA // "size": , // Size in bytes of this thread data. // }, -// }] +// ], +// "counters"?: { +// "info_kind": {...parameters specific to the provided counter info kind}, +// Each entry includes information related to counters associated with the trace. +// They are described below. +// } // } // // NOTES @@ -463,6 +468,26 @@ read packet: OK/E;AAAAAAAAA // Binary data kinds: // - threadTraceBuffer: trace buffer for a thread. // - cpuInfo: contents of the /proc/cpuinfo file. +// +// Counter info kinds: +// tsc-perf-zero-conversion: +// +// This field allows converting Intel processor's TSC values to a wall time. +// It is available through the Linux perf_event API when cap_user_time and cap_user_time_zero +// are set. +// See the documentation of time_zero in +// https://man7.org/linux/man-pages/man2/perf_event_open.2.html for more information about +// the calculation and the meaning of the values in the schema below. +/// +// Sub-schema for this field: +// +// { +// "tsc-perf-zero-conversion": { +// "time_mult": , +// "time_shift": , +// "time_zero": , +// } +// } //---------------------------------------------------------------------- send packet: jLLDBTraceGetState:{"type":}] diff --git a/lldb/include/lldb/Utility/TraceGDBRemotePackets.h b/lldb/include/lldb/Utility/TraceGDBRemotePackets.h index 1d2448b05f2a..b2669ee3d813 100644 --- a/lldb/include/lldb/Utility/TraceGDBRemotePackets.h +++ b/lldb/include/lldb/Utility/TraceGDBRemotePackets.h @@ -10,6 +10,7 @@ #define LLDB_UTILITY_TRACEGDBREMOTEPACKETS_H #include "llvm/Support/JSON.h" +#include #include "lldb/lldb-defines.h" #include "lldb/lldb-enumerations.h" @@ -116,6 +117,31 @@ bool fromJSON(const llvm::json::Value &value, TraceThreadState &packet, llvm::json::Value toJSON(const TraceThreadState &packet); +/// Interface for different algorithms used to convert trace +/// counters into different units. +template class TraceCounterConversion { +public: + virtual ~TraceCounterConversion() = default; + + /// Convert from raw counter value to the target type. + /// + /// \param[in] raw_counter_value + /// The raw counter value to be converted. + /// + /// \return + /// The converted counter value. + virtual ToType Convert(uint64_t raw_counter_value) = 0; + + /// Serialize trace counter conversion values to JSON. + /// + /// \return + /// \a llvm::json::Value representing the trace counter conversion object. + virtual llvm::json::Value toJSON() = 0; +}; + +using TraceTscConversionUP = + std::unique_ptr>; + struct TraceGetStateResponse { std::vector tracedThreads; std::vector processBinaryData; diff --git a/lldb/include/lldb/Utility/TraceIntelPTGDBRemotePackets.h b/lldb/include/lldb/Utility/TraceIntelPTGDBRemotePackets.h index 8f4947b1f189..8960949f2039 100644 --- a/lldb/include/lldb/Utility/TraceIntelPTGDBRemotePackets.h +++ b/lldb/include/lldb/Utility/TraceIntelPTGDBRemotePackets.h @@ -11,6 +11,10 @@ #include "lldb/Utility/TraceGDBRemotePackets.h" +#include "llvm/Support/JSON.h" + +#include + /// See docs/lldb-gdb-remote.txt for more information. namespace lldb_private { @@ -40,6 +44,60 @@ bool fromJSON(const llvm::json::Value &value, TraceIntelPTStartRequest &packet, llvm::json::Value toJSON(const TraceIntelPTStartRequest &packet); /// \} +/// jLLDBTraceGetState gdb-remote packet +/// \{ + +/// TSC to wall time conversion values defined in the Linux perf_event_open API +/// when the capibilities cap_user_time and cap_user_time_zero are set. See the +/// See the documentation of `time_zero` in +/// https://man7.org/linux/man-pages/man2/perf_event_open.2.html for more +/// information. +class LinuxPerfZeroTscConversion + : public TraceCounterConversion { +public: + /// Create new \a LinuxPerfZeroTscConversion object from the conversion values + /// defined in the Linux perf_event_open API. + LinuxPerfZeroTscConversion(uint32_t time_mult, uint16_t time_shift, + uint64_t time_zero) + : m_time_mult(time_mult), m_time_shift(time_shift), + m_time_zero(time_zero) {} + + /// Convert TSC value to nanosecond wall time. The beginning of time (0 + /// nanoseconds) is defined by the kernel at boot time and has no particularly + /// useful meaning. On the other hand, this value is constant for an entire + /// trace session. + // See 'time_zero' section of + // https://man7.org/linux/man-pages/man2/perf_event_open.2.html + /// + /// \param[in] tsc + /// The TSC value to be converted. + /// + /// \return + /// Nanosecond wall time. + std::chrono::nanoseconds Convert(uint64_t raw_counter_value) override; + + llvm::json::Value toJSON() override; + +private: + uint32_t m_time_mult; + uint16_t m_time_shift; + uint64_t m_time_zero; +}; + +struct TraceIntelPTGetStateResponse : TraceGetStateResponse { + /// The TSC to wall time conversion if it exists, otherwise \b nullptr. + TraceTscConversionUP tsc_conversion; +}; + +bool fromJSON(const llvm::json::Value &value, + TraceTscConversionUP &tsc_conversion, llvm::json::Path path); + +bool fromJSON(const llvm::json::Value &value, + TraceIntelPTGetStateResponse &packet, llvm::json::Path path); + +llvm::json::Value toJSON(const TraceIntelPTGetStateResponse &packet); +/// \} + } // namespace lldb_private #endif // LLDB_UTILITY_TRACEINTELPTGDBREMOTEPACKETS_H diff --git a/lldb/source/Plugins/Process/Linux/IntelPTCollector.cpp b/lldb/source/Plugins/Process/Linux/IntelPTCollector.cpp index 5f31c10f8b88..4882ab64f16a 100644 --- a/lldb/source/Plugins/Process/Linux/IntelPTCollector.cpp +++ b/lldb/source/Plugins/Process/Linux/IntelPTCollector.cpp @@ -522,6 +522,17 @@ IntelPTProcessTrace::GetThreadTraces() const { /// IntelPTCollector +IntelPTCollector::IntelPTCollector(lldb::pid_t pid) + : m_pid(pid), m_thread_traces(pid) { + if (Expected tsc_conversion = + LoadPerfTscConversionParameters()) + m_tsc_conversion = + std::make_unique(*tsc_conversion); + else + LLDB_LOG_ERROR(GetLog(POSIXLog::Trace), tsc_conversion.takeError(), + "unable to load TSC to wall time conversion: {0}"); +} + Error IntelPTCollector::TraceStop(lldb::tid_t tid) { if (IsProcessTracingEnabled() && m_process_trace->TracesThread(tid)) return m_process_trace->TraceStop(tid); diff --git a/lldb/source/Plugins/Process/Linux/IntelPTCollector.h b/lldb/source/Plugins/Process/Linux/IntelPTCollector.h index 12fa12dc299d..aa7eba4cd937 100644 --- a/lldb/source/Plugins/Process/Linux/IntelPTCollector.h +++ b/lldb/source/Plugins/Process/Linux/IntelPTCollector.h @@ -185,7 +185,7 @@ private: /// Main class that manages intel-pt process and thread tracing. class IntelPTCollector { public: - IntelPTCollector(lldb::pid_t pid) : m_pid(pid), m_thread_traces(pid) {} + IntelPTCollector(lldb::pid_t pid); static bool IsSupported(); @@ -235,6 +235,8 @@ private: /// Threads traced due to "process tracing". Only one active "process tracing" /// instance is assumed for a single process. llvm::Optional m_process_trace; + /// TSC to wall time conversion. + TraceTscConversionUP m_tsc_conversion; }; } // namespace process_linux diff --git a/lldb/source/Plugins/Process/Linux/Perf.cpp b/lldb/source/Plugins/Process/Linux/Perf.cpp index 455a81fbcbaf..ed65c61dc482 100644 --- a/lldb/source/Plugins/Process/Linux/Perf.cpp +++ b/lldb/source/Plugins/Process/Linux/Perf.cpp @@ -8,15 +8,9 @@ #include "Perf.h" -#include "lldb/lldb-types.h" - -#include "llvm/Support/Error.h" #include "llvm/Support/FormatVariadic.h" #include "llvm/Support/MathExtras.h" -#include -#include -#include #include #include #include @@ -25,8 +19,8 @@ using namespace lldb_private; using namespace process_linux; using namespace llvm; -Expected -lldb_private::process_linux::FetchPerfTscConversionParameters() { +Expected +lldb_private::process_linux::LoadPerfTscConversionParameters() { lldb::pid_t pid = getpid(); perf_event_attr attr; memset(&attr, 0, sizeof(attr)); @@ -43,7 +37,7 @@ lldb_private::process_linux::FetchPerfTscConversionParameters() { perf_event_mmap_page &mmap_metada = perf_event->GetMetadataPage(); if (mmap_metada.cap_user_time && mmap_metada.cap_user_time_zero) { - return PerfTscConversionParameters{ + return LinuxPerfZeroTscConversion{ mmap_metada.time_mult, mmap_metada.time_shift, mmap_metada.time_zero}; } else { auto err_cap = @@ -56,16 +50,6 @@ lldb_private::process_linux::FetchPerfTscConversionParameters() { } } -std::chrono::nanoseconds PerfTscConversionParameters::ToWallTime(uint64_t tsc) { - // See 'time_zero' section of - // https://man7.org/linux/man-pages/man2/perf_event_open.2.html - uint64_t quot = tsc >> m_time_shift; - uint64_t rem_flag = (((uint64_t)1 << m_time_shift) - 1); - uint64_t rem = tsc & rem_flag; - return std::chrono::nanoseconds{m_time_zero + quot * m_time_mult + - ((rem * m_time_mult) >> m_time_shift)}; -} - void resource_handle::MmapDeleter::operator()(void *ptr) { if (m_bytes && ptr != nullptr) munmap(ptr, m_bytes); diff --git a/lldb/source/Plugins/Process/Linux/Perf.h b/lldb/source/Plugins/Process/Linux/Perf.h index 6853b58666b1..d5cb1f3b7d88 100644 --- a/lldb/source/Plugins/Process/Linux/Perf.h +++ b/lldb/source/Plugins/Process/Linux/Perf.h @@ -15,6 +15,7 @@ #ifndef LLDB_SOURCE_PLUGINS_PROCESS_LINUX_PERF_H #define LLDB_SOURCE_PLUGINS_PROCESS_LINUX_PERF_H +#include "lldb/Utility/TraceIntelPTGDBRemotePackets.h" #include "lldb/lldb-types.h" #include "llvm/Support/Error.h" @@ -232,29 +233,9 @@ private: resource_handle::MmapUP m_aux_base; }; -/// TSC to nanoseconds conversion values defined by the Linux perf_event API -/// when the capibilities cap_user_time and cap_user_time_zero are set. See the -/// documentation of `time_zero` in -/// https://man7.org/linux/man-pages/man2/perf_event_open.2.html for more -/// information. -struct PerfTscConversionParameters { - uint32_t m_time_mult; - uint16_t m_time_shift; - uint64_t m_time_zero; - - /// Convert TSC value to nanosecond wall time. - /// - /// \a param[in] tsc - /// The TSC value to be converted. - /// - /// \return - /// Nanosecond wall time. - std::chrono::nanoseconds ToWallTime(uint64_t tsc); -}; - -/// Fetch \a PerfTscConversionParameters from \a perf_event_mmap_page, if +/// Load \a PerfTscConversionParameters from \a perf_event_mmap_page, if /// available. -llvm::Expected FetchPerfTscConversionParameters(); +llvm::Expected LoadPerfTscConversionParameters(); } // namespace process_linux } // namespace lldb_private diff --git a/lldb/source/Plugins/Process/POSIX/ProcessPOSIXLog.h b/lldb/source/Plugins/Process/POSIX/ProcessPOSIXLog.h index 2d48b9db013c..88cfdfd204c0 100644 --- a/lldb/source/Plugins/Process/POSIX/ProcessPOSIXLog.h +++ b/lldb/source/Plugins/Process/POSIX/ProcessPOSIXLog.h @@ -23,7 +23,8 @@ enum class POSIXLog : Log::MaskType { Registers = Log::ChannelFlag<4>, Thread = Log::ChannelFlag<5>, Watchpoints = Log::ChannelFlag<6>, - LLVM_MARK_AS_BITMASK_ENUM(Watchpoints) + Trace = Log::ChannelFlag<7>, + LLVM_MARK_AS_BITMASK_ENUM(Trace) }; LLVM_ENABLE_BITMASK_ENUMS_IN_NAMESPACE(); diff --git a/lldb/source/Utility/TraceIntelPTGDBRemotePackets.cpp b/lldb/source/Utility/TraceIntelPTGDBRemotePackets.cpp index dbb93d8d1c5c..5dd026141b3e 100644 --- a/lldb/source/Utility/TraceIntelPTGDBRemotePackets.cpp +++ b/lldb/source/Utility/TraceIntelPTGDBRemotePackets.cpp @@ -43,4 +43,68 @@ json::Value toJSON(const TraceIntelPTStartRequest &packet) { return base; } +std::chrono::nanoseconds +LinuxPerfZeroTscConversion::Convert(uint64_t raw_counter_value) { + uint64_t quot = raw_counter_value >> m_time_shift; + uint64_t rem_flag = (((uint64_t)1 << m_time_shift) - 1); + uint64_t rem = raw_counter_value & rem_flag; + return std::chrono::nanoseconds{m_time_zero + quot * m_time_mult + + ((rem * m_time_mult) >> m_time_shift)}; +} + +json::Value LinuxPerfZeroTscConversion::toJSON() { + return json::Value(json::Object{ + {"kind", "tsc-perf-zero-conversion"}, + {"time_mult", static_cast(m_time_mult)}, + {"time_shift", static_cast(m_time_shift)}, + {"time_zero", static_cast(m_time_zero)}, + }); +} + +bool fromJSON(const json::Value &value, TraceTscConversionUP &tsc_conversion, + json::Path path) { + ObjectMapper o(value, path); + + int64_t time_mult, time_shift, time_zero; + if (!o || !o.map("time_mult", time_mult) || + !o.map("time_shift", time_shift) || !o.map("time_zero", time_zero)) + return false; + + tsc_conversion = std::make_unique( + static_cast(time_mult), static_cast(time_shift), + static_cast(time_zero)); + + return true; +} + +bool fromJSON(const json::Value &value, TraceIntelPTGetStateResponse &packet, + json::Path path) { + ObjectMapper o(value, path); + if (!o || !fromJSON(value, (TraceGetStateResponse &)packet, path)) + return false; + + const Object &obj = *(value.getAsObject()); + if (const json::Value *counters = obj.get("counters")) { + json::Path subpath = path.field("counters"); + ObjectMapper ocounters(*counters, subpath); + if (!ocounters || !ocounters.mapOptional("tsc-perf-zero-conversion", + packet.tsc_conversion)) + return false; + } + return true; +} + +json::Value toJSON(const TraceIntelPTGetStateResponse &packet) { + json::Value base = toJSON((const TraceGetStateResponse &)packet); + + if (packet.tsc_conversion) { + std::vector counters{}; + base.getAsObject()->try_emplace( + "counters", json::Object{{"tsc-perf-zero-conversion", + packet.tsc_conversion->toJSON()}}); + } + + return base; +} + } // namespace lldb_private diff --git a/lldb/unittests/Process/Linux/PerfTests.cpp b/lldb/unittests/Process/Linux/PerfTests.cpp index 934d680e8c38..084b857b908f 100644 --- a/lldb/unittests/Process/Linux/PerfTests.cpp +++ b/lldb/unittests/Process/Linux/PerfTests.cpp @@ -58,8 +58,8 @@ TEST(Perf, TscConversion) { const int SLEEP_SECS = 1; std::chrono::nanoseconds SLEEP_NANOS{std::chrono::seconds(SLEEP_SECS)}; - Expected params = - FetchPerfTscConversionParameters(); + Expected params = + LoadPerfTscConversionParameters(); // Skip the test if the conversion parameters aren't available. if (!params) @@ -76,8 +76,7 @@ TEST(Perf, TscConversion) { GTEST_SKIP() << toString(tsc_after_sleep.takeError()); std::chrono::nanoseconds converted_tsc_diff = - params->ToWallTime(*tsc_after_sleep) - - params->ToWallTime(*tsc_before_sleep); + params->Convert(*tsc_after_sleep) - params->Convert(*tsc_before_sleep); std::chrono::microseconds acceptable_overhead(500); diff --git a/lldb/unittests/Utility/CMakeLists.txt b/lldb/unittests/Utility/CMakeLists.txt index 90e97f786a74..9a76b8a83099 100644 --- a/lldb/unittests/Utility/CMakeLists.txt +++ b/lldb/unittests/Utility/CMakeLists.txt @@ -38,6 +38,7 @@ add_lldb_unittest(UtilityTests TildeExpressionResolverTest.cpp TimeoutTest.cpp TimerTest.cpp + TraceGDBRemotePacketsTest.cpp UriParserTest.cpp UserIDResolverTest.cpp UUIDTest.cpp diff --git a/lldb/unittests/Utility/TraceGDBRemotePacketsTest.cpp b/lldb/unittests/Utility/TraceGDBRemotePacketsTest.cpp new file mode 100644 index 000000000000..94b6ec14ef84 --- /dev/null +++ b/lldb/unittests/Utility/TraceGDBRemotePacketsTest.cpp @@ -0,0 +1,101 @@ +//===-- TraceGDBRemotePacketsTest.cpp -------------------------------------===// +// +// 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 +// +//===----------------------------------------------------------------------===// + +#include "lldb/Utility/TraceIntelPTGDBRemotePackets.h" + +#include "gtest/gtest.h" + +#include + +using namespace lldb_private; +using namespace llvm; + +// Test serialization and deserialization of a non-empty +// TraceIntelPTGetStateResponse. +TEST(TraceGDBRemotePacketsTest, IntelPTGetStateResponse) { + // This test works as follows: + // 1. Create a non-empty TraceIntelPTGetStateResponse + // 2. Serialize to JSON + // 3. Deserialize the serialized JSON value + // 4. Ensure the original value and the deserialized value are equivalent + // + // Notes: + // - We intentionally set an integer value out of its signed range + // to ensure the serialization/deserialization isn't lossy since JSON + // operates on signed values + + // Choose arbitrary values for time_mult and time_shift + uint32_t test_time_mult = 1076264588; + uint16_t test_time_shift = 31; + // Intentionally set time_zero value out of the signed type's range. + uint64_t test_time_zero = + static_cast(std::numeric_limits::max()) + 1; + + // Create TraceIntelPTGetStateResponse. + TraceIntelPTGetStateResponse response; + response.tsc_conversion = std::make_unique( + test_time_mult, test_time_shift, test_time_zero); + + // Serialize then deserialize. + Expected deserialized_response = + json::parse( + llvm::formatv("{0}", toJSON(response)).str(), + "TraceIntelPTGetStateResponse"); + if (!deserialized_response) + FAIL() << toString(deserialized_response.takeError()); + + // Choose arbitrary TSC value to test the Convert function. + const uint64_t TSC = std::numeric_limits::max(); + // Expected nanosecond value pre calculated using the TSC to wall time + // conversion formula located in the time_zero section of + // https://man7.org/linux/man-pages/man2/perf_event_open.2.html + const uint64_t EXPECTED_NANOS = 9223372039007304983u; + + uint64_t pre_serialization_conversion = + response.tsc_conversion->Convert(TSC).count(); + uint64_t post_serialization_conversion = + deserialized_response->tsc_conversion->Convert(TSC).count(); + + // Check equality: + // Ensure that both the TraceGetStateResponse and TraceIntelPTGetStateResponse + // portions of the JSON representation are unchanged. + ASSERT_EQ(toJSON(response), toJSON(*deserialized_response)); + // Ensure the result of the Convert function is unchanged. + ASSERT_EQ(EXPECTED_NANOS, pre_serialization_conversion); + ASSERT_EQ(EXPECTED_NANOS, post_serialization_conversion); +} + +// Test serialization and deserialization of an empty +// TraceIntelPTGetStateResponse. +TEST(TraceGDBRemotePacketsTest, IntelPTGetStateResponseEmpty) { + // This test works as follows: + // 1. Create an empty TraceIntelPTGetStateResponse + // 2. Serialize to JSON + // 3. Deserialize the serialized JSON value + // 4. Ensure the original value and the deserialized value are equivalent + + // Create TraceIntelPTGetStateResponse. + TraceIntelPTGetStateResponse response; + + // Serialize then deserialize. + Expected deserialized_response = + json::parse( + llvm::formatv("{0}", toJSON(response)).str(), + "TraceIntelPTGetStateResponse"); + if (!deserialized_response) + FAIL() << toString(deserialized_response.takeError()); + + // Check equality: + // Ensure that both the TraceGetStateResponse and TraceIntelPTGetStateResponse + // portions of the JSON representation are unchanged. + ASSERT_EQ(toJSON(response), toJSON(*deserialized_response)); + // Ensure that the tsc_conversion's are nullptr. + ASSERT_EQ(response.tsc_conversion.get(), nullptr); + ASSERT_EQ(response.tsc_conversion.get(), + deserialized_response->tsc_conversion.get()); +}