Skip to content

Commit

Permalink
[trace][intel pt] Fix per-psb packet decoding
Browse files Browse the repository at this point in the history
The per-PSB packet decoding logic was wrong because it was assuming that pt_insn_get_sync_offset was being udpated after every PSB. Silly me, that is not true. It returns the offset of the PSB packet after invoking pt_insn_sync_forward regardless of how many PSBs are visited later. Instead, I'm now following the approach described in https://github.com/intel/libipt/blob/master/doc/howto_libipt.md#parallel-decode for parallel decoding, which is basically what we need.

A nasty error that happened because of this is that when we had two PSBs (A and B), the following was happening

1. PSB A was processed all the way up to the end of the trace, which includes PSB B.
2. PSB B was then processed until the end of the trace.

The instructions emitted by step 2. were also emitted as part of step 1. so our trace had duplicated chunks. This problem becomes worse when you many PSBs.

As part of making sure this diff is correct, I added some other features that are very useful.

- Added a "synchronization point" event to the TraceCursor, so we can inspect when PSBs are emitted.
- Removed the single-thread decoder. Now the per-cpu decoder and single-thread decoder use the same code paths.
- Use the query decoder to fetch PSBs and timestamps. It turns out that the pt_insn_sync_forward of the instruction decoder can move past several PSBs (this means that we could skip some TSCs). On the other hand, the pt_query_sync_forward method doesn't skip PSBs, so we can get more accurate sync events and timing information.
- Turned LibiptDecoder into PSBBlockDecoder, which decodes single PSB blocks. It is the fundamental processing unit for decoding.
- Added many comments, asserts and improved error handling for clarity.
- Improved DecodeSystemWideTraceForThread so that a TSC is emitted always before a cpu change event. This was a bug that was annoying me before.
- SplitTraceInContinuousExecutions and FindLowestTSCInTrace are now using the query decoder, which can identify precisely each PSB along with their TSCs.
- Added an "only-events" option to the trace dumper to inspect only events.

I did extensive testing and I think we should have an in-house testing CI. The LLVM buildbots are not capable of supporting testing post-mortem traces of hundreds of megabytes. I'll leave that for later, but at least for now the current tests were able to catch most of the issues I encountered when doing this task.

A sample output of a program that I was single stepping is the following. You can see that only one PSB is emitted even though stepping happened!

```
thread #1: tid = 3578223
    0: (event) trace synchronization point [offset = 0x0xef0]
  a.out`main + 20 at main.cpp:29:20
    1: 0x0000000000402479    leaq   -0x1210(%rbp), %rax
    2: (event) software disabled tracing
    3: 0x0000000000402480    movq   %rax, %rdi
    4: (event) software disabled tracing
    5: (event) software disabled tracing
    6: 0x0000000000402483    callq  0x403bd4                  ; std::vector<int, std::allocator<int>>::vector at stl_vector.h:391:7
    7: (event) software disabled tracing
  a.out`std::vector<int, std::allocator<int>>::vector() at stl_vector.h:391:7
    8: 0x0000000000403bd4    pushq  %rbp
    9: (event) software disabled tracing
    10: 0x0000000000403bd5    movq   %rsp, %rbp
    11: (event) software disabled tracing
```

This is another trace of a long program with a few PSBs.
```
(lldb) thread trace dump instructions -E -f                                                                                                         thread #1: tid = 3603082
    0: (event) trace synchronization point [offset = 0x0x80]
    47417: (event) software disabled tracing
    129231: (event) trace synchronization point [offset = 0x0x800]
    146747: (event) software disabled tracing
    246076: (event) software disabled tracing
    259068: (event) trace synchronization point [offset = 0x0xf78]
    259276: (event) software disabled tracing
    259278: (event) software disabled tracing
    no more data
```

Differential Revision: https://reviews.llvm.org/D131630
  • Loading branch information
