[trace][intelpt] Support system-wide tracing [10] - Return warnings and tsc informati...
authorWalter Erquinigo <wallace@fb.com>
Wed, 18 May 2022 21:32:35 +0000 (14:32 -0700)
committerWalter Erquinigo <wallace@fb.com>
Wed, 15 Jun 2022 19:08:00 +0000 (12:08 -0700)
- Add a warnings field in the jLLDBGetState response, for warnings to be delivered to the client for troubleshooting. This removes the need to silently log lldb-server's llvm::Errors and not expose them easily to the user
- Simplify the tscPerfZeroConversion struct and schema. It used to extend a base abstract class, but I'm doubting that we'll ever add other conversion mechanisms because all modern kernels support perf zero. It is also the one who is supposed to work with the timestamps produced by the context switch trace, so expecting it is imperative.
- Force tsc collection for cpu tracing.
- Add a test checking that tscPerfZeroConversion is returned by the GetState request
- Add a pre-check for cpu tracing that makes sure that perf zero values are available.

Differential Revision: https://reviews.llvm.org/D125932

14 files changed:
lldb/docs/lldb-gdb-remote.txt
lldb/include/lldb/Utility/TraceGDBRemotePackets.h
lldb/include/lldb/Utility/TraceIntelPTGDBRemotePackets.h
lldb/source/Plugins/Process/Linux/IntelPTCollector.cpp
lldb/source/Plugins/Process/Linux/IntelPTCollector.h
lldb/source/Plugins/Process/Linux/IntelPTMultiCoreTrace.cpp
lldb/source/Plugins/Process/Linux/IntelPTMultiCoreTrace.h
lldb/source/Plugins/Process/Linux/IntelPTPerThreadProcessTrace.cpp
lldb/source/Plugins/Process/Linux/IntelPTPerThreadProcessTrace.h
lldb/source/Plugins/Process/Linux/IntelPTProcessTrace.h
lldb/source/Utility/TraceGDBRemotePackets.cpp
lldb/source/Utility/TraceIntelPTGDBRemotePackets.cpp
lldb/test/API/commands/trace/multiple-threads/TestTraceStartStopMultipleThreads.py
lldb/unittests/Process/Linux/PerfTests.cpp

index 1c9f29f..1996e3f 100644 (file)
@@ -495,11 +495,10 @@ read packet: OK/E<error code>;AAAAAAAAA
 //        },
 //      ]
 //    ],
-//    "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.
-//    }
+//    "warnings"?: [<string>],
+//        Non-fatal messages useful for troubleshooting.
+//
+//    ... other attributes specific to the given tracing technology
 //  }
 //
 // NOTES
@@ -520,24 +519,22 @@ read packet: OK/E<error code>;AAAAAAAAA
 //                              perf_event_open.
 //    - procfsCpuInfo: contents of the /proc/cpuinfo file.
 //
-//  Counter info kinds:
-//    tsc-perf-zero-conversion:
+//  Additional attributes:
+//    tscPerfZeroConversion:
 //
-//    This field allows converting Intel processor's TSC values to a wall time.
+//    This field allows converting Intel processor's TSC values to nanoseconds.
 //    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": <decimal integer>,
-//        "time_shift": <decimal integer>,
-//        "time_zero": <decimal integer>,
-//      }
+//    Schema for this field:
+//
+//    "tscPerfZeroConversion": {
+//      "timeMult": <decimal integer>,
+//      "timeShift": <decimal integer>,
+//      "timeSero": <decimal integer>,
 //    }
 //----------------------------------------------------------------------
 
