[trace][intel pt] Handle better tsc in the decoder

[wallace]

Summary

A problem that I introduced in the decoder is that I was considering TSC decoding
errors as actual instruction errors, which mean that the trace has a gap. This is
wrong because a TSC decoding error doesn't mean that there's a gap in the trace.
Instead, now I'm just counting how many of these errors happened and I'm using
the dump info command to check for this number.

Besides that, I refactored the decoder a little bit to make it simpler, more
readable, and to handle TSCs in a cleaner way.

[jj10306]

The changes to the decoder look sound, just left two questions related to it and a couple other nits.

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

120

The parameter is unused, is there a reason to keep this or should it be removed since the method is simply incrementing the tsc error count?

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

230

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

106

see comment on DecodeInstructions

130

see comment on DecodeInstructions

138

see comment on DecodeInstructions

159

This function isn't taking ownership/storing this SP so consider just passing a reference here and in the AppendError, AppendInstruction and RefreshTsc funcs

192

This makes sense to not include the errors if you are at the end of the stream, I have two questions related to this:

1. Prior to this change, was there always at least one error in the instructions from the eos that occurs when tracing? My understanding is that eos as a result of pt_insn_next is an indication that you are at the end of the buffer and thus the decoding is done, is that correct?
2. When a pt_insn_next call returns pte_eos, does that gurantee that the next call to FindNextSynchronizationPoint will return pte_eos as well? If so, could this code be changed to immediately return if pte_eos is returned here since currently it will break from the inner loop, go back to the top of the outer loop, call FindNextSynchronizationPoint which will ultimately return pte_eos which causes a break from the outer loop and finally the implicit return from the function? Seems like we could fail fast by immediately returning from the function here if pt_insn_next returns pte_eos.

[jj10306]

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

245–247

nit: When I initially read "Report" it made me think that the last TSC was being logged or reported to something else. Since all this method does is record the tsc of the last instruction, potentially "Record" is a better name. This is purely my opinion so feel free to keep it as is or change it (:

[wallace]

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

120

good catch. I initially wanted to show the list of actual errors happening. I'll do that now

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

245–247

good idea

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

159

good idea :)

192

Prior to this change, was there always at least one error in the instructions from the eos that occurs when tracing?

Not really. In line 128 of the original code we had:

if (errcode == -pte_eos)
      break;

which broke the instruction decoding flow as soon as an eos is seen.

My understanding is that eos as a result of pt_insn_next is an indication that you are at the end of the buffer and thus the decoding is done, is that correct?

yes, that is true. The decoding will simply finish.

When a pt_insn_next call returns pte_eos, does that gurantee that the next call to FindNextSynchronizationPoint will return pte_eos as well?

yes

If so, could this code be changed to immediately return if pte_eos is returned here since currently it will break from the inner loop, go back to the top of the outer loop, call FindNextSynchronizationPoint which will ultimately return pte_eos which causes a break from the outer loop and finally the implicit return from the function? Seems like we could fail fast by immediately returning from the function here if pt_insn_next returns pte_eos.

In this case I don't want to fail fast and instead just break the innermost loop because the code is a little bit big and putting returns in the middle might cause bugs in the future when someone modifies this function. Let's suppose that you add some code right after the big loop thinking that the new code will always be reached. In this case, the early return might unexpectedly finish the execution of the function without reaching your code and you might not easily notice that.

[wallace]

• Address comments
• Also now using Format instead of Printf, which more idiomatic in this repo.

[jj10306]

Looks good

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

248

Do you need .get() or does just *decoded_thread work?

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

private:
     /// The iterator pointing to the beginning of the range.
     std::map<size_t, uint64_t>::const_iterator m_it;
     /// The largest instruction index that has this TSC.
     size_t m_end_index;
 
     const DecodedThread *m_decoded_thread;
   };
 
