[trace][intelpt] Fix multi CPU decoding TSC assertion error

[jj10306]

Summary

Occasionally the assertion that enforces increasing TSC values in DecodedThread::NotifyTsc
would get tripped during large multi CPU trace decoding.
The root cause of this issue was an assumption that all the data of a
PSB will fit within the start,end TSC of the "owning"
ThreadContinuousExecution. After investigating, this is not the case
because PSBs can have multiple TSCs.
This diff works around this issue by introducing a TSC upper bound for
each PSBBlockDecoder. This fixes the assertion failure by simply
"dropping" the remaining data of PSB whenever the TSC upper bound is
exceeded during decoding.
Future work will do a larger refactor of the multi CPU decoding to
remove the dependencies on this incorrect assumption so that PSB blocks
that span multiple ThreadContinuousExecutions are correctly handled.
correctly

Test Plan:
Run thread dump instructions 3 on a problematic trace and observe the assertion is no longer hit. The new error can be observed in the dump of events:

{
  "id": 5346,
  "error": "decoding truncated: TSC 64197386832965432 exceeds maximum TSC value 64197386633174537, will skip decoding the remaining data of the PSB (skipping 375 of 1336 bytes)"
},

Run relevant unittests

tools/lldb/unittests/Process/Linux/ProcessLinuxTests
tools/lldb/unittests/Utility/UtilityTests --gtest_filter=TraceGDBRemotePacketsTest.*
tools/lldb/unittests/Disassembler/x86/GetControlFlowKindx86Tests
./bin/lldb-dotest -p TestTrace

[wallace]

pretty good! I just left cosmetic requests

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

516–522

I suggest moving all of this to another function because it's a bit long

517

use * instead of value(). value() is rarely used in LLVM code. Also use >= instead of >

525–526

add a prefix message for easier regexp search

"decoding truncated: TSC packet {0} exceeds maximum TSC value {1} for this PSB block . Will resume decoding with the next PSB."

Use a better prefix if you can, and btw, you wrote the remining the remaining here.

527

ditto

530–538

I think let's better not include this to keep the error a bit smaller. In any case, you can do thread trace dump instructions <thread> -E and then look for the error prefix when debugging.

but if you insist, the byte offset message should come after the textual description of the error

539

return -pte_internal;

554

move this to the constructor so that it's highlighted by IDEs and appears in the public documentation

Maximum allowed value of TSCs decoded from this psb block. If this value is hit, then decoding for this block is stopped and an error is appended to the trace.

[jj10306]

Address comments

[jj10306]

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

530–538

I included the byte offset information so we can get an idea of what % of data we are losing each time this occurs. I'll clean this up a bit.

[wallace]

thanks. Your explanation of why the verbose error is useful was good :)

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

public:
   ///     The PSB block to decode.
   ///
   /// \param[in] next_block_ip
   ///     The starting ip at the next PSB block of the same thread if available.
   ///
   /// \param[in] decoded_thread
   ///     A \a DecodedThread object where the decoded instructions will be
   ///     appended to. It might have already some instructions.
+  ///
+  /// \param[in] tsc_upper_bound
+  ///   Maximum allowed value of TSCs decoded from this PSB block.
+  ///   Any of this PSB's data occurring after this TSC will be excluded.
   PSBBlockDecoder(PtInsnDecoderUP &&decoder_up, const PSBBlock &psb_block,
                   Optional<lldb::addr_t> next_block_ip,
-                  DecodedThread &decoded_thread, TraceIntelPT &trace_intel_pt)
+                  DecodedThread &decoded_thread, TraceIntelPT &trace_intel_pt,
+                  llvm::Optional<DecodedThread::TSC> tsc_upper_bound)
       : m_decoder_up(std::move(decoder_up)), m_psb_block(psb_block),
         m_next_block_ip(next_block_ip), m_decoded_thread(decoded_thread),
