[trace][intel pt] Create a CPU change event and expose it in the dumper

Thanks to fredzhou@fb.com for coming up with this feature.

When tracing in per-cpu mode, we have information of in which cpu we are execution each instruction, which comes from the context switch trace. This diff makes this information available as a `cpu changed event`, which an additional accessor in the cursor `GetCPU()`. As cpu changes are very infrequent, any consumer should listen to cpu change events instead of querying the actual cpu of a trace item. Once a cpu change event is seen, the consumer can invoke GetCPU() to get that information. Also, it's possible to invoke GetCPU() on an arbitrary instruction item, which will return the last cpu seen. However, this call is O(logn) and should be used sparingly.

Manually tested with a sample program that starts on cpu 52, then goes to 18, and then goes back to 52.

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

lldb/include/lldb/Target/TraceCursor.h

@@ -266,6 +266,16 @@ class TraceCursor {
   ///    The value of the counter or \b llvm::None if not available.
   virtual llvm::Optional<uint64_t>
   GetCounter(lldb::TraceCounter counter_type) const = 0;
+
+  /// Get the CPU associated with the current trace item.
+  ///
+  /// This call might not be O(1), so it's suggested to invoke this method
+  /// whenever a cpu change event is fired.
+  ///
+  /// \return
+  ///    The requested CPU id, or \a llvm::None if this information is
+  ///    not available for the current item.
+  virtual llvm::Optional<lldb::cpu_id_t> GetCPU() const = 0;
   /// \}
 
 protected:

lldb/include/lldb/Target/TraceDumper.h

@@ -66,6 +66,7 @@ class TraceDumper {
     llvm::Optional<lldb::TraceEvent> event;
     llvm::Optional<SymbolInfo> symbol_info;
     llvm::Optional<SymbolInfo> prev_symbol_info;
+    llvm::Optional<lldb::cpu_id_t> cpu_id;
   };
 
   /// Interface used to abstract away the format in which the instruction

lldb/include/lldb/lldb-enumerations.h

@@ -1163,12 +1163,15 @@ enum TraceCounter {
   eTraceCounterTSC = 0,
 };
 
-// Events that might happen during a trace session.
+/// Events that might happen during a trace session.
 enum TraceEvent {
-  // Tracing was disabled for some time due to a software trigger
+  /// Tracing was disabled for some time due to a software trigger
   eTraceEventDisabledSW,
-  // Tracing was disable for some time due to a hardware trigger
+  /// Tracing was disable for some time due to a hardware trigger
   eTraceEventDisabledHW,
+  /// Event due to CPU change for a thread. This event is also fired when
+  /// suddenly it's not possible to identify the cpu of a given thread.
+  eTraceEventCPUChanged,
 };
 
 // Enum used to identify which kind of item a \a TraceCursor is pointing at

lldb/source/Plugins/Trace/intel-pt/DecodedThread.cpp

@@ -63,11 +63,28 @@ DecodedThread::CreateNewTraceItem(lldb::TraceItemKind kind) {
 
 void DecodedThread::NotifyTsc(uint64_t tsc) {
   if (!m_last_tsc || *m_last_tsc != tsc) {
-    m_instruction_timestamps.emplace(m_item_kinds.size(), tsc);
+    m_timestamps.emplace(m_item_kinds.size(), tsc);
     m_last_tsc = tsc;
   }
 }
 
+void DecodedThread::NotifyCPU(lldb::cpu_id_t cpu_id) {
+  if (!m_last_cpu || *m_last_cpu != cpu_id) {
+    m_cpus.emplace(m_item_kinds.size(), cpu_id);
+    m_last_cpu = cpu_id;
+    AppendEvent(lldb::eTraceEventCPUChanged);
+  }
+}
+
+Optional<lldb::cpu_id_t>
+DecodedThread::GetCPUByIndex(uint64_t insn_index) const {
+  // Could possibly optimize the search
+  auto it = m_cpus.upper_bound(insn_index);
+  if (it == m_cpus.begin())
+    return None;
+  return prev(it)->second;
+}
+
 void DecodedThread::AppendEvent(lldb::TraceEvent event) {
   CreateNewTraceItem(lldb::eTraceItemKindEvent).event = event;
   m_events_stats.RecordEvent(event);
@@ -136,8 +153,8 @@ Optional<DecodedThread::TscRange> DecodedThread::CalculateTscRange(
       return candidate_range;
   }
   // Now we do a more expensive lookup
-  auto it = m_instruction_timestamps.upper_bound(insn_index);
-  if (it == m_instruction_timestamps.begin())
+  auto it = m_timestamps.upper_bound(insn_index);
+  if (it == m_timestamps.begin())
     return None;
 
   return TscRange(--it, *this);
@@ -160,15 +177,16 @@ lldb::TraceCursorUP DecodedThread::CreateNewCursor() {
 size_t DecodedThread::CalculateApproximateMemoryUsage() const {
   return sizeof(TraceItemStorage) * m_item_data.size() +
          sizeof(uint8_t) * m_item_kinds.size() +
-         (sizeof(size_t) + sizeof(uint64_t)) * m_instruction_timestamps.size();
+         (sizeof(size_t) + sizeof(uint64_t)) * m_timestamps.size() +
+         (sizeof(size_t) + sizeof(lldb::cpu_id_t)) * m_cpus.size();
 }
 
 DecodedThread::TscRange::TscRange(std::map<size_t, uint64_t>::const_iterator it,
                                   const DecodedThread &decoded_thread)
     : m_it(it), m_decoded_thread(&decoded_thread) {
   auto next_it = m_it;
   ++next_it;
-  m_end_index = (next_it == m_decoded_thread->m_instruction_timestamps.end())
+  m_end_index = (next_it == m_decoded_thread->m_timestamps.end())
                     ? std::numeric_limits<uint64_t>::max()
                     : next_it->first - 1;
 }
@@ -191,13 +209,13 @@ bool DecodedThread::TscRange::InRange(size_t insn_index) const {
 Optional<DecodedThread::TscRange> DecodedThread::TscRange::Next() const {
   auto next_it = m_it;
   ++next_it;
-  if (next_it == m_decoded_thread->m_instruction_timestamps.end())
+  if (next_it == m_decoded_thread->m_timestamps.end())
     return None;
   return TscRange(next_it, *m_decoded_thread);
 }
 
 Optional<DecodedThread::TscRange> DecodedThread::TscRange::Prev() const {
-  if (m_it == m_decoded_thread->m_instruction_timestamps.begin())
+  if (m_it == m_decoded_thread->m_timestamps.begin())
     return None;
   auto prev_it = m_it;
   --prev_it;

lldb/source/Plugins/Trace/intel-pt/DecodedThread.h

@@ -168,6 +168,15 @@ class DecodedThread : public std::enable_shared_from_this<DecodedThread> {
   ///   The underlying event type for the given trace item index.
   lldb::TraceEvent GetEventByIndex(int item_index) const;
 
+  /// Get the most recent CPU id before or at the given trace item index.
+  ///
+  /// \param[in] item_index
+  ///   The trace item index to compare with.
+  ///
+  /// \return
+  ///   The requested cpu id, or \a llvm::None if not available.
+  llvm::Optional<lldb::cpu_id_t> GetCPUByIndex(uint64_t item_index) const;
+
   /// \return
   ///     The load address of the instruction at the given index.
   lldb::addr_t GetInstructionLoadAddress(size_t item_index) const;
@@ -204,8 +213,13 @@ class DecodedThread : public std::enable_shared_from_this<DecodedThread> {
   lldb::ThreadSP GetThread();
 
   /// Notify this object that a new tsc has been seen.
+  /// If this a new TSC, an event will be created.
   void NotifyTsc(uint64_t tsc);
 
+  /// Notify this object that a CPU has been seen.
+  /// If this a new CPU, an event will be created.
+  void NotifyCPU(lldb::cpu_id_t cpu_id);
+
   /// Append a decoding error.
   void AppendError(const IntelPTError &error);
 
@@ -254,10 +268,17 @@ class DecodedThread : public std::enable_shared_from_this<DecodedThread> {
   /// are sporadic and we can think of them as ranges. If TSCs are present in
   /// the trace, all instructions will have an associated TSC, including the
   /// first one. Otherwise, this map will be empty.
-  std::map<uint64_t, uint64_t> m_instruction_timestamps;
+  std::map<uint64_t, uint64_t> m_timestamps;
   /// This is the chronologically last TSC that has been added.
   llvm::Optional<uint64_t> m_last_tsc = llvm::None;
 
+  // The cpu information is stored as a map. It maps `instruction index -> CPU`
+  // A CPU is associated with the next instructions that follow until the next
+  // cpu is seen.
+  std::map<uint64_t, lldb::cpu_id_t> m_cpus;
+  /// This is the chronologically last CPU ID.
+  llvm::Optional<uint64_t> m_last_cpu = llvm::None;
+
   /// Statistics of all tracing events.
   EventsStats m_events_stats;
   /// Statistics of libipt errors when decoding TSCs.

lldb/source/Plugins/Trace/intel-pt/LibiptDecoder.cpp

@@ -285,6 +285,8 @@ Error lldb_private::trace_intel_pt::DecodeSystemWideTraceForThread(
   for (size_t i = 0; i < executions.size(); i++) {
     const IntelPTThreadContinousExecution &execution = executions[i];
 
+    decoded_thread.NotifyCPU(execution.thread_execution.cpu_id);
+
     auto variant = execution.thread_execution.variant;
     // If we haven't seen a PSB yet, then it's fine not to show errors
     if (has_seen_psbs) {

lldb/source/Plugins/Trace/intel-pt/TraceCursorIntelPT.cpp

@@ -84,6 +84,10 @@ TraceCursorIntelPT::GetCounter(lldb::TraceCounter counter_type) const {
   }
 }
 
+Optional<lldb::cpu_id_t> TraceCursorIntelPT::GetCPU() const {
+  return m_decoded_thread_sp->GetCPUByIndex(m_pos);
+}
+
 lldb::TraceEvent TraceCursorIntelPT::GetEventType() const {
   return m_decoded_thread_sp->GetEventByIndex(m_pos);
 }

lldb/source/Plugins/Trace/intel-pt/TraceCursorIntelPT.h

@@ -34,6 +34,8 @@ class TraceCursorIntelPT : public TraceCursor {
 
   lldb::TraceEvent GetEventType() const override;
 
+  llvm::Optional<lldb::cpu_id_t> GetCPU() const override;
+
   lldb::TraceItemKind GetItemKind() const override;
 
   bool GoToId(lldb::user_id_t id) override;

lldb/source/Target/TraceCursor.cpp

@@ -48,5 +48,7 @@ const char *TraceCursor::EventKindToString(lldb::TraceEvent event_kind) {
     return "hardware disabled tracing";
   case lldb::eTraceEventDisabledSW:
     return "software disabled tracing";
+  case lldb::eTraceEventCPUChanged:
+    return "CPU core changed";
   }
 }

lldb/source/Target/TraceDumper.cpp

@@ -129,18 +129,16 @@ class OutputWriterCLI : public TraceDumper::OutputWriter {
     m_s.Format("    {0}: ", item.id);
 
     if (m_options.show_tsc) {
-      m_s << "[tsc=";
-
-      if (item.tsc)
-        m_s.Format("{0}", *item.tsc);
-      else
-        m_s << "unavailable";
-
-      m_s << "] ";
+      m_s.Format("[tsc={0}] ",
+                 item.tsc ? std::to_string(*item.tsc) : "unavailable");
     }
 
     if (item.event) {
       m_s << "(event) " << TraceCursor::EventKindToString(*item.event);
+      if (*item.event == eTraceEventCPUChanged) {
+        m_s.Format(" [new CPU={0}]",
+                   item.cpu_id ? std::to_string(*item.cpu_id) : "unavailable");
+      }
     } else if (item.error) {
       m_s << "(error) " << *item.error;
     } else {
@@ -172,14 +170,16 @@ class OutputWriterJSON : public TraceDumper::OutputWriter {
   /* schema:
     error_message: string
     | {
+      "event": string,
       "id": decimal,
       "tsc"?: string decimal,
-      "event": string
+      "cpuId"? decimal,
     } | {
+      "error": string,
       "id": decimal,
       "tsc"?: string decimal,
-      "error": string,
     | {
+      "loadAddress": string decimal,
       "id": decimal,
       "tsc"?: string decimal,
       "module"?: string,
@@ -202,6 +202,11 @@ class OutputWriterJSON : public TraceDumper::OutputWriter {
 
   void DumpEvent(const TraceDumper::TraceItem &item) {
     m_j.attribute("event", TraceCursor::EventKindToString(*item.event));
+<<<<<<< HEAD
+=======
+    if (item.event == eTraceEventCPUChanged)
+      m_j.attribute("cpuId", item.cpu_id);
+>>>>>>> ccb96b741a18 ([trace][intel pt] Create a CPU change event and expose it in the dumper)
   }
 
   void DumpInstruction(const TraceDumper::TraceItem &item) {
@@ -211,12 +216,18 @@ class OutputWriterJSON : public TraceDumper::OutputWriter {
       m_j.attribute(
           "symbol",
           ToOptionalString(item.symbol_info->sc.GetFunctionName().AsCString()));
+<<<<<<< HEAD
 
       if (item.symbol_info->instruction) {
         m_j.attribute("mnemonic",
                       ToOptionalString(item.symbol_info->instruction->GetMnemonic(
                           &item.symbol_info->exe_ctx)));
       }
+=======
+      m_j.attribute("mnemonic",
+                    ToOptionalString(item.symbol_info->instruction->GetMnemonic(
+                        &item.symbol_info->exe_ctx)));
+>>>>>>> ccb96b741a18 ([trace][intel pt] Create a CPU change event and expose it in the dumper)
 
       if (IsLineEntryValid(item.symbol_info->sc.line_entry)) {
         m_j.attribute(
@@ -239,6 +250,7 @@ class OutputWriterJSON : public TraceDumper::OutputWriter {
 
       if (item.event) {
         DumpEvent(item);
+<<<<<<< HEAD
         return;
       }
 
@@ -249,6 +261,13 @@ class OutputWriterJSON : public TraceDumper::OutputWriter {
 
       // we know we are seeing an actual instruction
       DumpInstruction(item);
+=======
+      } else if (item.error) {
+        m_j.attribute("error", *item.error);
+      } else {
+        DumpInstruction(item);
+      }
+>>>>>>> ccb96b741a18 ([trace][intel pt] Create a CPU change event and expose it in the dumper)
     });
   }
 
@@ -369,6 +388,8 @@ Optional<lldb::user_id_t> TraceDumper::DumpInstructions(size_t count) {
       if (!m_options.show_events)
         continue;
       item.event = m_cursor_up->GetEventType();
+      if (*item.event == eTraceEventCPUChanged)
+        item.cpu_id = m_cursor_up->GetCPU();
     } else if (m_cursor_up->IsError()) {
       item.error = m_cursor_up->GetError();
     } else {

lldb/test/API/commands/trace/TestTraceEvents.py

@@ -6,6 +6,23 @@
 
 class TestTraceEvents(TraceIntelPTTestCaseBase):
 
+    @testSBAPIAndCommands
+    def testCPUEvents(self):
+      trace_description_file_path = os.path.join(self.getSourceDir(), "intelpt-multi-core-trace", "trace_missing_threads.json")
+      self.traceLoad(traceDescriptionFilePath=trace_description_file_path, substrs=["intel-pt"])
+
+      self.expect("thread trace dump instructions 3 -e --forward -c 5",
+        substrs=['''thread #3: tid = 3497496
+    0: (event) CPU core changed [new CPU=51]
+  m.out`foo() + 65 at multi_thread.cpp:12:21'''])
+
+      self.expect("thread trace dump instructions 3 -e --forward -c 5 -J",
+        substrs=['''{
+    "id": 0,
+    "event": "CPU core changed",
+    "cpuId": 51
+  }'''])
+
     @testSBAPIAndCommands
     def testPauseEvents(self):
       '''