+  // Struct holding counts for libipts errors;
+  struct LibiptErrors {
+    // libipt error -> count
+    llvm::DenseMap<const char *, int> libipt_errors;
+    int total_count = 0;
+
+    void RecordError(int libipt_error_code);
+  };
+
   DecodedThread(lldb::ThreadSP thread_sp);
 
   /// Utility constructor that initializes the trace with a provided error.
   DecodedThread(lldb::ThreadSP thread_sp, llvm::Error &&err);
 
   /// Append a successfully decoded instruction.
   void AppendInstruction(const pt_insn &instruction);
 
public:
 
   /// Get the error associated with a given instruction index.
   ///
   /// \return
   ///   The error message of \b nullptr if the given index
   ///   points to a valid instruction.
   const char *GetErrorByInstructionIndex(size_t ins_idx);
 
+  /// Append a decoding error with a corresponding TSC.
+  void AppendError(llvm::Error &&error, uint64_t TSC);
+
+  /// Record an error decoding a TSC timestamp.
+  ///
+  /// See \a GetTscErrors() for more documentation.
+  ///
+  /// \param[in] libipt_error_code
+  ///   An error returned by the libipt library.
+  void RecordTscError(int libipt_error_code);
+
   /// Get a new cursor for the decoded thread.
   lldb::TraceCursorUP GetCursor();
 
   /// Set the size in bytes of the corresponding Intel PT raw trace.
   void SetRawTraceSize(size_t size);
 
   /// Get the size in bytes of the corresponding Intel PT raw trace.
   ///
   /// \return
   ///   The size of the trace, or \b llvm::None if not available.
   llvm::Optional<size_t> GetRawTraceSize() const;
 
+  /// Return the number of TSC decoding errors that happened. A TSC error
+  /// is not a fatal error and doesn't create gaps in the trace. Instead
+  /// we only keep track of them as a statistic.
+  ///
+  /// \return
+  ///   The number of TSC decoding errors.
+  const LibiptErrors &GetTscErrors() const;
+
   /// The approximate size in bytes used by this instance,
   /// including all the already decoded instructions.
   size_t CalculateApproximateMemoryUsage() const;
 
   lldb::ThreadSP GetThread();
 
 private:
+  /// Notify this class that the last added instruction or error has
+  /// an associated TSC.
+  void RecordTscForLastInstruction(uint64_t tsc);
+
   /// When adding new members to this class, make sure
   /// to update \a CalculateApproximateMemoryUsage() accordingly.
   lldb::ThreadSP m_thread_sp;
   /// The low level storage of all instruction addresses. Each instruction has
   /// an index in this vector and it will be used in other parts of the code.
   std::vector<IntelPTInstruction> m_instructions;
   /// This map contains the TSCs of the decoded instructions. It maps
   /// `instruction index -> TSC`, where `instruction index` is the first index
   /// at which the mapped TSC appears. We use this representation because TSCs
   /// 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<size_t, uint64_t> m_instruction_timestamps;
   /// This is the chronologically last TSC that has been added.
   llvm::Optional<uint64_t> m_last_tsc = llvm::None;
   // This variables stores the messages of all the error instructions in the
   // trace. It maps `instruction index -> error message`.
   llvm::DenseMap<uint64_t, std::string> m_errors;
   /// The size in bytes of the raw buffer before decoding. It might be None if
   /// the decoding failed.
   llvm::Optional<size_t> m_raw_trace_size;
+  /// All occurrences of libipt errors when decoding TSCs.
+  LibiptErrors m_tsc_errors;
 };
 
 using DecodedThreadSP = std::shared_ptr<DecodedThread>;
 
 } // namespace trace_intel_pt
 } // namespace lldb_private
 
 #endif // LLDB_SOURCE_PLUGINS_TRACE_INTEL_PT_DECODEDTHREAD_H

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

default:
     break;
   }
 
   return mask;
 }
 
 ThreadSP DecodedThread::GetThread() { return m_thread_sp; }
 
