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 @@ -215,7 +215,7 @@ /// of this cursor. ExecutionContextRef &GetExecutionContextRef(); - /// Instruction, event or error information + /// Trace item information (instructions, errors and events) /// \{ /// \return @@ -255,27 +255,35 @@ /// The load address of the instruction the cursor is pointing at. virtual lldb::addr_t GetLoadAddress() const = 0; - /// Get the hardware counter of a given type associated with the current - /// instruction. Each architecture might support different counters. It might - /// happen that only some instructions of an entire trace have a given counter - /// associated with them. - /// - /// \param[in] counter_type - /// The counter type. - /// \return - /// The value of the counter or \b llvm::None if not available. - virtual llvm::Optional - 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. + /// whenever an eTraceEventCPUChanged 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 GetCPU() const = 0; + + /// Get the last hardware clock value that was emitted before the current + /// trace item. + /// + /// This call might not be O(1), so it's suggested to invoke this method + /// whenever an eTraceEventHWClockTick event is fired. + /// + /// \return + /// The requested HW clock value, or \a llvm::None if this information is + /// not available for the current item. + virtual llvm::Optional GetHWClock() const = 0; + + /// Get the approximate wall clock time in nanoseconds at which the current + /// trace item was executed. Each trace plug-in has a different definition for + /// what time 0 means. + /// + /// \return + /// The approximate wall clock time for the trace item, or \a llvm::None + /// if not available. + virtual llvm::Optional GetWallClockTime() const = 0; /// \} protected: diff --git a/lldb/include/lldb/Target/TraceDumper.h b/lldb/include/lldb/Target/TraceDumper.h --- a/lldb/include/lldb/Target/TraceDumper.h +++ b/lldb/include/lldb/Target/TraceDumper.h @@ -29,9 +29,9 @@ bool json = false; /// When dumping in JSON format, pretty print the output. bool pretty_print_json = false; - /// For each instruction, print the corresponding timestamp counter if + /// For each trace item, print the corresponding timestamp in nanoseconds if /// available. - bool show_tsc = false; + bool show_timestamps = false; /// Dump the events that happened between instructions. bool show_events = false; /// For each instruction, print the instruction kind. @@ -61,7 +61,8 @@ struct TraceItem { lldb::user_id_t id; lldb::addr_t load_address; - llvm::Optional tsc; + llvm::Optional timestamp; + llvm::Optional hw_clock; llvm::Optional error; llvm::Optional event; llvm::Optional symbol_info; 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 @@ -1157,12 +1157,6 @@ eSaveCoreStackOnly = 3, }; -// Type of counter values associated with instructions in a trace. -enum TraceCounter { - // Timestamp counter, like the one offered by Intel CPUs (TSC). - eTraceCounterTSC = 0, -}; - /// Events that might happen during a trace session. enum TraceEvent { /// Tracing was disabled for some time due to a software trigger @@ -1172,6 +1166,8 @@ /// 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 + eTraceEventHWClockTick, }; // Enum used to identify which kind of item a \a TraceCursor is pointing at 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 @@ -2179,7 +2179,7 @@ break; } case 't': { - m_dumper_options.show_tsc = true; + m_dumper_options.show_timestamps = true; break; } case 'e': { 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 @@ -1146,15 +1146,17 @@ Desc<"Dump in simple JSON format.">; def thread_trace_dump_instructions_pretty_print: Option<"pretty-json", "J">, Group<1>, - Desc<"Dump in JSON format but pretty printing the output for easier readability.">; + Desc<"Dump in JSON format but pretty printing the output for easier " + "readability.">; def thread_trace_dump_instructions_show_kind : Option<"kind", "k">, Group<1>, Desc<"Show instruction control flow kind. Refer to the enum " "`InstructionControlFlowKind` for a list of control flow kind. " "As an important note, far jumps, far calls and far returns often indicate " "calls to and from kernel.">; - 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_show_timestamps: Option<"time", "t">, + Group<1>, + Desc<"For each trace item, print the corresponding wall clock timestamp " + "if available.">; def thread_trace_dump_instructions_show_events : Option<"events", "e">, Group<1>, Desc<"Dump the events that happened during the execution of the target.">; 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 @@ -71,6 +71,8 @@ /// stopped at. See \a Trace::GetCursorPosition for more information. class DecodedThread : public std::enable_shared_from_this { public: + using TSC = uint64_t; + /// \class TscRange /// Class that represents the trace range associated with a given TSC. /// It provides efficient iteration to the previous or next TSC range in the @@ -82,7 +84,7 @@ class TscRange { public: /// Check if this TSC range includes the given instruction index. - bool InRange(size_t insn_index) const; + bool InRange(uint64_t insn_index) const; /// Get the next range chronologically. llvm::Optional Next() const; @@ -91,22 +93,27 @@ llvm::Optional Prev() const; /// Get the TSC value. - size_t GetTsc() const; + TSC GetTsc() const; /// Get the smallest instruction index that has this TSC. - size_t GetStartInstructionIndex() const; + uint64_t GetStartInstructionIndex() const; /// Get the largest instruction index that has this TSC. - size_t GetEndInstructionIndex() const; + uint64_t GetEndInstructionIndex() const; + /// Get an interpolated TSC value for the given item index assuming it + /// belongs to the current range. + TSC GetInterpolatedTSC(uint64_t item_index) const; private: friend class DecodedThread; - TscRange(std::map::const_iterator it, + TscRange(std::map::const_iterator it, const DecodedThread &decoded_thread); /// The iterator pointing to the beginning of the range. - std::map::const_iterator m_it; + std::map::const_iterator m_it; /// The largest instruction index that has this TSC. - size_t m_end_index; + uint64_t m_end_index; + /// Duration per instruction + long double m_tsc_duration_per_instruction; const DecodedThread *m_decoded_thread; }; @@ -153,16 +160,16 @@ /// neighbor of it. It might help speed it traversals of the trace with /// short jumps. llvm::Optional CalculateTscRange( - size_t insn_index, + uint64_t insn_index, const llvm::Optional &hint_range) const; /// \return /// The error associated with a given trace item. - const char *GetErrorByIndex(size_t item_index) const; + const char *GetErrorByIndex(uint64_t item_index) const; /// \return /// The trace item kind given an item index. - lldb::TraceItemKind GetItemKindByIndex(size_t item_index) const; + lldb::TraceItemKind GetItemKindByIndex(uint64_t item_index) const; /// \return /// The underlying event type for the given trace item index. @@ -179,10 +186,7 @@ /// \return /// The load address of the instruction at the given index. - lldb::addr_t GetInstructionLoadAddress(size_t item_index) const; - - /// Get a new cursor for the decoded thread. - lldb::TraceCursorUP CreateNewCursor(); + 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. @@ -214,7 +218,7 @@ /// 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); + void NotifyTsc(TSC tsc); /// Notify this object that a CPU has been seen. /// If this a new CPU, an event will be created. @@ -268,9 +272,9 @@ /// 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_timestamps; + std::map m_timestamps; /// This is the chronologically last TSC that has been added. - llvm::Optional m_last_tsc = llvm::None; + llvm::Optional 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 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 @@ -48,7 +48,8 @@ return static_cast(m_item_kinds.size()); } -lldb::addr_t DecodedThread::GetInstructionLoadAddress(size_t item_index) const { +lldb::addr_t +DecodedThread::GetInstructionLoadAddress(uint64_t item_index) const { return m_item_data[item_index].load_address; } @@ -65,6 +66,7 @@ if (!m_last_tsc || *m_last_tsc != tsc) { m_timestamps.emplace(m_item_kinds.size(), tsc); m_last_tsc = tsc; + AppendEvent(lldb::eTraceEventHWClockTick); } } @@ -135,7 +137,7 @@ } Optional DecodedThread::CalculateTscRange( - size_t insn_index, + uint64_t insn_index, const Optional &hint_range) const { // We first try to check the given hint range in case we are traversing the // trace in short jumps. If that fails, then we do the more expensive @@ -160,20 +162,17 @@ return TscRange(--it, *this); } -lldb::TraceItemKind DecodedThread::GetItemKindByIndex(size_t item_index) const { +lldb::TraceItemKind +DecodedThread::GetItemKindByIndex(uint64_t item_index) const { return static_cast(m_item_kinds[item_index]); } -const char *DecodedThread::GetErrorByIndex(size_t item_index) const { +const char *DecodedThread::GetErrorByIndex(uint64_t item_index) const { return m_item_data[item_index].error; } DecodedThread::DecodedThread(ThreadSP thread_sp) : m_thread_sp(thread_sp) {} -lldb::TraceCursorUP DecodedThread::CreateNewCursor() { - return std::make_unique(m_thread_sp, shared_from_this()); -} - size_t DecodedThread::CalculateApproximateMemoryUsage() const { return sizeof(TraceItemStorage) * m_item_data.size() + sizeof(uint8_t) * m_item_kinds.size() + @@ -181,27 +180,49 @@ (sizeof(size_t) + sizeof(lldb::cpu_id_t)) * m_cpus.size(); } -DecodedThread::TscRange::TscRange(std::map::const_iterator it, +DecodedThread::TscRange::TscRange(std::map::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_timestamps.end()) - ? std::numeric_limits::max() + ? decoded_thread.GetItemsCount() - 1 : next_it->first - 1; + TSC tsc_duration = + next_it == m_decoded_thread->m_timestamps.end() + ? (m_end_index + 1 - it->first) // for the last range, we assume each + // instruction took 1 TSC + : next_it->second - it->second; + m_tsc_duration_per_instruction = + static_cast(tsc_duration) / (m_end_index - m_it->first + 1); + // duration_per_instruction will be greater than 1 if the PSBs are too spread + // out, e.g. when we missed instructions or there was a context switch in + // between. In this case, we change it to 1 to have a more real number. If + // duration_per_instruction is less than 1, then that means that multiple + // instructions were executed in the same tsc. + if (m_tsc_duration_per_instruction > 1) + m_tsc_duration_per_instruction = 1; } -size_t DecodedThread::TscRange::GetTsc() const { return m_it->second; } +DecodedThread::TSC +DecodedThread::TscRange::GetInterpolatedTSC(uint64_t item_index) const { + return GetTsc() + (item_index - GetStartInstructionIndex()) * + m_tsc_duration_per_instruction; +} + +DecodedThread::TSC DecodedThread::TscRange::GetTsc() const { + return m_it->second; +} -size_t DecodedThread::TscRange::GetStartInstructionIndex() const { +uint64_t DecodedThread::TscRange::GetStartInstructionIndex() const { return m_it->first; } -size_t DecodedThread::TscRange::GetEndInstructionIndex() const { +uint64_t DecodedThread::TscRange::GetEndInstructionIndex() const { return m_end_index; } -bool DecodedThread::TscRange::InRange(size_t insn_index) const { +bool DecodedThread::TscRange::InRange(uint64_t insn_index) const { return GetStartInstructionIndex() <= insn_index && insn_index <= GetEndInstructionIndex(); } 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 @@ -16,8 +16,9 @@ class TraceCursorIntelPT : public TraceCursor { public: - TraceCursorIntelPT(lldb::ThreadSP thread_sp, - DecodedThreadSP decoded_thread_sp); + TraceCursorIntelPT( + lldb::ThreadSP thread_sp, DecodedThreadSP decoded_thread_sp, + const llvm::Optional &tsc_conversion); bool Seek(int64_t offset, SeekType origin) override; @@ -29,13 +30,12 @@ lldb::addr_t GetLoadAddress() const override; - llvm::Optional - GetCounter(lldb::TraceCounter counter_type) const override; - lldb::TraceEvent GetEventType() const override; llvm::Optional GetCPU() const override; + llvm::Optional GetHWClock() const override; + lldb::TraceItemKind GetItemKind() const override; bool GoToId(lldb::user_id_t id) override; @@ -44,6 +44,8 @@ bool HasId(lldb::user_id_t id) const override; + llvm::Optional GetWallClockTime() const override; + private: /// Calculate the tsc range for the current position if needed. void CalculateTscRange(); @@ -54,6 +56,8 @@ int64_t m_pos; /// Tsc range covering the current instruction. llvm::Optional m_tsc_range; + /// TSC to nanos conversion + llvm::Optional m_tsc_conversion; }; } // namespace trace_intel_pt 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 @@ -17,9 +17,11 @@ using namespace lldb_private::trace_intel_pt; using namespace llvm; -TraceCursorIntelPT::TraceCursorIntelPT(ThreadSP thread_sp, - DecodedThreadSP decoded_thread_sp) - : TraceCursor(thread_sp), m_decoded_thread_sp(decoded_thread_sp) { +TraceCursorIntelPT::TraceCursorIntelPT( + ThreadSP thread_sp, DecodedThreadSP decoded_thread_sp, + const llvm::Optional &tsc_conversion) + : TraceCursor(thread_sp), m_decoded_thread_sp(decoded_thread_sp), + m_tsc_conversion(tsc_conversion) { Seek(0, SeekType::End); } @@ -73,15 +75,18 @@ return m_decoded_thread_sp->GetInstructionLoadAddress(m_pos); } -Optional -TraceCursorIntelPT::GetCounter(lldb::TraceCounter counter_type) const { - switch (counter_type) { - case lldb::eTraceCounterTSC: - if (m_tsc_range) - return m_tsc_range->GetTsc(); - else - return llvm::None; - } +Optional TraceCursorIntelPT::GetHWClock() const { + if (m_tsc_range) + return m_tsc_range->GetTsc(); + else + return llvm::None; +} + +Optional TraceCursorIntelPT::GetWallClockTime() const { + if (!m_tsc_conversion || !m_tsc_range) + return None; + + return m_tsc_conversion->ToNanos(m_tsc_range->GetInterpolatedTSC(m_pos)); } Optional TraceCursorIntelPT::GetCPU() const { 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 @@ -8,6 +8,8 @@ #include "TraceIntelPT.h" +#include "TraceCursorIntelPT.h" + #include "../common/ThreadPostMortemTrace.h" #include "CommandObjectTraceStartIntelPT.h" #include "DecodedThread.h" @@ -141,7 +143,8 @@ llvm::Expected TraceIntelPT::CreateNewCursor(Thread &thread) { if (Expected decoded_thread = Decode(thread)) - return decoded_thread.get()->CreateNewCursor(); + return std::make_unique( + thread.shared_from_this(), *decoded_thread, m_storage.tsc_conversion); else return decoded_thread.takeError(); } 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 @@ -50,5 +50,7 @@ return "software disabled tracing"; case lldb::eTraceEventCPUChanged: return "CPU core changed"; + case lldb::eTraceEventHWClockTick: + return "HW clock tick"; } } diff --git a/lldb/source/Target/TraceDumper.cpp b/lldb/source/Target/TraceDumper.cpp --- a/lldb/source/Target/TraceDumper.cpp +++ b/lldb/source/Target/TraceDumper.cpp @@ -128,16 +128,26 @@ m_s.Format(" {0}: ", item.id); - if (m_options.show_tsc) { - m_s.Format("[tsc={0}] ", - item.tsc ? std::to_string(*item.tsc) : "unavailable"); + if (m_options.show_timestamps) { + m_s.Format("[{0}] ", item.timestamp + ? (std::to_string(*item.timestamp) + " ns") + : "unavailable"); } if (item.event) { m_s << "(event) " << TraceCursor::EventKindToString(*item.event); - if (*item.event == eTraceEventCPUChanged) { + switch (*item.event) { + case eTraceEventCPUChanged: m_s.Format(" [new CPU={0}]", item.cpu_id ? std::to_string(*item.cpu_id) : "unavailable"); + break; + case eTraceEventHWClockTick: + m_s.Format(" [{0}]", item.hw_clock ? std::to_string(*item.hw_clock) + : "unavailable"); + break; + case eTraceEventDisabledHW: + case eTraceEventDisabledSW: + break; } } else if (item.error) { m_s << "(error) " << *item.error; @@ -181,7 +191,8 @@ | { "loadAddress": string decimal, "id": decimal, - "tsc"?: string decimal, + "hwClock"?: string decimal, + "timestamp_ns"?: string decimal, "module"?: string, "symbol"?: string, "line"?: decimal, @@ -202,8 +213,17 @@ void DumpEvent(const TraceDumper::TraceItem &item) { m_j.attribute("event", TraceCursor::EventKindToString(*item.event)); - if (item.event == eTraceEventCPUChanged) + switch (*item.event) { + case eTraceEventCPUChanged: m_j.attribute("cpuId", item.cpu_id); + break; + case eTraceEventHWClockTick: + m_j.attribute("hwClock", item.hw_clock); + break; + case eTraceEventDisabledHW: + case eTraceEventDisabledSW: + break; + } } void DumpInstruction(const TraceDumper::TraceItem &item) { @@ -234,10 +254,11 @@ void TraceItem(const TraceDumper::TraceItem &item) override { m_j.object([&] { m_j.attribute("id", item.id); - if (m_options.show_tsc) - m_j.attribute( - "tsc", - item.tsc ? Optional(std::to_string(*item.tsc)) : None); + if (m_options.show_timestamps) + m_j.attribute("timestamp_ns", item.timestamp + ? Optional( + std::to_string(*item.timestamp)) + : None); if (item.event) { DumpEvent(item); @@ -289,8 +310,8 @@ TraceItem item; item.id = m_cursor_up->GetId(); - if (m_options.show_tsc) - item.tsc = m_cursor_up->GetCounter(lldb::eTraceCounterTSC); + if (m_options.show_timestamps) + item.timestamp = m_cursor_up->GetWallClockTime(); return item; } @@ -366,8 +387,17 @@ if (!m_options.show_events) continue; item.event = m_cursor_up->GetEventType(); - if (*item.event == eTraceEventCPUChanged) + switch (*item.event) { + case eTraceEventCPUChanged: item.cpu_id = m_cursor_up->GetCPU(); + break; + case eTraceEventHWClockTick: + item.hw_clock = m_cursor_up->GetHWClock(); + break; + case eTraceEventDisabledHW: + case eTraceEventDisabledSW: + break; + } } else if (m_cursor_up->IsError()) { item.error = m_cursor_up->GetError(); } else {