index 163c1d3..d7b5a37 100644 (file)
@@ -129,35 +129,11 @@ bool fromJSON(const llvm::json::Value &value, TraceCoreState &packet,
 
 llvm::json::Value toJSON(const TraceCoreState &packet);
 
-/// Interface for different algorithms used to convert trace
-/// counters into different units.
-template <typename ToType> 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<TraceCounterConversion<std::chrono::nanoseconds>>;
-
 struct TraceGetStateResponse {
   std::vector<TraceThreadState> traced_threads;
   std::vector<TraceBinaryData> process_binary_data;
   llvm::Optional<std::vector<TraceCoreState>> cores;
+  std::vector<std::string> warnings;
 };
 
 bool fromJSON(const llvm::json::Value &value, TraceGetStateResponse &packet,
index abe67ff..6a1e96d 100644 (file)
@@ -67,16 +67,7 @@ llvm::json::Value toJSON(const TraceIntelPTStartRequest &packet);
 /// 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<std::chrono::nanoseconds> {
-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) {}
-
+struct LinuxPerfZeroTscConversion {
   /// 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
@@ -89,23 +80,22 @@ public:
   ///
   /// \return
   ///   Nanosecond wall time.
-  std::chrono::nanoseconds Convert(uint64_t raw_counter_value) override;
-
-  llvm::json::Value toJSON() override;
+  std::chrono::nanoseconds ToNanos(uint64_t tsc);
 
-private:
-  uint32_t m_time_mult;
-  uint16_t m_time_shift;
-  uint64_t m_time_zero;
+  uint32_t time_mult;
+  uint16_t time_shift;
+  uint64_t time_zero;
 };
 
 struct TraceIntelPTGetStateResponse : TraceGetStateResponse {
   /// The TSC to wall time conversion if it exists, otherwise \b nullptr.
-  TraceTscConversionUP tsc_conversion;
+  llvm::Optional<LinuxPerfZeroTscConversion> tsc_perf_zero_conversion;
 };
 
 bool fromJSON(const llvm::json::Value &value,
-              TraceTscConversionUP &tsc_conversion, llvm::json::Path path);
+              LinuxPerfZeroTscConversion &packet, llvm::json::Path path);
+
+llvm::json::Value toJSON(const LinuxPerfZeroTscConversion &packet);
 
 bool fromJSON(const llvm::json::Value &value,
               TraceIntelPTGetStateResponse &packet, llvm::json::Path path);
index 1016488..29ff87f 100644 (file)
@@ -33,14 +33,20 @@ using namespace process_linux;
 using namespace llvm;
 
 IntelPTCollector::IntelPTCollector(NativeProcessProtocol &process)
-    : m_process(process) {
-  if (Expected<LinuxPerfZeroTscConversion> tsc_conversion =
-          LoadPerfTscConversionParameters())
-    m_tsc_conversion =
-        std::make_unique<LinuxPerfZeroTscConversion>(*tsc_conversion);
-  else
-    LLDB_LOG_ERROR(GetLog(POSIXLog::Trace), tsc_conversion.takeError(),
-                   "unable to load TSC to wall time conversion: {0}");
+    : m_process(process) {}
+
+llvm::Expected<LinuxPerfZeroTscConversion &>
+IntelPTCollector::FetchPerfTscConversionParameters() {
+  if (!m_cached_tsc_conversion) {
+    if (Expected<LinuxPerfZeroTscConversion> tsc_conversion =
+            LoadPerfTscConversionParameters())
+      m_cached_tsc_conversion = std::move(*tsc_conversion);
+    else
+      return createStringError(inconvertibleErrorCode(),
+                               "Unable to load TSC to wall time conversion: %s",
+                               toString(tsc_conversion.takeError()).c_str());
+  }
+  return *m_cached_tsc_conversion;
 }
 
 Error IntelPTCollector::TraceStop(lldb::tid_t tid) {
@@ -74,8 +80,20 @@ Error IntelPTCollector::TraceStart(const TraceIntelPTStartRequest &request) {
         return createStringError(
             inconvertibleErrorCode(),
             "Threads currently traced. Stop tracing them first.");
+      // CPU tracing is useless if we can't convert tsc to nanos.
+      Expected<LinuxPerfZeroTscConversion &> tsc_conversion =
+          FetchPerfTscConversionParameters();
+      if (!tsc_conversion)
+        return tsc_conversion.takeError();
+
+      // We force the enabledment of TSCs, which is needed for correlating the
+      // cpu traces.
+      TraceIntelPTStartRequest effective_request = request;
+      effective_request.enable_tsc = true;
+
       if (Expected<IntelPTProcessTraceUP> trace =
-              IntelPTMultiCoreTrace::StartOnAllCores(request, m_process)) {
+              IntelPTMultiCoreTrace::StartOnAllCores(effective_request,
+                                                     m_process)) {
         m_process_trace_up = std::move(*trace);
         return Error::success();
       } else {
@@ -146,7 +164,7 @@ Expected<json::Value> IntelPTCollector::GetState() {
   if (!cpu_info)
     return cpu_info.takeError();
 
-  TraceGetStateResponse state;
+  TraceIntelPTGetStateResponse state;
   if (m_process_trace_up)
     state = m_process_trace_up->GetState();
 
@@ -159,6 +177,12 @@ Expected<json::Value> IntelPTCollector::GetState() {
                                         {{IntelPTDataKinds::kTraceBuffer,
                                           thread_trace.GetTraceBufferSize()}}});
       });
+
+  if (Expected<LinuxPerfZeroTscConversion &> tsc_conversion =
+          FetchPerfTscConversionParameters())
+    state.tsc_perf_zero_conversion = *tsc_conversion;
+  else
+    state.warnings.push_back(toString(tsc_conversion.takeError()));
   return toJSON(state);
 }
 
index 19f8d7b..5777ac8 100644 (file)
@@ -73,6 +73,12 @@ private:
   llvm::Error TraceStart(lldb::tid_t tid,
                          const TraceIntelPTStartRequest &request);
 
+  /// \return
+  ///   The conversion object between TSC and wall time. It caches the result
+  ///   upon success.
+  llvm::Expected<LinuxPerfZeroTscConversion &>
+  FetchPerfTscConversionParameters();
+
   /// The target process.
   NativeProcessProtocol &m_process;
   /// Threads traced due to "thread tracing"
@@ -82,8 +88,8 @@ private:
   /// It might be \b nullptr.
   IntelPTProcessTraceUP m_process_trace_up;
 
-  /// TSC to wall time conversion.
-  TraceTscConversionUP m_tsc_conversion;
+  /// Cached TSC to and from wall time conversion.
+  llvm::Optional<LinuxPerfZeroTscConversion> m_cached_tsc_conversion;
 };
 
 } // namespace process_linux