-void DecodedThread::AppendInstruction(const pt_insn &insn) {
-  m_instructions.emplace_back(insn);
-}
-
-void DecodedThread::AppendInstruction(const pt_insn &insn, uint64_t tsc) {
-  m_instructions.emplace_back(insn);
+void DecodedThread::RecordTscForLastInstruction(uint64_t tsc) {
   if (!m_last_tsc || *m_last_tsc != tsc) {
     // In case the first instructions are errors or did not have a TSC, we'll
     // get a first valid TSC not in position 0. We can safely force these error
     // instructions to use the first valid TSC, so that all the trace has TSCs.
     size_t start_index =
         m_instruction_timestamps.empty() ? 0 : m_instructions.size() - 1;
     m_instruction_timestamps.emplace(start_index, tsc);
     m_last_tsc = tsc;
   }
 }
 
+void DecodedThread::AppendInstruction(const pt_insn &insn) {
+  m_instructions.emplace_back(insn);
+}
+
+void DecodedThread::AppendInstruction(const pt_insn &insn, uint64_t tsc) {
+  AppendInstruction(insn);
+  RecordTscForLastInstruction(tsc);
+}
+
 void DecodedThread::AppendError(llvm::Error &&error) {
   m_errors.try_emplace(m_instructions.size(), toString(std::move(error)));
   m_instructions.emplace_back();
 }
 
+void DecodedThread::AppendError(llvm::Error &&error, uint64_t tsc) {
+  AppendError(std::move(error));
+  RecordTscForLastInstruction(tsc);
+}
+
+void DecodedThread::LibiptErrors::RecordError(int libipt_error_code) {
+  libipt_errors[pt_errstr(pt_errcode(libipt_error_code))]++;
+  total_count++;
+}
+
+void DecodedThread::RecordTscError(int libipt_error_code) {
+  m_tsc_errors.RecordError(libipt_error_code);
+}
+
+const DecodedThread::LibiptErrors &DecodedThread::GetTscErrors() const {
+  return m_tsc_errors;
+}
+
 ArrayRef<IntelPTInstruction> DecodedThread::GetInstructions() const {
   return makeArrayRef(m_instructions);
 }
 
 Optional<DecodedThread::TscRange>
 DecodedThread::CalculateTscRange(size_t insn_index) const {
   auto it = m_instruction_timestamps.upper_bound(insn_index);
   if (it == m_instruction_timestamps.begin())

 }
 
 Optional<DecodedThread::TscRange> DecodedThread::TscRange::Prev() {
   if (m_it == m_decoded_thread->m_instruction_timestamps.begin())
     return None;
   auto prev_it = m_it;
   --prev_it;
   return TscRange(prev_it, *m_decoded_thread);
-}
+}
 

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

while (errcode & pts_event_pending) {
     pt_event event;
     errcode = pt_insn_event(&decoder, &event, sizeof(event));
     if (errcode < 0)
       return errcode;
   }
   return 0;
 }
 
