diff --git a/lldb/include/lldb/Target/TraceCursor.h b/lldb/include/lldb/Target/TraceCursor.h --- a/lldb/include/lldb/Target/TraceCursor.h +++ b/lldb/include/lldb/Target/TraceCursor.h @@ -234,9 +234,17 @@ /// \param[in] counter_type /// The counter type. /// \return - /// The value of the counter or \b llvm::None if not available. + /// The value of the counter or \b llvm::None if not available. virtual llvm::Optional GetCounter(lldb::TraceCounter counter_type) = 0; + /// Get a bitmask with a list of events that happened chronologically right + /// before the current instruction or error, but after the previous + /// instruction. + /// + /// \return + /// The bitmask of events. + virtual lldb::TraceEvents GetEvents() = 0; + /// \return /// The \a lldb::TraceInstructionControlFlowType categories the /// instruction the cursor is pointing at falls into. If the cursor points @@ -254,6 +262,29 @@ bool m_forwards = false; }; +namespace trace_event_utils { +/// Convert an individual event to a display string. +/// +/// \param[in] event +/// An individual event. +/// +/// \return +/// A display string for that event, or nullptr if wrong data is passed +/// in. +const char *EventToDisplayString(lldb::TraceEvents event); + +/// Invoke the given callback for each individual event of the given events +/// bitmask. +/// +/// \param[in] events +/// A list of events to inspect. +/// +/// \param[in] callback +/// The callback to invoke for each event. +void ForEachEvent(lldb::TraceEvents events, + std::function callback); +} // namespace trace_event_utils + } // namespace lldb_private #endif // LLDB_TARGET_TRACE_CURSOR_H diff --git a/lldb/include/lldb/Target/TraceInstructionDumper.h b/lldb/include/lldb/Target/TraceInstructionDumper.h --- a/lldb/include/lldb/Target/TraceInstructionDumper.h +++ b/lldb/include/lldb/Target/TraceInstructionDumper.h @@ -26,6 +26,8 @@ /// For each instruction, print the corresponding timestamp counter if /// available. bool show_tsc = false; + /// Dump the events that happened between instructions. + bool show_events = false; /// Optional custom id to start traversing from. llvm::Optional id = llvm::None; /// Optional number of instructions to skip from the starting position @@ -79,6 +81,8 @@ /// \b true if the cursor moved. bool TryMoveOneStep(); + void PrintEvents(); + lldb::TraceCursorUP m_cursor_up; TraceInstructionDumperOptions m_options; Stream &m_s; diff --git a/lldb/include/lldb/lldb-enumerations.h b/lldb/include/lldb/lldb-enumerations.h --- a/lldb/include/lldb/lldb-enumerations.h +++ b/lldb/include/lldb/lldb-enumerations.h @@ -1147,6 +1147,15 @@ eTraceCounterTSC, }; +// Events that might happen during a trace session. +FLAGS_ENUM(TraceEvents){ + // Tracing was paused. If instructions were executed after pausing + // and before resuming, the TraceCursor used to traverse the trace + // should provide an error signalinig this data loss. + eTraceEventPaused = (1u << 0), +}; +LLDB_MARK_AS_BITMASK_ENUM(TraceEvents) + } // namespace lldb #endif // LLDB_LLDB_ENUMERATIONS_H diff --git a/lldb/source/Commands/CommandObjectThread.cpp b/lldb/source/Commands/CommandObjectThread.cpp --- a/lldb/source/Commands/CommandObjectThread.cpp +++ b/lldb/source/Commands/CommandObjectThread.cpp @@ -2156,6 +2156,10 @@ m_dumper_options.show_tsc = true; break; } + case 'e': { + m_dumper_options.show_events = true; + break; + } case 'C': { m_continue = true; break; diff --git a/lldb/source/Commands/Options.td b/lldb/source/Commands/Options.td --- a/lldb/source/Commands/Options.td +++ b/lldb/source/Commands/Options.td @@ -1121,12 +1121,15 @@ def thread_trace_dump_instructions_show_tsc : Option<"tsc", "t">, Group<1>, Desc<"For each instruction, print the corresponding timestamp counter if " "available.">; + def thread_trace_dump_instructions_hide_events : Option<"events", "e">, + Group<1>, + Desc<"Dump the events that happened during the execution of the target.">; def thread_trace_dump_instructions_continue: Option<"continue", "C">, Group<1>, - Desc<"Continue dumping instructions right where the previous invocation of this " - "command was left, or from the beginning if this is the first invocation. The --skip " - "argument is discarded and the other arguments are preserved from the previous " - "invocation when possible.">; + Desc<"Continue dumping instructions right where the previous invocation of " + "this command was left, or from the beginning if this is the first " + "invocation. The --skip argument is discarded and the other arguments are " + "preserved from the previous invocation when possible.">; } let Command = "thread trace dump info" in { diff --git a/lldb/source/Plugins/Trace/intel-pt/DecodedThread.h b/lldb/source/Plugins/Trace/intel-pt/DecodedThread.h --- a/lldb/source/Plugins/Trace/intel-pt/DecodedThread.h +++ b/lldb/source/Plugins/Trace/intel-pt/DecodedThread.h @@ -23,6 +23,15 @@ 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 { public: @@ -51,6 +60,27 @@ lldb::addr_t m_address; }; +/// Helper struct for building an instruction or error from the decoder. +/// It holds associated events and timing information. +struct DecodedInstruction { + DecodedInstruction() { + pt_insn.ip = LLDB_INVALID_ADDRESS; + libipt_error = pte_ok; + } + + DecodedInstruction(int libipt_error_code) : DecodedInstruction() { + libipt_error = libipt_error_code; + } + + /// \return \b true if and only if this struct holds a libipt error. + explicit operator bool() const; + + int libipt_error; + lldb::TraceEvents events = (lldb::TraceEvents)0; + llvm::Optional tsc = llvm::None; + pt_insn pt_insn; +}; + /// \class DecodedThread /// Class holding the instructions and function call hierarchy obtained from /// decoding a trace, as well as a position cursor used when reverse debugging @@ -101,30 +131,40 @@ }; // Struct holding counts for libipts errors; - struct LibiptErrors { + struct LibiptErrorsStats { // libipt error -> count - llvm::DenseMap libipt_errors; - int total_count = 0; + llvm::DenseMap libipt_errors_counts; + size_t total_count = 0; void RecordError(int libipt_error_code); }; + // Struct holding counts for events; + struct EventsStats { + /// A count for each individual event kind. We use an unordered map instead + /// of a DenseMap because DenseMap can't understand enums. + std::unordered_map events_counts; + size_t total_count = 0; + size_t total_instructions_with_events = 0; + + void RecordEventsForInstruction(lldb::TraceEvents events); + }; + 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); + /// Append an instruction or a libipt error. + void Append(const DecodedInstruction &insn); - /// Append a sucessfully decoded instruction with an associated TSC timestamp. - void AppendInstruction(const pt_insn &instruction, uint64_t tsc); - - /// Append a decoding error (i.e. an instruction that failed to be decoded). - void AppendError(llvm::Error &&error); + /// Append an error signaling that decoding completely failed. + void SetAsFailed(llvm::Error &&error); - /// Append a decoding error with a corresponding TSC. - void AppendError(llvm::Error &&error, uint64_t tsc); + /// Get a bitmask with the events that happened chronologically right before + /// the instruction pointed by the given instruction index, but after the + /// previous instruction. + lldb::TraceEvents GetEvents(int insn_index); /// Get the total number of instruction pointers from the decoded trace. /// This will include instructions that indicate errors (or gaps) in the @@ -175,13 +215,19 @@ /// Get a new cursor for the decoded thread. lldb::TraceCursorUP GetCursor(); - /// 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 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 - /// The number of TSC decoding errors. - const LibiptErrors &GetTscErrors() const; + /// 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. /// @@ -198,6 +244,9 @@ lldb::ThreadSP GetThread(); private: + /// Append a decoding error given an llvm::Error. + void AppendError(llvm::Error &&error); + /// Notify this class that the last added instruction or error has /// an associated TSC. void RecordTscForLastInstruction(uint64_t tsc); @@ -219,17 +268,20 @@ /// 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 m_instruction_timestamps; + std::map m_instruction_timestamps; /// This is the chronologically last TSC that has been added. llvm::Optional 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 m_errors; - /// The size in bytes of the raw buffer before decoding. It might be None if - /// the decoding failed. - llvm::Optional m_raw_trace_size; - /// All occurrences of libipt errors when decoding TSCs. - LibiptErrors m_tsc_errors; + /// This variable stores the bitmask of events that happened right before + /// the instruction given as a key. It maps `instruction index -> events`. + llvm::DenseMap m_events; + + /// 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}; }; diff --git a/lldb/source/Plugins/Trace/intel-pt/DecodedThread.cpp b/lldb/source/Plugins/Trace/intel-pt/DecodedThread.cpp --- a/lldb/source/Plugins/Trace/intel-pt/DecodedThread.cpp +++ b/lldb/source/Plugins/Trace/intel-pt/DecodedThread.cpp @@ -19,6 +19,18 @@ 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) @@ -35,6 +47,10 @@ OS << "error: " << libipt_error_message; } +DecodedInstruction::operator bool() const { + return !IsLibiptError(libipt_error); +} + size_t DecodedThread::GetInstructionsCount() const { return m_instruction_ips.size(); } @@ -93,15 +109,26 @@ } } -void DecodedThread::AppendInstruction(const pt_insn &insn) { - m_instruction_ips.emplace_back(insn.ip); - m_instruction_sizes.emplace_back(insn.size); - m_instruction_classes.emplace_back(insn.iclass); -} +void DecodedThread::Append(const DecodedInstruction &insn) { + if (!insn) { + // End of stream shouldn't be a public error + if (IsEndOfStream(insn.libipt_error)) + return; + + AppendError(make_error(insn.libipt_error, insn.pt_insn.ip)); + } else { + m_instruction_ips.emplace_back(insn.pt_insn.ip); + m_instruction_sizes.emplace_back(insn.pt_insn.size); + m_instruction_classes.emplace_back(insn.pt_insn.iclass); + } -void DecodedThread::AppendInstruction(const pt_insn &insn, uint64_t tsc) { - AppendInstruction(insn); - RecordTscForLastInstruction(tsc); + if (insn.tsc) + RecordTscForLastInstruction(*insn.tsc); + + if (insn.events) { + m_events.try_emplace(m_instruction_ips.size() - 1, insn.events); + m_events_stats.RecordEventsForInstruction(insn.events); + } } void DecodedThread::AppendError(llvm::Error &&error) { @@ -111,22 +138,45 @@ m_instruction_classes.emplace_back(pt_insn_class::ptic_error); } -void DecodedThread::AppendError(llvm::Error &&error, uint64_t tsc) { +void DecodedThread::SetAsFailed(llvm::Error &&error) { AppendError(std::move(error)); - RecordTscForLastInstruction(tsc); } -void DecodedThread::LibiptErrors::RecordError(int libipt_error_code) { - libipt_errors[pt_errstr(pt_errcode(libipt_error_code))]++; +lldb::TraceEvents DecodedThread::GetEvents(int insn_index) { + auto it = m_events.find(insn_index); + if (it != m_events.end()) + return it->second; + return (TraceEvents)0; +} + +void DecodedThread::LibiptErrorsStats::RecordError(int libipt_error_code) { + libipt_errors_counts[pt_errstr(pt_errcode(libipt_error_code))]++; total_count++; } void DecodedThread::RecordTscError(int libipt_error_code) { - m_tsc_errors.RecordError(libipt_error_code); + m_tsc_errors_stats.RecordError(libipt_error_code); } -const DecodedThread::LibiptErrors &DecodedThread::GetTscErrors() const { - return m_tsc_errors; +const DecodedThread::LibiptErrorsStats & +DecodedThread::GetTscErrorsStats() const { + return m_tsc_errors_stats; +} + +const DecodedThread::EventsStats &DecodedThread::GetEventsStats() const { + return m_events_stats; +} + +void DecodedThread::EventsStats::RecordEventsForInstruction( + lldb::TraceEvents events) { + if (!events) + return; + + total_instructions_with_events++; + trace_event_utils::ForEachEvent(events, [&](TraceEvents event) { + events_counts[event]++; + total_count++; + }); } Optional DecodedThread::CalculateTscRange( @@ -187,7 +237,7 @@ sizeof(pt_insn::size) * m_instruction_sizes.size() + sizeof(pt_insn::iclass) * m_instruction_classes.size() + (sizeof(size_t) + sizeof(uint64_t)) * m_instruction_timestamps.size() + - m_errors.getMemorySize(); + m_errors.getMemorySize() + m_events.getMemorySize(); } DecodedThread::TscRange::TscRange(std::map::const_iterator it, diff --git a/lldb/source/Plugins/Trace/intel-pt/LibiptDecoder.cpp b/lldb/source/Plugins/Trace/intel-pt/LibiptDecoder.cpp --- a/lldb/source/Plugins/Trace/intel-pt/LibiptDecoder.cpp +++ b/lldb/source/Plugins/Trace/intel-pt/LibiptDecoder.cpp @@ -26,18 +26,6 @@ explicit operator bool() const { return has_tsc == eLazyBoolYes; } }; -static inline bool IsLibiptError(int libipt_status) { - return libipt_status < 0; -} - -static inline bool IsEndOfStream(int libipt_status) { - return libipt_status == -pte_eos; -} - -static inline bool IsTscUnavailable(int libipt_status) { - return libipt_status == -pte_no_time; -} - /// Class that decodes a raw buffer for a single thread using the low level /// libipt library. /// @@ -75,20 +63,33 @@ } private: + /// Invoke the low level function \a pt_insn_next and store the decoded + /// instruction in the given \a DecodedInstruction. + /// + /// \param[out] insn + /// The instruction builder where the pt_insn information will be stored. + /// + /// \return + /// The status returned by pt_insn_next. + int DecodeNextInstruction(DecodedInstruction &insn) { + return pt_insn_next(&m_decoder, &insn.pt_insn, sizeof(insn.pt_insn)); + } + /// Decode all the instructions and events until an error is found or the end /// of the trace is reached. /// /// \param[in] status /// The status that was result of synchronizing to the most recent PSB. void DecodeInstructionsAndEvents(int status) { - pt_insn insn; - while (ProcessPTEvents(status)) { - status = pt_insn_next(&m_decoder, &insn, sizeof(insn)); - // The status returned by pt_insn_next will need to be processed by - // ProcessPTEvents in the next loop. - if (FoundErrors(status, insn.ip)) + while (DecodedInstruction insn = ProcessPTEvents(status)) { + // The status returned by DecodeNextInstruction will need to be processed + // by ProcessPTEvents in the next loop if it is not an error. + if (IsLibiptError(status = DecodeNextInstruction(insn))) { + insn.libipt_error = status; + m_decoded_thread.Append(insn); break; - AppendInstruction(insn); + } + m_decoded_thread.Append(insn); } } @@ -98,6 +99,8 @@ /// Once the decoder is at that synchronization point, it can start decoding /// instructions. /// + /// If errors are found, they will be appended to the trace. + /// /// \return /// The libipt decoder status after moving to the next PSB. Negative if /// no PSB was found. @@ -135,7 +138,9 @@ } // We make this call to record any synchronization errors. - FoundErrors(status); + if (IsLibiptError(status)) + m_decoded_thread.Append(DecodedInstruction(status)); + return status; } @@ -143,21 +148,60 @@ /// instruction e.g. timing events like ptev_tick, or paging events like /// ptev_paging. /// + /// If an error is found, it will be appended to the trace. + /// + /// \param[in] status + /// The status gotten from the previous instruction decoding or PSB + /// synchronization. + /// /// \return - /// \b true if we could process the events, \b false if errors were found. - bool ProcessPTEvents(int status) { + /// A \a DecodedInstruction with event, tsc and error information. + DecodedInstruction ProcessPTEvents(int status) { + DecodedInstruction insn; while (status & pts_event_pending) { pt_event event; status = pt_insn_event(&m_decoder, &event, sizeof(event)); - if (IsLibiptError(status)) + if (IsLibiptError(status)) { + insn.libipt_error = status; break; + } + + switch (event.type) { + case ptev_enabled: + // The kernel started or resumed tracing the program. + break; + case ptev_disabled: + // The CPU paused tracing the program, e.g. due to ip filtering. + 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. + + if (m_decoded_thread.GetInstructionsCount() > 0) { + // A paused event before the first instruction can be safely + // discarded. + insn.events |= eTraceEventPaused; + } + break; + case ptev_overflow: + // The CPU internal buffer had an overflow error and some instructions + // were lost. + insn.libipt_error = -pte_overflow; + break; + default: + 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(); - return !FoundErrors(status); + if (m_tsc_info) + insn.tsc = m_tsc_info.tsc; + if (!insn) + m_decoded_thread.Append(insn); + return insn; } /// Query the decoder for the most recent TSC timestamp and update @@ -189,39 +233,6 @@ } } - /// Check if the given libipt status signals any errors. If errors were found, - /// they will be recorded in the decoded trace. - /// - /// \param[in] ip - /// An optional ip address can be passed if the error is associated with - /// the decoding of a specific instruction. - /// - /// \return - /// \b true if errors were found, \b false otherwise. - bool FoundErrors(int status, lldb::addr_t ip = LLDB_INVALID_ADDRESS) { - if (!IsLibiptError(status)) - return false; - - // We signal a gap only if it's not "end of stream", as that's not a proper - // error. - if (!IsEndOfStream(status)) { - if (m_tsc_info) { - m_decoded_thread.AppendError(make_error(status, ip), - m_tsc_info.tsc); - } else { - m_decoded_thread.AppendError(make_error(status, ip)); - } - } - return true; - } - - void AppendInstruction(const pt_insn &insn) { - if (m_tsc_info) - m_decoded_thread.AppendInstruction(insn, m_tsc_info.tsc); - else - m_decoded_thread.AppendInstruction(insn); - } - private: pt_insn_decoder &m_decoder; DecodedThread &m_decoded_thread; @@ -293,7 +304,7 @@ Expected decoder_up = CreateInstructionDecoder(decoded_thread, trace_intel_pt, buffer); if (!decoder_up) - return decoded_thread.AppendError(decoder_up.takeError()); + return decoded_thread.SetAsFailed(decoder_up.takeError()); LibiptDecoder libipt_decoder(*decoder_up.get(), decoded_thread); libipt_decoder.DecodeUntilEndOfTrace(); diff --git a/lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.cpp b/lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.cpp --- a/lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.cpp +++ b/lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.cpp @@ -43,7 +43,7 @@ }); if (err) - decoded_thread_sp->AppendError(std::move(err)); + decoded_thread_sp->SetAsFailed(std::move(err)); return decoded_thread_sp; }); } diff --git a/lldb/source/Plugins/Trace/intel-pt/TraceCursorIntelPT.h b/lldb/source/Plugins/Trace/intel-pt/TraceCursorIntelPT.h --- a/lldb/source/Plugins/Trace/intel-pt/TraceCursorIntelPT.h +++ b/lldb/source/Plugins/Trace/intel-pt/TraceCursorIntelPT.h @@ -30,6 +30,8 @@ llvm::Optional GetCounter(lldb::TraceCounter counter_type) override; + lldb::TraceEvents GetEvents() override; + lldb::TraceInstructionControlFlowType GetInstructionControlFlowType() override; diff --git a/lldb/source/Plugins/Trace/intel-pt/TraceCursorIntelPT.cpp b/lldb/source/Plugins/Trace/intel-pt/TraceCursorIntelPT.cpp --- a/lldb/source/Plugins/Trace/intel-pt/TraceCursorIntelPT.cpp +++ b/lldb/source/Plugins/Trace/intel-pt/TraceCursorIntelPT.cpp @@ -108,6 +108,10 @@ } } +lldb::TraceEvents TraceCursorIntelPT::GetEvents() { + return m_decoded_thread_sp->GetEvents(m_pos); +} + TraceInstructionControlFlowType TraceCursorIntelPT::GetInstructionControlFlowType() { return m_decoded_thread_sp->GetInstructionControlFlowType(m_pos); diff --git a/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.cpp b/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.cpp --- a/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.cpp +++ b/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.cpp @@ -142,11 +142,25 @@ s.Format(" {0}: {1:2}s\n", name, duration.count() / 1000.0); }); + const DecodedThread::EventsStats &events_stats = + decoded_trace_sp->GetEventsStats(); + s << "\n Events:\n"; + s.Format(" Number of instructions with events: {0}\n", + events_stats.total_instructions_with_events); + s.Format(" Number of individual events: {0}\n", events_stats.total_count); + for (const auto &event_to_count : events_stats.events_counts) { + s.Format(" {0}: {1}\n", + trace_event_utils::EventToDisplayString(event_to_count.first), + event_to_count.second); + } + s << "\n Errors:\n"; - const DecodedThread::LibiptErrors &tsc_errors = - decoded_trace_sp->GetTscErrors(); - s.Format(" Number of TSC decoding errors: {0}\n", tsc_errors.total_count); - for (const auto &error_message_to_count : tsc_errors.libipt_errors) { + const DecodedThread::LibiptErrorsStats &tsc_errors_stats = + decoded_trace_sp->GetTscErrorsStats(); + s.Format(" Number of TSC decoding errors: {0}\n", + tsc_errors_stats.total_count); + for (const auto &error_message_to_count : + tsc_errors_stats.libipt_errors_counts) { s.Format(" {0}: {1}\n", error_message_to_count.first, error_message_to_count.second); } diff --git a/lldb/source/Target/TraceCursor.cpp b/lldb/source/Target/TraceCursor.cpp --- a/lldb/source/Target/TraceCursor.cpp +++ b/lldb/source/Target/TraceCursor.cpp @@ -33,3 +33,21 @@ void TraceCursor::SetForwards(bool forwards) { m_forwards = forwards; } bool TraceCursor::IsForwards() const { return m_forwards; } + +const char *trace_event_utils::EventToDisplayString(lldb::TraceEvents event) { + switch (event) { + case lldb::eTraceEventPaused: + return "paused"; + } + return nullptr; +} + +void trace_event_utils::ForEachEvent( + lldb::TraceEvents events, + std::function callback) { + while (events) { + TraceEvents event = static_cast(events & ~(events - 1)); + callback(event); + events &= ~event; + } +} diff --git a/lldb/source/Target/TraceInstructionDumper.cpp b/lldb/source/Target/TraceInstructionDumper.cpp --- a/lldb/source/Target/TraceInstructionDumper.cpp +++ b/lldb/source/Target/TraceInstructionDumper.cpp @@ -172,6 +172,16 @@ bool TraceInstructionDumper::HasMoreData() { return !m_no_more_data; } +void TraceInstructionDumper::PrintEvents() { + if (!m_options.show_events) + return; + + trace_event_utils::ForEachEvent( + m_cursor_up->GetEvents(), [&](TraceEvents event) { + m_s.Format(" [{0}]\n", trace_event_utils::EventToDisplayString(event)); + }); +} + Optional TraceInstructionDumper::DumpInstructions(size_t count) { ThreadSP thread_sp = m_cursor_up->GetExecutionContextRef().GetThreadSP(); if (!thread_sp) { @@ -259,6 +269,11 @@ break; } last_id = m_cursor_up->GetId(); + if (m_options.forwards) { + // When moving forwards, we first print the event before printing + // the actual instruction. + PrintEvents(); + } if (const char *err = m_cursor_up->GetError()) { if (!m_cursor_up->IsForwards() && !was_prev_instruction_an_error) @@ -297,6 +312,13 @@ } m_s.Printf("\n"); + + if (!m_options.forwards) { + // If we move backwards, we print the events after printing + // the actual instruction so that reading chronologically + // makes sense. + PrintEvents(); + } TryMoveOneStep(); } return last_id; diff --git a/lldb/test/API/commands/trace/TestTraceDumpInfo.py b/lldb/test/API/commands/trace/TestTraceDumpInfo.py --- a/lldb/test/API/commands/trace/TestTraceDumpInfo.py +++ b/lldb/test/API/commands/trace/TestTraceDumpInfo.py @@ -42,12 +42,17 @@ Memory usage: Raw trace size: 4 KiB - Total approximate memory usage (excluding raw trace): 0.27 KiB - Average memory usage per instruction (excluding raw trace): 13.00 bytes + Total approximate memory usage (excluding raw trace): 1.27 KiB + Average memory usage per instruction (excluding raw trace): 61.76 bytes Timing: Decoding instructions: ''', '''s + Events: + Number of instructions with events: 1 + Number of individual events: 1 + paused: 1 + Errors: Number of TSC decoding errors: 0'''], patterns=["Decoding instructions: \d.\d\ds"]) diff --git a/lldb/test/API/commands/trace/TestTraceEvents.py b/lldb/test/API/commands/trace/TestTraceEvents.py new file mode 100644 --- /dev/null +++ b/lldb/test/API/commands/trace/TestTraceEvents.py @@ -0,0 +1,82 @@ +import lldb +from intelpt_testcase import * +from lldbsuite.test.lldbtest import * +from lldbsuite.test import lldbutil +from lldbsuite.test.decorators import * + +class TestTraceEvents(TraceIntelPTTestCaseBase): + + mydir = TestBase.compute_mydir(__file__) + + @testSBAPIAndCommands + def testPauseEvents(self): + ''' + Everytime the target stops running on the CPU, a 'disabled' event will + be emitted, which is represented by the TraceCursor API as a 'paused' + event. + ''' + self.expect("target create " + + os.path.join(self.getSourceDir(), "intelpt-trace-multi-file", "a.out")) + self.expect("b 12") + self.expect("r") + self.traceStartThread() + self.expect("n") + self.expect("n") + self.expect("si") + self.expect("si") + self.expect("si") + # We ensure that the paused events are printed correctly forward + self.expect("thread trace dump instructions -e -f", + patterns=[f'''thread #1: tid = .* + a.out`main \+ 23 at main.cpp:12 + 0: {ADDRESS_REGEX} movl .* + \[paused\] + 1: {ADDRESS_REGEX} addl .* + 2: {ADDRESS_REGEX} movl .* + \[paused\] + a.out`main \+ 34 \[inlined\] inline_function\(\) at main.cpp:4 + 3: {ADDRESS_REGEX} movl .* + a.out`main \+ 41 \[inlined\] inline_function\(\) \+ 7 at main.cpp:5 + 4: {ADDRESS_REGEX} movl .* + 5: {ADDRESS_REGEX} addl .* + 6: {ADDRESS_REGEX} movl .* + a.out`main \+ 52 \[inlined\] inline_function\(\) \+ 18 at main.cpp:6 + 7: {ADDRESS_REGEX} movl .* + a.out`main \+ 55 at main.cpp:14 + 8: {ADDRESS_REGEX} movl .* + 9: {ADDRESS_REGEX} addl .* + 10: {ADDRESS_REGEX} movl .* + \[paused\] + a.out`main \+ 63 at main.cpp:16 + 11: {ADDRESS_REGEX} callq .* ; symbol stub for: foo\(\) + \[paused\] + a.out`symbol stub for: foo\(\) + 12: {ADDRESS_REGEX} jmpq''']) + + # We ensure that the paused events are printed correctly backward + self.expect("thread trace dump instructions -e --id 12", + patterns=[f'''thread #1: tid = .* + a.out`symbol stub for: foo\(\) + 12: {ADDRESS_REGEX} jmpq .* + \[paused\] + a.out`main \+ 63 at main.cpp:16 + 11: {ADDRESS_REGEX} callq .* ; symbol stub for: foo\(\) + \[paused\] + a.out`main \+ 60 at main.cpp:14 + 10: {ADDRESS_REGEX} movl .* + 9: {ADDRESS_REGEX} addl .* + 8: {ADDRESS_REGEX} movl .* + a.out`main \+ 52 \[inlined\] inline_function\(\) \+ 18 at main.cpp:6 + 7: {ADDRESS_REGEX} movl .* + a.out`main \+ 49 \[inlined\] inline_function\(\) \+ 15 at main.cpp:5 + 6: {ADDRESS_REGEX} movl .* + 5: {ADDRESS_REGEX} addl .* + 4: {ADDRESS_REGEX} movl .* + a.out`main \+ 34 \[inlined\] inline_function\(\) at main.cpp:4 + 3: {ADDRESS_REGEX} movl .* + \[paused\] + a.out`main \+ 31 at main.cpp:12 + 2: {ADDRESS_REGEX} movl .* + 1: {ADDRESS_REGEX} addl .* + \[paused\] + 0: {ADDRESS_REGEX} movl .*''']) diff --git a/lldb/test/API/commands/trace/TestTraceLoad.py b/lldb/test/API/commands/trace/TestTraceLoad.py --- a/lldb/test/API/commands/trace/TestTraceLoad.py +++ b/lldb/test/API/commands/trace/TestTraceLoad.py @@ -40,12 +40,17 @@ Memory usage: Raw trace size: 4 KiB - Total approximate memory usage (excluding raw trace): 0.27 KiB - Average memory usage per instruction (excluding raw trace): 13.00 bytes + Total approximate memory usage (excluding raw trace): 1.27 KiB + Average memory usage per instruction (excluding raw trace): 61.76 bytes Timing: Decoding instructions: ''', '''s + Events: + Number of instructions with events: 1 + Number of individual events: 1 + paused: 1 + Errors: Number of TSC decoding errors: 0'''])