walter-erquinigo committed Aug 12, 2022
1 parent 2366c6a commit e17cae0
Show file tree
Hide file tree
Showing 20 changed files with 751 additions and 649 deletions.
9 changes: 9 additions & 0 deletions lldb/include/lldb/Target/TraceCursor.h
Original file line number Diff line number Diff line change
Expand Up @@ -271,6 +271,15 @@ class TraceCursor {
/// The approximate wall clock time for the trace item, or \a llvm::None
/// if not available.
virtual llvm::Optional<double> GetWallClockTime() const = 0;

/// Get some metadata associated with a synchronization point event. As
/// different trace technologies might have different values for this,
/// we return a string for flexibility.
///
/// \return
/// A string representing some metadata associated with a
/// \a eTraceEventSyncPoint event. \b None if no metadata is available.
virtual llvm::Optional<std::string> GetSyncPointMetadata() const = 0;
/// \}

protected:
Expand Down
3 changes: 3 additions & 0 deletions lldb/include/lldb/Target/TraceDumper.h
Original file line number Diff line number Diff line change
Expand Up @@ -34,6 +34,8 @@ struct TraceDumperOptions {
bool show_timestamps = false;
/// Dump the events that happened between instructions.
bool show_events = false;
/// Dump events and none of the instructions.
bool only_events = false;
/// For each instruction, print the instruction kind.
bool show_control_flow_kind = false;
/// Optional custom id to start traversing from.
Expand Down Expand Up @@ -63,6 +65,7 @@ class TraceDumper {
lldb::addr_t load_address;
llvm::Optional<double> timestamp;
llvm::Optional<uint64_t> hw_clock;
llvm::Optional<std::string> sync_point_metadata;
llvm::Optional<llvm::StringRef> error;
llvm::Optional<lldb::TraceEvent> event;
llvm::Optional<SymbolInfo> symbol_info;
Expand Down
9 changes: 6 additions & 3 deletions lldb/include/lldb/lldb-enumerations.h
Original file line number Diff line number Diff line change
Expand Up @@ -1161,15 +1161,18 @@ enum SaveCoreStyle {

/// 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,
/// Event due to a CPU HW clock tick
/// Event due to a CPU HW clock tick.
eTraceEventHWClockTick,
/// The underlying tracing technology emitted a synchronization event used by
/// trace processors.
eTraceEventSyncPoint,
};

// Enum used to identify which kind of item a \a TraceCursor is pointing at
Expand Down
5 changes: 5 additions & 0 deletions lldb/source/Commands/CommandObjectThread.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -2178,6 +2178,11 @@ class CommandObjectTraceDumpInstructions : public CommandObjectParsed {
m_dumper_options.json = true;
break;
}
case 'E': {
m_dumper_options.only_events = true;
m_dumper_options.show_events = true;
break;
}
case 'C': {
m_continue = true;
break;
Expand Down
4 changes: 4 additions & 0 deletions lldb/source/Commands/Options.td
Original file line number Diff line number Diff line change
Expand Up @@ -1160,6 +1160,10 @@ let Command = "thread trace dump instructions" in {
def thread_trace_dump_instructions_show_events : Option<"events", "e">,
Group<1>,
Desc<"Dump the events that happened during the execution of the target.">;
def thread_trace_dump_instruction_only_events : Option<"only-events", "E">,
Group<1>,
Desc<"Dump only the events that happened during the execution of the "
"target. No instrutions are dumped.">;
def thread_trace_dump_instructions_continue: Option<"continue", "C">,
Group<1>,
Desc<"Continue dumping instructions right where the previous invocation of "
Expand Down
37 changes: 13 additions & 24 deletions lldb/source/Plugins/Trace/intel-pt/DecodedThread.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -16,18 +16,6 @@ using namespace lldb_private;
using namespace lldb_private::trace_intel_pt;
using namespace llvm;

bool lldb_private::trace_intel_pt::IsLibiptError(int libipt_status) {
return libipt_status < 0;
}

bool lldb_private::trace_intel_pt::IsEndOfStream(int libipt_status) {
return libipt_status == -pte_eos;
}

bool lldb_private::trace_intel_pt::IsTscUnavailable(int libipt_status) {
return libipt_status == -pte_no_time;
}

char IntelPTError::ID;

IntelPTError::IntelPTError(int libipt_error_code, lldb::addr_t address)
Expand Down Expand Up @@ -103,6 +91,11 @@ DecodedThread::GetInstructionLoadAddress(uint64_t item_index) const {
return m_item_data[item_index].load_address;
}

lldb::addr_t
DecodedThread::GetSyncPointOffsetByIndex(uint64_t item_index) const {
return m_psb_offsets.find(item_index)->second;
}

ThreadSP DecodedThread::GetThread() { return m_thread_sp; }

DecodedThread::TraceItemStorage &
Expand All @@ -116,9 +109,17 @@ DecodedThread::CreateNewTraceItem(lldb::TraceItemKind kind) {
return m_item_data.back();
}

void DecodedThread::NotifySyncPoint(lldb::addr_t psb_offset) {
m_psb_offsets.try_emplace(GetItemsCount(), psb_offset);
AppendEvent(lldb::eTraceEventSyncPoint);
}

void DecodedThread::NotifyTsc(TSC tsc) {
if (m_last_tsc && (*m_last_tsc)->second.tsc == tsc)
return;
if (m_last_tsc)
assert(tsc >= (*m_last_tsc)->second.tsc &&
"We can't have decreasing times");

m_last_tsc =
m_tscs.emplace(GetItemsCount(), TSCRange{tsc, 0, GetItemsCount()}).first;
Expand Down Expand Up @@ -179,9 +180,6 @@ void DecodedThread::AppendInstruction(const pt_insn &insn) {
}

void DecodedThread::AppendError(const IntelPTError &error) {
// End of stream shouldn't be a public error
if (IsEndOfStream(error.GetLibiptErrorCode()))
return;
CreateNewTraceItem(lldb::eTraceItemKindError).error =
ConstString(error.message()).AsCString();
}
Expand All @@ -200,15 +198,6 @@ void DecodedThread::LibiptErrorsStats::RecordError(int libipt_error_code) {
total_count++;
}

void DecodedThread::RecordTscError(int libipt_error_code) {
m_tsc_errors_stats.RecordError(libipt_error_code);
}

const DecodedThread::LibiptErrorsStats &
DecodedThread::GetTscErrorsStats() const {
return m_tsc_errors_stats;
}

const DecodedThread::EventsStats &DecodedThread::GetEventsStats() const {
return m_events_stats;
}
Expand Down
39 changes: 11 additions & 28 deletions lldb/source/Plugins/Trace/intel-pt/DecodedThread.h
Original file line number Diff line number Diff line change
Expand Up @@ -20,15 +20,6 @@
namespace lldb_private {
namespace trace_intel_pt {

/// libipt status utils
/// \{
bool IsLibiptError(int libipt_status);

bool IsEndOfStream(int libipt_status);

bool IsTscUnavailable(int libipt_status);
/// \}

/// Class for representing a libipt decoding error.
class IntelPTError : public llvm::ErrorInfo<IntelPTError> {
public:
Expand Down Expand Up @@ -173,6 +164,10 @@ class DecodedThread : public std::enable_shared_from_this<DecodedThread> {
/// The requested cpu id, or \a LLDB_INVALID_CPU_ID if not available.
lldb::cpu_id_t GetCPUByIndex(uint64_t item_index) const;

/// \return
/// The PSB offset associated with the given item index.
lldb::addr_t GetSyncPointOffsetByIndex(uint64_t item_index) const;

/// Get a maximal range of trace items that include the given \p item_index
/// that have the same TSC value.
///
Expand All @@ -199,28 +194,12 @@ class DecodedThread : public std::enable_shared_from_this<DecodedThread> {
/// The load address of the instruction at the given index.
lldb::addr_t GetInstructionLoadAddress(uint64_t item_index) const;

/// Return an object with statistics of the 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 statistics.
///
/// \return
/// An object with the statistics of TSC decoding errors.
const LibiptErrorsStats &GetTscErrorsStats() const;

/// Return an object with statistics of the trace events that happened.
///
/// \return
/// The stats object of all the events.
const EventsStats &GetEventsStats() const;

/// 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);

/// The approximate size in bytes used by this instance,
/// including all the already decoded instructions.
size_t CalculateApproximateMemoryUsage() const;
Expand All @@ -235,6 +214,9 @@ class DecodedThread : public std::enable_shared_from_this<DecodedThread> {
/// If this a new CPU, an event will be created.
void NotifyCPU(lldb::cpu_id_t cpu_id);

/// Notify this object that a new PSB has been seen.
void NotifySyncPoint(lldb::addr_t psb_offset);

/// Append a decoding error.
void AppendError(const IntelPTError &error);

Expand Down Expand Up @@ -294,20 +276,21 @@ class DecodedThread : public std::enable_shared_from_this<DecodedThread> {
llvm::Optional<std::map<uint64_t, NanosecondsRange>::iterator>
m_last_nanoseconds = llvm::None;

// The cpu information is stored as a map. It maps `instruction index -> CPU`
// The cpu information is stored as a map. It maps `item 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;

// The PSB offsets are stored as a map. It maps `item index -> psb offset`.
llvm::DenseMap<uint64_t, lldb::addr_t> m_psb_offsets;

/// TSC -> nanos conversion utility.
llvm::Optional<LinuxPerfZeroTscConversion> m_tsc_conversion;

/// Statistics of all tracing events.
EventsStats m_events_stats;
/// Statistics of libipt errors when decoding TSCs.
LibiptErrorsStats m_tsc_errors_stats;
/// Total amount of time spent decoding.
std::chrono::milliseconds m_total_decoding_time{0};
};
Expand Down
Loading

0 comments on commit e17cae0

Please sign in to comment.