+// Simple struct used by the decoder to keep the state of the most
+// recent TSC and a flag indicating whether TSCs are enabled, not enabled
+// or we just don't yet.
+struct TscInfo {
+  uint64_t tsc = 0;
+  LazyBool has_tsc = eLazyBoolCalculate;
+
+  explicit operator bool() const { return has_tsc == eLazyBoolYes; }
+};
+
+/// Query the decoder for the most recent TSC timestamp and update
+/// tsc_info accordingly.
+void RefreshTscInfo(TscInfo &tsc_info, pt_insn_decoder &decoder,
+                    DecodedThread &decoded_thread) {
+  if (tsc_info.has_tsc == eLazyBoolNo)
+    return;
+
+  uint64_t new_tsc;
+  if (int tsc_error = pt_insn_time(&decoder, &new_tsc, nullptr, nullptr)) {
+    if (tsc_error == -pte_no_time) {
+      // We now know that the trace doesn't support TSC, so we won't try again.
+      // See
+      // https://github.com/intel/libipt/blob/master/doc/man/pt_qry_time.3.md
+      tsc_info.has_tsc = eLazyBoolNo;
+    } else {
+      // We don't add TSC decoding errors in the decoded trace itself to prevent
+      // creating unnecessary gaps, but we can count how many of these errors
+      // happened. In this case we reuse the previous correct TSC we saw, as
+      // it's better than no TSC at all.
+      decoded_thread.RecordTscError(tsc_error);
+    }
+  } else {
+    tsc_info.tsc = new_tsc;
+    tsc_info.has_tsc = eLazyBoolYes;
+  }
+}
+
+static void AppendError(DecodedThread &decoded_thread, Error &&error,
+                        TscInfo &tsc_info) {
+  if (tsc_info)
+    decoded_thread.AppendError(std::move(error), tsc_info.tsc);
+  else
+    decoded_thread.AppendError(std::move(error));
+}
+
+static void AppendInstruction(DecodedThread &decoded_thread,
+                              const pt_insn &insn, TscInfo &tsc_info) {
+  if (tsc_info)
+    decoded_thread.AppendInstruction(insn, tsc_info.tsc);
+  else
+    decoded_thread.AppendInstruction(insn);
+}
+
 /// Decode all the instructions from a configured decoder.
 /// The decoding flow is based on
 /// https://github.com/intel/libipt/blob/master/doc/howto_libipt.md#the-instruction-flow-decode-loop
 /// but with some relaxation to allow for gaps in the trace.
 ///
 /// Error codes returned by libipt while decoding are:
 /// - negative: actual errors
 /// - positive or zero: not an error, but a list of bits signaling the status of