-        m_anomaly_detector(*m_decoder_up, trace_intel_pt, decoded_thread) {}
+        m_anomaly_detector(*m_decoder_up, trace_intel_pt, decoded_thread),
+        m_tsc_upper_bound(tsc_upper_bound) {}
 
   /// \param[in] trace_intel_pt
   ///     The main Trace object that own the PSB block.
   ///
   /// \param[in] decoder
   ///     A decoder configured to start and end within the boundaries of the
   ///     given \p psb_block.
   ///
public:
   ///     The starting ip at the next PSB block of the same thread if available.
   ///
   /// \param[in] decoded_thread
   ///     A \a DecodedThread object where the decoded instructions will be
   ///     appended to. It might have already some instructions.
   static Expected<PSBBlockDecoder>
   Create(TraceIntelPT &trace_intel_pt, const PSBBlock &psb_block,
          ArrayRef<uint8_t> buffer, Process &process,
-         Optional<lldb::addr_t> next_block_ip, DecodedThread &decoded_thread) {
+         Optional<lldb::addr_t> next_block_ip, DecodedThread &decoded_thread,
+         llvm::Optional<DecodedThread::TSC> tsc_upper_bound) {
     Expected<PtInsnDecoderUP> decoder_up =
         CreateInstructionDecoder(trace_intel_pt, buffer, process);
     if (!decoder_up)
       return decoder_up.takeError();
 
     return PSBBlockDecoder(std::move(*decoder_up), psb_block, next_block_ip,
-                           decoded_thread, trace_intel_pt);
+                           decoded_thread, trace_intel_pt, tsc_upper_bound);
   }
 
   void DecodePSBBlock() {
     int status = pt_insn_sync_forward(m_decoder_up.get());
     assert(status >= 0 &&
            "Synchronization shouldn't fail because this PSB was previously "
            "decoded correctly.");
 
if (m_next_block_ip && insn.ip != 0) {
         if (IsLibiptError(status)) {
           m_decoded_thread.AppendError(IntelPTError(status, insn.ip));
           return;
         }
       }
     }
   }
 
+  /// Process the TSC of a decoded PT event. Specifically, check if this TSC
+  /// is below the TSC upper bound for this PSB. If the TSC exceeds the upper
+  /// bound, return an error to abort decoding. Otherwise add the it to the
+  /// underlying DecodedThread and decoding should continue as expected.
+  ///
+  /// \param[in] tsc
+  ///   The TSC of the a decoded event.
+  Error ProcessPTEventTSC(DecodedThread::TSC tsc) {
+    if (m_tsc_upper_bound && tsc >= *m_tsc_upper_bound) {
+      // This event and all the remaining events of this PSB have a TSC
+      // outside the range of the "owning" ThreadContinuousExecution. For
+      // now we drop all of these events/instructions, future work can
+      // improve upon this by determining the "owning"
+      // ThreadContinuousExecution of the remaining PSB data.
+      std::string err_msg = formatv("decoding truncated: TSC {0} exceeds "
+                                    "maximum TSC value {1}, will skip decoding"
+                                    " the remaining data of the PSB",
+                                    tsc, *m_tsc_upper_bound)
+                                .str();
+
+      uint64_t offset;
+      int status = pt_insn_get_offset(m_decoder_up.get(), &offset);
+      if (!IsLibiptError(status)) {
+        err_msg = formatv("{2} (skipping {0} of {1} bytes)", offset,
+                          m_psb_block.size, err_msg)
+                      .str();
+      }
+      m_decoded_thread.AppendCustomError(err_msg);
+      return createStringError(inconvertibleErrorCode(), err_msg);
+    } else {
+      m_decoded_thread.NotifyTsc(tsc);
+      return Error::success();
+    }
+  }
+
   /// Before querying instructions, we need to query the events associated with
   /// that instruction, e.g. timing and trace disablement events.
   ///
   /// \param[in] status
   ///   The status gotten from the previous instruction decoding or PSB
   ///   synchronization.
   ///
   /// \return
   ///     The pte_status after decoding events.
   int ProcessPTEvents(int status) {
     while (HasEvents(status)) {
       pt_event event;
       std::memset(&event, 0, sizeof event);
       status = pt_insn_event(m_decoder_up.get(), &event, sizeof(event));
 
       if (IsLibiptError(status)) {
         m_decoded_thread.AppendError(IntelPTError(status));
         return status;
       }
 
-      if (event.has_tsc)
-        m_decoded_thread.NotifyTsc(event.tsc);
+      if (event.has_tsc) {
+        if (Error err = ProcessPTEventTSC(event.tsc)) {
+          consumeError(std::move(err));
+          return -pte_internal;
+        }
+      }
 
       switch (event.type) {
       case ptev_disabled:
         // The CPU paused tracing the program, e.g. due to ip filtering.
         m_decoded_thread.AppendEvent(lldb::eTraceEventDisabledHW);
         break;
       case ptev_async_disabled:
         // The kernel or user code paused tracing the program, e.g.
         // a breakpoint or a ioctl invocation pausing the trace, or a
         // context switch happened.
         m_decoded_thread.AppendEvent(lldb::eTraceEventDisabledSW);
         break;
       case ptev_overflow:
         // The CPU internal buffer had an overflow error and some instructions
         // were lost. A OVF packet comes with an FUP packet (harcoded address)
         // according to the documentation, so we'll continue seeing instructions
         // after this event.
         m_decoded_thread.AppendError(IntelPTError(-pte_overflow));
         break;
       default:
         break;
       }
     }
 
     return status;
   }
 
 private:
   PtInsnDecoderUP m_decoder_up;
   PSBBlock m_psb_block;
   Optional<lldb::addr_t> m_next_block_ip;
   DecodedThread &m_decoded_thread;
   PSBBlockAnomalyDetector m_anomaly_detector;
