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 @@ -266,6 +266,16 @@ /// 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. + /// + /// \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; /// \} 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 @@ -64,6 +64,7 @@ llvm::Optional event; llvm::Optional symbol_info; llvm::Optional prev_symbol_info; + llvm::Optional cpu_id; }; /// Interface used to abstract away the format in which the instruction 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 @@ -1153,12 +1153,15 @@ eTraceCounterTSC = 0, }; -// Events that might happen during a trace session. +/// 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, }; // Enum used to identify which kind of item a \a TraceCursor is pointing at 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 @@ -168,6 +168,15 @@ /// The underlying event type for the given trace item index. lldb::TraceEvent GetEventByIndex(int item_index) const; + /// Get the most recent CPU id before or at the given trace item index. + /// + /// \param[in] item_index + /// The trace item index to compare with. + /// + /// \return + /// The requested cpu id, or \a llvm::None if not available. + llvm::Optional GetCPUByIndex(uint64_t item_index) const; + /// \return /// The load address of the instruction at the given index. lldb::addr_t GetInstructionLoadAddress(size_t item_index) const; @@ -204,8 +213,13 @@ lldb::ThreadSP GetThread(); /// 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); + /// Notify this object that a CPU has been seen. + /// If this a new CPU, an event will be created. + void NotifyCPU(lldb::cpu_id_t cpu_id); + /// Append a decoding error. void AppendError(const IntelPTError &error); @@ -254,10 +268,17 @@ /// 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_timestamps; /// This is the chronologically last TSC that has been added. 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 + // cpu is seen. + std::map m_cpus; + /// This is the chronologically last CPU ID. + llvm::Optional m_last_cpu = llvm::None; + /// Statistics of all tracing events. EventsStats m_events_stats; /// Statistics of libipt errors when decoding TSCs. 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 @@ -63,11 +63,28 @@ void DecodedThread::NotifyTsc(uint64_t tsc) { if (!m_last_tsc || *m_last_tsc != tsc) { - m_instruction_timestamps.emplace(m_item_kinds.size(), tsc); + m_timestamps.emplace(m_item_kinds.size(), tsc); m_last_tsc = tsc; } } +void DecodedThread::NotifyCPU(lldb::cpu_id_t cpu_id) { + if (!m_last_cpu || *m_last_cpu != cpu_id) { + m_cpus.emplace(m_item_kinds.size(), cpu_id); + m_last_cpu = cpu_id; + AppendEvent(lldb::eTraceEventCPUChanged); + } +} + +Optional +DecodedThread::GetCPUByIndex(uint64_t insn_index) const { + // Could possibly optimize the search + auto it = m_cpus.upper_bound(insn_index); + if (it == m_cpus.begin()) + return None; + return prev(it)->second; +} + void DecodedThread::AppendEvent(lldb::TraceEvent event) { CreateNewTraceItem(lldb::eTraceItemKindEvent).event = event; m_events_stats.RecordEvent(event); @@ -136,8 +153,8 @@ return candidate_range; } // Now we do a more expensive lookup - auto it = m_instruction_timestamps.upper_bound(insn_index); - if (it == m_instruction_timestamps.begin()) + auto it = m_timestamps.upper_bound(insn_index); + if (it == m_timestamps.begin()) return None; return TscRange(--it, *this); @@ -160,7 +177,8 @@ size_t DecodedThread::CalculateApproximateMemoryUsage() const { return sizeof(TraceItemStorage) * m_item_data.size() + sizeof(uint8_t) * m_item_kinds.size() + - (sizeof(size_t) + sizeof(uint64_t)) * m_instruction_timestamps.size(); + (sizeof(size_t) + sizeof(uint64_t)) * m_timestamps.size() + + (sizeof(size_t) + sizeof(lldb::cpu_id_t)) * m_cpus.size(); } DecodedThread::TscRange::TscRange(std::map::const_iterator it, @@ -168,7 +186,7 @@ : m_it(it), m_decoded_thread(&decoded_thread) { auto next_it = m_it; ++next_it; - m_end_index = (next_it == m_decoded_thread->m_instruction_timestamps.end()) + m_end_index = (next_it == m_decoded_thread->m_timestamps.end()) ? std::numeric_limits::max() : next_it->first - 1; } @@ -191,13 +209,13 @@ Optional DecodedThread::TscRange::Next() const { auto next_it = m_it; ++next_it; - if (next_it == m_decoded_thread->m_instruction_timestamps.end()) + if (next_it == m_decoded_thread->m_timestamps.end()) return None; return TscRange(next_it, *m_decoded_thread); } Optional DecodedThread::TscRange::Prev() const { - if (m_it == m_decoded_thread->m_instruction_timestamps.begin()) + if (m_it == m_decoded_thread->m_timestamps.begin()) return None; auto prev_it = m_it; --prev_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 @@ -285,6 +285,8 @@ for (size_t i = 0; i < executions.size(); i++) { const IntelPTThreadContinousExecution &execution = executions[i]; + decoded_thread.NotifyCPU(execution.thread_execution.cpu_id); + auto variant = execution.thread_execution.variant; // If we haven't seen a PSB yet, then it's fine not to show errors if (has_seen_psbs) { 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 @@ -34,6 +34,8 @@ lldb::TraceEvent GetEventType() const override; + llvm::Optional GetCPU() const override; + lldb::TraceItemKind GetItemKind() const override; bool GoToId(lldb::user_id_t id) 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 @@ -84,6 +84,10 @@ } } +Optional TraceCursorIntelPT::GetCPU() const { + return m_decoded_thread_sp->GetCPUByIndex(m_pos); +} + lldb::TraceEvent TraceCursorIntelPT::GetEventType() const { return m_decoded_thread_sp->GetEventByIndex(m_pos); } 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 @@ -48,5 +48,7 @@ return "hardware disabled tracing"; case lldb::eTraceEventDisabledSW: return "software disabled tracing"; + case lldb::eTraceEventCPUChanged: + return "CPU core changed"; } } 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 @@ -129,18 +129,16 @@ m_s.Format(" {0}: ", item.id); if (m_options.show_tsc) { - m_s << "[tsc="; - - if (item.tsc) - m_s.Format("{0}", *item.tsc); - else - m_s << "unavailable"; - - m_s << "] "; + m_s.Format("[tsc={0}] ", + item.tsc ? std::to_string(*item.tsc) : "unavailable"); } if (item.event) { m_s << "(event) " << TraceCursor::EventKindToString(*item.event); + if (*item.event == eTraceEventCPUChanged) { + m_s.Format(" [new CPU={0}]", + item.cpu_id ? std::to_string(*item.cpu_id) : "unavailable"); + } } else if (item.error) { m_s << "(error) " << *item.error; } else { @@ -172,14 +170,16 @@ /* schema: error_message: string | { + "event": string, "id": decimal, "tsc"?: string decimal, - "event": string + "cpuId"? decimal, } | { + "error": string, "id": decimal, "tsc"?: string decimal, - "error": string, | { + "loadAddress": string decimal, "id": decimal, "tsc"?: string decimal, "module"?: string, @@ -200,6 +200,34 @@ ~OutputWriterJSON() { m_j.arrayEnd(); } + void DumpEvent(const TraceDumper::TraceItem &item) { + m_j.attribute("event", TraceCursor::EventKindToString(*item.event)); + if (item.event == eTraceEventCPUChanged) + m_j.attribute("cpuId", item.cpu_id); + } + + void DumpInstruction(const TraceDumper::TraceItem &item) { + m_j.attribute("loadAddress", formatv("{0:x}", item.load_address)); + if (item.symbol_info) { + m_j.attribute("module", ToOptionalString(GetModuleName(item))); + m_j.attribute( + "symbol", + ToOptionalString(item.symbol_info->sc.GetFunctionName().AsCString())); + m_j.attribute("mnemonic", + ToOptionalString(item.symbol_info->instruction->GetMnemonic( + &item.symbol_info->exe_ctx))); + + if (IsLineEntryValid(item.symbol_info->sc.line_entry)) { + m_j.attribute( + "source", + ToOptionalString( + item.symbol_info->sc.line_entry.file.GetPath().c_str())); + m_j.attribute("line", item.symbol_info->sc.line_entry.line); + m_j.attribute("column", item.symbol_info->sc.line_entry.column); + } + } + } + void TraceItem(const TraceDumper::TraceItem &item) override { m_j.object([&] { m_j.attribute("id", item.id); @@ -209,37 +237,11 @@ item.tsc ? Optional(std::to_string(*item.tsc)) : None); if (item.event) { - m_j.object([&] { - m_j.attribute("event", TraceCursor::EventKindToString(*item.event)); - }); - return; - } - - if (item.error) { + DumpEvent(item); + } else if (item.error) { m_j.attribute("error", *item.error); - return; - } - - // we know we are seeing an actual instruction - m_j.attribute("loadAddress", formatv("{0:x}", item.load_address)); - if (item.symbol_info) { - m_j.attribute("module", ToOptionalString(GetModuleName(item))); - m_j.attribute("symbol", - ToOptionalString( - item.symbol_info->sc.GetFunctionName().AsCString())); - m_j.attribute( - "mnemonic", - ToOptionalString(item.symbol_info->instruction->GetMnemonic( - &item.symbol_info->exe_ctx))); - - if (IsLineEntryValid(item.symbol_info->sc.line_entry)) { - m_j.attribute( - "source", - ToOptionalString( - item.symbol_info->sc.line_entry.file.GetPath().c_str())); - m_j.attribute("line", item.symbol_info->sc.line_entry.line); - m_j.attribute("column", item.symbol_info->sc.line_entry.column); - } + } else { + DumpInstruction(item); } }); } @@ -361,6 +363,8 @@ if (!m_options.show_events) continue; item.event = m_cursor_up->GetEventType(); + if (*item.event == eTraceEventCPUChanged) + item.cpu_id = m_cursor_up->GetCPU(); } else if (m_cursor_up->IsError()) { item.error = m_cursor_up->GetError(); } else { diff --git a/lldb/test/API/commands/trace/TestTraceEvents.py b/lldb/test/API/commands/trace/TestTraceEvents.py --- a/lldb/test/API/commands/trace/TestTraceEvents.py +++ b/lldb/test/API/commands/trace/TestTraceEvents.py @@ -6,6 +6,23 @@ class TestTraceEvents(TraceIntelPTTestCaseBase): + @testSBAPIAndCommands + def testCPUEvents(self): + trace_description_file_path = os.path.join(self.getSourceDir(), "intelpt-multi-core-trace", "trace_missing_threads.json") + self.traceLoad(traceDescriptionFilePath=trace_description_file_path, substrs=["intel-pt"]) + + self.expect("thread trace dump instructions 3 -e --forward -c 5", + substrs=['''thread #3: tid = 3497496 + 0: (event) CPU core changed [new CPU=51] + m.out`foo() + 65 at multi_thread.cpp:12:21''']) + + self.expect("thread trace dump instructions 3 -e --forward -c 5 -J", + substrs=['''{ + "id": 0, + "event": "CPU core changed", + "cpuId": 51 + }''']) + @testSBAPIAndCommands def testPauseEvents(self): ''' 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 @@ -13,11 +13,11 @@ trace_description_file_path = os.path.join(src_dir, "intelpt-multi-core-trace", "trace.json") self.traceLoad(traceDescriptionFilePath=trace_description_file_path, substrs=["intel-pt"]) self.expect("thread trace dump instructions 2 -t", - substrs=["19522: [tsc=40450075478109270] (error) expected tracing enabled event", + substrs=["19523: [tsc=40450075478109270] (error) expected tracing enabled event", "m.out`foo() + 65 at multi_thread.cpp:12:21", - "19520: [tsc=40450075477657246] 0x0000000000400ba7 jg 0x400bb3"]) + "19521: [tsc=40450075477657246] 0x0000000000400ba7 jg 0x400bb3"]) self.expect("thread trace dump instructions 3 -t", - substrs=["67911: [tsc=40450075477799536] 0x0000000000400bd7 addl $0x1, -0x4(%rbp)", + substrs=["67912: [tsc=40450075477799536] 0x0000000000400bd7 addl $0x1, -0x4(%rbp)", "m.out`bar() + 26 at multi_thread.cpp:20:6"]) self.expect("thread trace dump info --json", @@ -58,15 +58,16 @@ "traceTechnology": "intel-pt", "threadStats": { "tid": 3497496, - "traceItemsCount": 19523, + "traceItemsCount": 19524, "memoryUsage": { - "totalInBytes": "175739", + "totalInBytes": "175760", "avgPerItemInBytes": 9.00''', '''}, "timingInSeconds": {}, "events": { - "totalCount": 1, + "totalCount": 2, "individualCounts": { - "software disabled tracing": 1 + "software disabled tracing": 1, + "CPU core changed": 1 } }, "continuousExecutions": 1, @@ -92,11 +93,11 @@ trace_description_file_path = os.path.join(src_dir, "intelpt-multi-core-trace", "trace_with_string_numbers.json") self.traceLoad(traceDescriptionFilePath=trace_description_file_path, substrs=["intel-pt"]) self.expect("thread trace dump instructions 2 -t", - substrs=["19522: [tsc=40450075478109270] (error) expected tracing enabled event", + substrs=["19523: [tsc=40450075478109270] (error) expected tracing enabled event", "m.out`foo() + 65 at multi_thread.cpp:12:21", - "19520: [tsc=40450075477657246] 0x0000000000400ba7 jg 0x400bb3"]) + "19521: [tsc=40450075477657246] 0x0000000000400ba7 jg 0x400bb3"]) self.expect("thread trace dump instructions 3 -t", - substrs=["67911: [tsc=40450075477799536] 0x0000000000400bd7 addl $0x1, -0x4(%rbp)", + substrs=["67912: [tsc=40450075477799536] 0x0000000000400bd7 addl $0x1, -0x4(%rbp)", "m.out`bar() + 26 at multi_thread.cpp:20:6"]) @testSBAPIAndCommands @@ -105,11 +106,11 @@ trace_description_file_path = os.path.join(src_dir, "intelpt-multi-core-trace", "trace_missing_threads.json") self.traceLoad(traceDescriptionFilePath=trace_description_file_path, substrs=["intel-pt"]) self.expect("thread trace dump instructions 3 -t", - substrs=["19522: [tsc=40450075478109270] (error) expected tracing enabled event", + substrs=["19523: [tsc=40450075478109270] (error) expected tracing enabled event", "m.out`foo() + 65 at multi_thread.cpp:12:21", - "19520: [tsc=40450075477657246] 0x0000000000400ba7 jg 0x400bb3"]) + "19521: [tsc=40450075477657246] 0x0000000000400ba7 jg 0x400bb3"]) self.expect("thread trace dump instructions 2 -t", - substrs=["67911: [tsc=40450075477799536] 0x0000000000400bd7 addl $0x1, -0x4(%rbp)", + substrs=["67912: [tsc=40450075477799536] 0x0000000000400bd7 addl $0x1, -0x4(%rbp)", "m.out`bar() + 26 at multi_thread.cpp:20:6"]) @testSBAPIAndCommands