-/// the decoder
+/// the decoder, e.g. whether there are events that need to be decoded or not
 ///
 /// \param[in] decoder
 ///   A configured libipt \a pt_insn_decoder.
 static void DecodeInstructions(pt_insn_decoder &decoder,
-                               DecodedThreadSP &decoded_thread_sp) {
-  while (true) {
-    int errcode = FindNextSynchronizationPoint(decoder);
-    if (errcode == -pte_eos)
-      break;
+                               DecodedThread &decoded_thread) {
 
-    if (errcode < 0) {
-      decoded_thread_sp->AppendError(make_error<IntelPTError>(errcode));
+  TscInfo tsc_info;
+  // We have this "global" errcode because if it's positive, we'll need
+  // its bits later to process events.
+  int errcode;
+
+  while (true) {
+    if ((errcode = FindNextSynchronizationPoint(decoder)) < 0) {
+      // We signal a gap only if it's not "end of stream"
+      if (errcode != -pte_eos)
+        AppendError(decoded_thread, make_error<IntelPTError>(errcode),
+                    tsc_info);
       break;
     }
 
     // We have synchronized, so we can start decoding
     // instructions and events.
     while (true) {
-      errcode = ProcessPTEvents(decoder, errcode);
-      if (errcode < 0) {
-        decoded_thread_sp->AppendError(make_error<IntelPTError>(errcode));
+      if ((errcode = ProcessPTEvents(decoder, errcode)) < 0) {
+        AppendError(decoded_thread, make_error<IntelPTError>(errcode),
+                    tsc_info);
         break;
       }
 
-      pt_insn insn;
-      errcode = pt_insn_next(&decoder, &insn, sizeof(insn));
-      if (errcode == -pte_eos)
-        break;
+      // We refresh the TSC that might have changed after processing the events.
+      // See
+      // https://github.com/intel/libipt/blob/master/doc/man/pt_evt_next.3.md
+      RefreshTscInfo(tsc_info, decoder, decoded_thread);
 
-      if (errcode < 0) {
-        decoded_thread_sp->AppendError(
-            make_error<IntelPTError>(errcode, insn.ip));
-        break;
-      }
-
-      uint64_t time;
-      int time_error = pt_insn_time(&decoder, &time, nullptr, nullptr);
-      if (time_error == -pte_invalid) {
-        // This happens if we invoke the pt_insn_time method incorrectly,
-        // but the instruction is good though.
-        decoded_thread_sp->AppendError(
-            make_error<IntelPTError>(time_error, insn.ip));
-        decoded_thread_sp->AppendInstruction(insn);
+      pt_insn insn;
+      if ((errcode = pt_insn_next(&decoder, &insn, sizeof(insn))) < 0) {
+        // We signal a gap only if it's not "end of stream"
+        if (errcode != -pte_eos)
+          AppendError(decoded_thread,
+                      make_error<IntelPTError>(errcode, insn.ip), tsc_info);
         break;
       }
-
-      if (time_error == -pte_no_time) {
-        // We simply don't have time information, i.e. None of TSC, MTC or CYC
-        // was enabled.
-        decoded_thread_sp->AppendInstruction(insn);
-      } else {
-        decoded_thread_sp->AppendInstruction(insn, time);
-      }
+      AppendInstruction(decoded_thread, insn, tsc_info);
     }
   }
 }
 
 /// Callback used by libipt for reading the process memory.
 ///
 /// More information can be found in
 /// https://github.com/intel/libipt/blob/master/doc/man/pt_image_set_callback.3.md
static void DecodeInMemoryTrace(DecodedThreadSP &decoded_thread_sp,
   pt_image *image = pt_insn_get_image(decoder);
 
   int errcode =
       pt_image_set_callback(image, ReadProcessMemory,
                             decoded_thread_sp->GetThread()->GetProcess().get());
   assert(errcode == 0);
   (void)errcode;
 
-  DecodeInstructions(*decoder, decoded_thread_sp);
+  DecodeInstructions(*decoder, *decoded_thread_sp);
   pt_insn_free_decoder(decoder);
 }
 // ---------------------------
 
 DecodedThreadSP ThreadDecoder::Decode() {
   if (!m_decoded_thread.hasValue())
     m_decoded_thread = DoDecode();
   return *m_decoded_thread;

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

 }
 
 lldb::TraceCursorUP TraceIntelPT::GetCursor(Thread &thread) {
   return Decode(thread)->GetCursor();
 }
 
 void TraceIntelPT::DumpTraceInfo(Thread &thread, Stream &s, bool verbose) {
   Optional<size_t> raw_size = GetRawTraceSize(thread);
-  s.Printf("\nthread #%u: tid = %" PRIu64, thread.GetIndexID(), thread.GetID());
+  s.Format("\nthread #{0}: tid = {1}", thread.GetIndexID(), thread.GetID());
   if (!raw_size) {
-    s.Printf(", not traced\n");
+    s << ", not traced\n";
     return;
   }
-  s.Printf("\n");
-
-  size_t insn_len = Decode(thread)->GetInstructions().size();
-  size_t mem_used = Decode(thread)->CalculateApproximateMemoryUsage();
-
-  s.Printf("  Raw trace size: %zu KiB\n", *raw_size / 1024);
-  s.Printf("  Total number of instructions: %zu\n", insn_len);
-  s.Printf("  Total approximate memory usage: %0.2lf KiB\n",
+  s << "\n";
+  DecodedThreadSP decoded_trace_sp = Decode(thread);
+  size_t insn_len = decoded_trace_sp->GetInstructions().size();
+  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);
   if (insn_len != 0)
-    s.Printf("  Average memory usage per instruction: %0.2lf bytes\n",
+    s.Format("  Average memory usage per instruction: {0:2} bytes\n",
              (double)mem_used / insn_len);
-  return;
+
+  const DecodedThread::LibiptErrors &tsc_errors =
+      decoded_trace_sp->GetTscErrors();
+  s.Format("\n  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,
+             error_message_to_count.second);
+  }
 }
 
 Optional<size_t> TraceIntelPT::GetRawTraceSize(Thread &thread) {
   if (IsTraced(thread.GetID()))
     return Decode(thread)->GetRawTraceSize();
   else
     return None;
 }

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

def testDumpRawTraceSize(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.98 KiB
-  Average memory usage per instruction: 48.00 bytes'''])
+  Average memory usage per instruction: 48.00 bytes
+
+  Number of TSC decoding errors: 0'''])