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 @@ -66,6 +66,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 @@ -1163,12 +1163,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, @@ -202,6 +202,11 @@ void DumpEvent(const TraceDumper::TraceItem &item) { m_j.attribute("event", TraceCursor::EventKindToString(*item.event)); +<<<<<<< HEAD +======= + if (item.event == eTraceEventCPUChanged) + m_j.attribute("cpuId", item.cpu_id); +>>>>>>> ccb96b741a18 ([trace][intel pt] Create a CPU change event and expose it in the dumper) } void DumpInstruction(const TraceDumper::TraceItem &item) { @@ -211,12 +216,18 @@ m_j.attribute( "symbol", ToOptionalString(item.symbol_info->sc.GetFunctionName().AsCString())); +<<<<<<< HEAD if (item.symbol_info->instruction) { m_j.attribute("mnemonic", ToOptionalString(item.symbol_info->instruction->GetMnemonic( &item.symbol_info->exe_ctx))); } +======= + m_j.attribute("mnemonic", + ToOptionalString(item.symbol_info->instruction->GetMnemonic( + &item.symbol_info->exe_ctx))); +>>>>>>> ccb96b741a18 ([trace][intel pt] Create a CPU change event and expose it in the dumper) if (IsLineEntryValid(item.symbol_info->sc.line_entry)) { m_j.attribute( @@ -239,6 +250,7 @@ if (item.event) { DumpEvent(item); +<<<<<<< HEAD return; } @@ -249,6 +261,13 @@ // we know we are seeing an actual instruction DumpInstruction(item); +======= + } else if (item.error) { + m_j.attribute("error", *item.error); + } else { + DumpInstruction(item); + } +>>>>>>> ccb96b741a18 ([trace][intel pt] Create a CPU change event and expose it in the dumper) }); } @@ -369,6 +388,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,13 +13,80 @@ 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", + substrs=['''{ + "traceTechnology": "intel-pt", + "threadStats": { + "tid": 3497234, + "traceItemsCount": 0, + "memoryUsage": { + "totalInBytes": "0", + "avgPerItemInBytes": null + }, + "timingInSeconds": {}, + "events": { + "totalCount": 0, + "individualCounts": {} + }, + "continuousExecutions": 0, + "PSBBlocks": 0, + "errorItems": { + "total": 0, + "individualErrors": {} + } + }, + "globalStats": { + "timingInSeconds": { + "Context switch and Intel PT traces correlation": 0 + }, + "totalUnattributedPSBBlocks": 0, + "totalCountinuosExecutions": 153, + "totalPSBBlocks": 5, + "totalContinuousExecutions": 153 + } +}''']) + + self.expect("thread trace dump info 2 --json", + substrs=['''{ + "traceTechnology": "intel-pt", + "threadStats": { + "tid": 3497496, + "traceItemsCount": 19524, + "memoryUsage": { + "totalInBytes": "175760", + "avgPerItemInBytes": 9.00''', '''}, + "timingInSeconds": {}, + "events": { + "totalCount": 2, + "individualCounts": { + "software disabled tracing": 1, + "CPU core changed": 1 + } + }, + "continuousExecutions": 1, + "PSBBlocks": 1, + "errorItems": { + "total": 0, + "individualErrors": {} + } + }, + "globalStats": { + "timingInSeconds": { + "Context switch and Intel PT traces correlation": 0''', '''}, + "totalUnattributedPSBBlocks": 0, + "totalCountinuosExecutions": 153, + "totalPSBBlocks": 5, + "totalContinuousExecutions": 153 + } +}''']) + @testSBAPIAndCommands def testLoadCompactMultiCoreTrace(self): src_dir = self.getSourceDir() @@ -52,18 +119,17 @@ # We clean up for the next run of this test self.dbg.DeleteTarget(self.dbg.GetTargetAtIndex(0)) - @testSBAPIAndCommands def testLoadMultiCoreTraceWithStringNumbers(self): src_dir = self.getSourceDir() 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 @@ -72,11 +138,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