index ce0bb48..ea58cf6 100644 (file)
@@ -153,8 +153,8 @@ void IntelPTMultiCoreTrace::ProcessWillResume() {
   });
 }
 
-TraceGetStateResponse IntelPTMultiCoreTrace::GetState() {
-  TraceGetStateResponse state;
+TraceIntelPTGetStateResponse IntelPTMultiCoreTrace::GetState() {
+  TraceIntelPTGetStateResponse state;
 
   for (size_t i = 0; m_process.GetThreadAtIndex(i); i++)
     state.traced_threads.push_back(
index 5c73067..30fb5de 100644 (file)
@@ -72,7 +72,7 @@ public:
 
   void ProcessWillResume() override;
 
-  TraceGetStateResponse GetState() override;
+  TraceIntelPTGetStateResponse GetState() override;
 
   bool TracesThread(lldb::tid_t tid) const override;
 
index 48761d6..1545b21 100644 (file)
@@ -35,8 +35,8 @@ Error IntelPTPerThreadProcessTrace::TraceStart(lldb::tid_t tid) {
   return m_thread_traces.TraceStart(tid, m_tracing_params);
 }
 
-TraceGetStateResponse IntelPTPerThreadProcessTrace::GetState() {
-  TraceGetStateResponse state;
+TraceIntelPTGetStateResponse IntelPTPerThreadProcessTrace::GetState() {
+  TraceIntelPTGetStateResponse state;
   m_thread_traces.ForEachThread(
       [&](lldb::tid_t tid, const IntelPTSingleBufferTrace &thread_trace) {
         state.traced_threads.push_back({tid,
index d850dbd..f1ae8ef 100644 (file)
@@ -42,7 +42,7 @@ public:
 
   llvm::Error TraceStop(lldb::tid_t tid) override;
 
-  TraceGetStateResponse GetState() override;
+  TraceIntelPTGetStateResponse GetState() override;
 
   llvm::Expected<std::vector<uint8_t>>
   GetBinaryData(const TraceGetBinaryDataRequest &request) override;
index c893866..06fc346 100644 (file)
@@ -26,7 +26,7 @@ public:
   virtual void ProcessWillResume() {}
 
   /// Construct a minimal jLLDBTraceGetState response for this process trace.
-  virtual TraceGetStateResponse GetState() = 0;
+  virtual TraceIntelPTGetStateResponse GetState() = 0;
 
   virtual bool TracesThread(lldb::tid_t tid) const = 0;
 
index 9f92da3..313de1a 100644 (file)
@@ -100,13 +100,15 @@ bool fromJSON(const json::Value &value, TraceGetStateResponse &packet,
   ObjectMapper o(value, path);
   return o && o.map("tracedThreads", packet.traced_threads) &&
          o.map("processBinaryData", packet.process_binary_data) &&
-         o.map("cores", packet.cores);
+         o.map("cores", packet.cores) &&
+         o.mapOptional("warnings", packet.warnings);
 }
 
 json::Value toJSON(const TraceGetStateResponse &packet) {
   return json::Value(Object{{"tracedThreads", packet.traced_threads},
                             {"processBinaryData", packet.process_binary_data},
-                            {"cores", packet.cores}});
+                            {"cores", packet.cores},
+                            {"warnings", packet.warnings}});
 }
 
 bool fromJSON(const json::Value &value, TraceCoreState &packet,
index f4658f3..505d726 100644 (file)
@@ -50,67 +50,47 @@ 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)};
+std::chrono::nanoseconds LinuxPerfZeroTscConversion::ToNanos(uint64_t tsc) {
+  uint64_t quot = tsc >> time_shift;
+  uint64_t rem_flag = (((uint64_t)1 << time_shift) - 1);
+  uint64_t rem = tsc & rem_flag;
+  return std::chrono::nanoseconds{time_zero + quot * time_mult +
+                                  ((rem * time_mult) >> time_shift)};
 }
 
-json::Value LinuxPerfZeroTscConversion::toJSON() {
+json::Value toJSON(const LinuxPerfZeroTscConversion &packet) {
   return json::Value(json::Object{
-      {"kind", "tsc-perf-zero-conversion"},
-      {"time_mult", m_time_mult},
-      {"time_shift", m_time_shift},
-      {"time_zero", m_time_zero},
+      {"kind", "tscPerfZeroConversion"},
+      {"timeMult", packet.time_mult},
+      {"timeShift", packet.time_shift},
+      {"timeZero", packet.time_zero},
   });
 }
 
-bool fromJSON(const json::Value &value, TraceTscConversionUP &tsc_conversion,
+bool fromJSON(const json::Value &value, LinuxPerfZeroTscConversion &packet,
               json::Path path) {
   ObjectMapper o(value, path);
-
   uint64_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))
+  if (!o || !o.map("timeMult", time_mult) || !o.map("timeShift", time_shift) ||
+      !o.map("timeZero", time_zero))
     return false;
-
-  tsc_conversion = std::make_unique<LinuxPerfZeroTscConversion>(
-      static_cast<uint32_t>(time_mult), static_cast<uint16_t>(time_shift),
-      time_zero);
-
+  packet.time_mult = time_mult;
+  packet.time_zero = time_zero;
+  packet.time_shift = time_shift;
   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;
+  return o && fromJSON(value, (TraceGetStateResponse &)packet, path) &&
+         o.map("tscPerfZeroConversion", packet.tsc_perf_zero_conversion);
 }
 
 json::Value toJSON(const TraceIntelPTGetStateResponse &packet) {
   json::Value base = toJSON((const TraceGetStateResponse &)packet);
-
-  if (packet.tsc_conversion) {
-    std::vector<json::Value> counters{};
-    base.getAsObject()->try_emplace(
-        "counters", json::Object{{"tsc-perf-zero-conversion",
-                                  packet.tsc_conversion->toJSON()}});
-  }
-
+  base.getAsObject()->insert(
+      {"tscPerfZeroConversion", packet.tsc_perf_zero_conversion});
   return base;
 }
 
index 859f486..2df666a 100644 (file)
@@ -200,7 +200,8 @@ class TestTraceStartStopMultipleThreads(TraceIntelPTTestCaseBase):
         self.expect("b 19")
         self.expect("c")
 
-        # We will assert that the trace state will contain valid context switch and trace buffer entries
+        # We will assert that the trace state will contain valid context switch and trace buffer entries.
+        # Besides that, we need to get tsc-to-nanos conversion information.
 
         # We first parse the json response from the custom packet
         self.runCmd("""process plugin packet send 'jLLDBTraceGetState:{"type":"intel-pt"}]'""")
@@ -213,6 +214,7 @@ class TestTraceStartStopMultipleThreads(TraceIntelPTTestCaseBase):
 
         self.assertTrue(output is not None)
         self.assertIn("cores", output)
+        self.assertIn("tscPerfZeroConversion", output)
         found_non_empty_context_switch = False
 
         for core in output["cores"]:
index b5b6625..39bbc43 100644 (file)
@@ -77,7 +77,7 @@ TEST(Perf, TscConversion) {
     GTEST_SKIP() << toString(tsc_after_sleep.takeError());
 
   std::chrono::nanoseconds converted_tsc_diff =
-      params->Convert(*tsc_after_sleep) - params->Convert(*tsc_before_sleep);
+      params->ToNanos(*tsc_after_sleep) - params->ToNanos(*tsc_before_sleep);
 
   std::chrono::microseconds acceptable_overhead(500);