+  llvm::Optional<DecodedThread::TSC> m_tsc_upper_bound;
 };
 
 Error lldb_private::trace_intel_pt::DecodeSingleTraceForThread(
     DecodedThread &decoded_thread, TraceIntelPT &trace_intel_pt,
     ArrayRef<uint8_t> buffer) {
   Expected<std::vector<PSBBlock>> blocks =
       SplitTraceIntoPSBBlock(trace_intel_pt, buffer, /*expect_tscs=*/false);
   if (!blocks)
     return blocks.takeError();
 
   for (size_t i = 0; i < blocks->size(); i++) {
     PSBBlock &block = blocks->at(i);
 
     Expected<PSBBlockDecoder> decoder = PSBBlockDecoder::Create(
         trace_intel_pt, block, buffer.slice(block.psb_offset, block.size),
         *decoded_thread.GetThread()->GetProcess(),
         i + 1 < blocks->size() ? blocks->at(i + 1).starting_ip : None,
-        decoded_thread);
+        decoded_thread, llvm::None);
     if (!decoder)
       return decoder.takeError();
 
     decoder->DecodePSBBlock();
   }
 
   return Error::success();
 }
if (has_seen_psbs) {
       }
     }
 
     for (size_t j = 0; j < execution.psb_blocks.size(); j++) {
       const PSBBlock &psb_block = execution.psb_blocks[j];
 
       Expected<PSBBlockDecoder> decoder = PSBBlockDecoder::Create(
           trace_intel_pt, psb_block,
-          buffers.lookup(executions[i].thread_execution.cpu_id)
+          buffers.lookup(execution.thread_execution.cpu_id)
               .slice(psb_block.psb_offset, psb_block.size),
           *decoded_thread.GetThread()->GetProcess(),
           j + 1 < execution.psb_blocks.size()
               ? execution.psb_blocks[j + 1].starting_ip
               : None,
-          decoded_thread);
+          decoded_thread, execution.thread_execution.GetEndTSC());
       if (!decoder)
         return decoder.takeError();
 
       has_seen_psbs = true;
       decoder->DecodePSBBlock();
     }
 
     // If we haven't seen a PSB yet, then it's fine not to show errors