[Lldb-commits] [lldb] 4f676c2 - [trace][intel pt] Introduce wall clock time for each trace item
Walter Erquinigo via lldb-commits
lldb-commits at lists.llvm.org
Tue Jul 26 12:05:35 PDT 2022
Author: Walter Erquinigo
Date: 2022-07-26T12:05:23-07:00
New Revision: 4f676c2599eb9c5c57528ebad93269a9ee30d7ca
URL: https://github.com/llvm/llvm-project/commit/4f676c2599eb9c5c57528ebad93269a9ee30d7ca
DIFF: https://github.com/llvm/llvm-project/commit/4f676c2599eb9c5c57528ebad93269a9ee30d7ca.diff
LOG: [trace][intel pt] Introduce wall clock time for each trace item
- Decouple TSCs from trace items
- Turn TSCs into events just like CPUs. The new name is HW clock tick, wich could be reused by other vendors.
- Add a GetWallTime that returns the wall time that the trace plug-in can infer for each trace item.
- For intel pt, we are doing the following interpolation: if an instruction takes less than 1 TSC, we use that duration, otherwise, we assume the instruction took 1 TSC. This helps us avoid having to handle context switches, changes to kernel, idle times, decoding errors, etc. We are just trying to show some approximation and not the real data. For the real data, TSCs are the way to go. Besides that, we are making sure that no two trace items will give the same interpolation value. Finally, we are using as time 0 the time at which tracing started.
Sample output:
```
(lldb) r
Process 750047 launched: '/home/wallace/a.out' (x86_64)
Process 750047 stopped
* thread #1, name = 'a.out', stop reason = breakpoint 1.1
frame #0: 0x0000000000402479 a.out`main at main.cpp:29:20
26 };
27
28 int main() {
-> 29 std::vector<int> vvv;
30 for (int i = 0; i < 100; i++)
31 vvv.push_back(i);
32
(lldb) process trace start -s 64kb -t --per-cpu
(lldb) b 60
Breakpoint 2: where = a.out`main + 1689 at main.cpp:60:23, address = 0x0000000000402afe
(lldb) c
Process 750047 resuming
Process 750047 stopped
* thread #1, name = 'a.out', stop reason = breakpoint 2.1
frame #0: 0x0000000000402afe a.out`main at main.cpp:60:23
57 map<int, int> m;
58 m[3] = 4;
59
-> 60 map<string, string> m2;
61 m2["5"] = "6";
62
63 std::vector<std::string> vs = {"2", "3"};
(lldb) thread trace dump instructions -t -f -e thread #1: tid = 750047
0: [379567.000 ns] (event) HW clock tick [48599428476224707]
1: [379569.000 ns] (event) CPU core changed [new CPU=2]
2: [390487.000 ns] (event) HW clock tick [48599428476246495]
3: [1602508.000 ns] (event) HW clock tick [48599428478664855]
4: [1662745.000 ns] (event) HW clock tick [48599428478785046]
libc.so.6`malloc
5: [1662746.995 ns] 0x00007ffff7176660 endbr64
6: [1662748.991 ns] 0x00007ffff7176664 movq 0x32387d(%rip), %rax ; + 408
7: [1662750.986 ns] 0x00007ffff717666b pushq %r12
8: [1662752.981 ns] 0x00007ffff717666d pushq %rbp
9: [1662754.977 ns] 0x00007ffff717666e pushq %rbx
10: [1662756.972 ns] 0x00007ffff717666f movq (%rax), %rax
11: [1662758.967 ns] 0x00007ffff7176672 testq %rax, %rax
12: [1662760.963 ns] 0x00007ffff7176675 jne 0x9c7e0 ; <+384>
13: [1662762.958 ns] 0x00007ffff717667b leaq 0x17(%rdi), %rax
14: [1662764.953 ns] 0x00007ffff717667f cmpq $0x1f, %rax
15: [1662766.949 ns] 0x00007ffff7176683 ja 0x9c730 ; <+208>
16: [1662768.944 ns] 0x00007ffff7176730 andq $-0x10, %rax
17: [1662770.939 ns] 0x00007ffff7176734 cmpq $-0x41, %rax
18: [1662772.935 ns] 0x00007ffff7176738 seta %dl
19: [1662774.930 ns] 0x00007ffff717673b jmp 0x9c690 ; <+48>
20: [1662776.925 ns] 0x00007ffff7176690 cmpq %rdi, %rax
21: [1662778.921 ns] 0x00007ffff7176693 jb 0x9c7b0 ; <+336>
22: [1662780.916 ns] 0x00007ffff7176699 testb %dl, %dl
23: [1662782.911 ns] 0x00007ffff717669b jne 0x9c7b0 ; <+336>
24: [1662784.906 ns] 0x00007ffff71766a1 movq 0x3236c0(%rip), %r12 ; + 24
(lldb) thread trace dump instructions -t -f -e -J -c 4
[
{
"id": 0,
"timestamp_ns": "379567.000000",
"event": "HW clock tick",
"hwClock": 48599428476224707
},
{
"id": 1,
"timestamp_ns": "379569.000000",
"event": "CPU core changed",
"cpuId": 2
},
{
"id": 2,
"timestamp_ns": "390487.000000",
"event": "HW clock tick",
"hwClock": 48599428476246495
},
{
"id": 3,
"timestamp_ns": "1602508.000000",
"event": "HW clock tick",
"hwClock": 48599428478664855
},
{
"id": 4,
"timestamp_ns": "1662745.000000",
"event": "HW clock tick",
"hwClock": 48599428478785046
},
{
"id": 5,
"timestamp_ns": "1662746.995324",
"loadAddress": "0x7ffff7176660",
"module": "libc.so.6",
"symbol": "malloc",
"mnemonic": "endbr64"
},
{
"id": 6,
"timestamp_ns": "1662748.990648",
"loadAddress": "0x7ffff7176664",
"module": "libc.so.6",
"symbol": "malloc",
"mnemonic": "movq"
},
{
"id": 7,
"timestamp_ns": "1662750.985972",
"loadAddress": "0x7ffff717666b",
"module": "libc.so.6",
"symbol": "malloc",
"mnemonic": "pushq"
},
{
"id": 8,
"timestamp_ns": "1662752.981296",
"loadAddress": "0x7ffff717666d",
"module": "libc.so.6",
"symbol": "malloc",
"mnemonic": "pushq"
}
]
```
Differential Revision: https://reviews.llvm.org/D130054
Added:
Modified:
lldb/include/lldb/Target/TraceCursor.h
lldb/include/lldb/Target/TraceDumper.h
lldb/include/lldb/Utility/TraceIntelPTGDBRemotePackets.h
lldb/include/lldb/lldb-enumerations.h
lldb/source/Commands/CommandObjectThread.cpp
lldb/source/Commands/Options.td
lldb/source/Plugins/Trace/intel-pt/DecodedThread.cpp
lldb/source/Plugins/Trace/intel-pt/DecodedThread.h
lldb/source/Plugins/Trace/intel-pt/LibiptDecoder.cpp
lldb/source/Plugins/Trace/intel-pt/LibiptDecoder.h
lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.cpp
lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.h
lldb/source/Plugins/Trace/intel-pt/TraceCursorIntelPT.cpp
lldb/source/Plugins/Trace/intel-pt/TraceCursorIntelPT.h
lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.cpp
lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.h
lldb/source/Plugins/Trace/intel-pt/TraceIntelPTMultiCpuDecoder.cpp
lldb/source/Plugins/Trace/intel-pt/TraceIntelPTMultiCpuDecoder.h
lldb/source/Target/TraceCursor.cpp
lldb/source/Target/TraceDumper.cpp
lldb/test/API/commands/trace/TestTraceEvents.py
lldb/test/API/commands/trace/TestTraceLoad.py
lldb/test/API/commands/trace/TestTraceTSC.py
Removed:
################################################################################
diff --git a/lldb/include/lldb/Target/TraceCursor.h b/lldb/include/lldb/Target/TraceCursor.h
index f6337e3d3d3f..95b022331634 100644
--- a/lldb/include/lldb/Target/TraceCursor.h
+++ b/lldb/include/lldb/Target/TraceCursor.h
@@ -215,7 +215,7 @@ class TraceCursor {
/// of this cursor.
ExecutionContextRef &GetExecutionContextRef();
- /// Instruction, event or error information
+ /// Trace item information (instructions, errors and events)
/// \{
/// \return
@@ -255,27 +255,35 @@ class TraceCursor {
/// 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
diff erent 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<uint64_t>
- 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<lldb::cpu_id_t> 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<uint64_t> 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
diff erent 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<double> GetWallClockTime() const = 0;
/// \}
protected:
diff --git a/lldb/include/lldb/Target/TraceDumper.h b/lldb/include/lldb/Target/TraceDumper.h
index bbc1a55873d7..ada779990e07 100644
--- a/lldb/include/lldb/Target/TraceDumper.h
+++ b/lldb/include/lldb/Target/TraceDumper.h
@@ -29,9 +29,9 @@ struct TraceDumperOptions {
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 @@ class TraceDumper {
struct TraceItem {
lldb::user_id_t id;
lldb::addr_t load_address;
- llvm::Optional<uint64_t> tsc;
+ llvm::Optional<double> timestamp;
+ llvm::Optional<uint64_t> hw_clock;
llvm::Optional<llvm::StringRef> error;
llvm::Optional<lldb::TraceEvent> event;
llvm::Optional<SymbolInfo> symbol_info;
diff --git a/lldb/include/lldb/Utility/TraceIntelPTGDBRemotePackets.h b/lldb/include/lldb/Utility/TraceIntelPTGDBRemotePackets.h
index bf9409743a6d..5930cd9970e7 100644
--- a/lldb/include/lldb/Utility/TraceIntelPTGDBRemotePackets.h
+++ b/lldb/include/lldb/Utility/TraceIntelPTGDBRemotePackets.h
@@ -91,8 +91,8 @@ struct LinuxPerfZeroTscConversion {
/// nanoseconds) is defined by the kernel at boot time and has no particularly
/// useful meaning. On the other hand, this value is constant for an entire
/// trace session.
- // See 'time_zero' section of
- // https://man7.org/linux/man-pages/man2/perf_event_open.2.html
+ /// See 'time_zero' section of
+ /// https://man7.org/linux/man-pages/man2/perf_event_open.2.html
///
/// \param[in] tsc
/// The TSC value to be converted.
diff --git a/lldb/include/lldb/lldb-enumerations.h b/lldb/include/lldb/lldb-enumerations.h
index 974cc293709e..2566a43daac8 100644
--- a/lldb/include/lldb/lldb-enumerations.h
+++ b/lldb/include/lldb/lldb-enumerations.h
@@ -1159,12 +1159,6 @@ enum SaveCoreStyle {
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
@@ -1174,6 +1168,8 @@ enum TraceEvent {
/// 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
index 1371b9dbda1e..fe0cb0945cde 100644
--- a/lldb/source/Commands/CommandObjectThread.cpp
+++ b/lldb/source/Commands/CommandObjectThread.cpp
@@ -2162,7 +2162,7 @@ class CommandObjectTraceDumpInstructions : public CommandObjectParsed {
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
index 78221db18e65..cc47db575306 100644
--- a/lldb/source/Commands/Options.td
+++ b/lldb/source/Commands/Options.td
@@ -1146,15 +1146,17 @@ let Command = "thread trace dump instructions" in {
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.cpp b/lldb/source/Plugins/Trace/intel-pt/DecodedThread.cpp
index 0859c5a20b7e..02f1d2f24d8c 100644
--- a/lldb/source/Plugins/Trace/intel-pt/DecodedThread.cpp
+++ b/lldb/source/Plugins/Trace/intel-pt/DecodedThread.cpp
@@ -44,11 +44,65 @@ void IntelPTError::log(llvm::raw_ostream &OS) const {
OS << formatv(": {0:x+16}", m_address);
}
-int64_t DecodedThread::GetItemsCount() const {
- return static_cast<int64_t>(m_item_kinds.size());
+bool DecodedThread::TSCRange::InRange(uint64_t item_index) const {
+ return item_index >= first_item_index &&
+ item_index < first_item_index + items_count;
+}
+
+bool DecodedThread::NanosecondsRange::InRange(uint64_t item_index) const {
+ return item_index >= first_item_index &&
+ item_index < first_item_index + items_count;
+}
+
+double DecodedThread::NanosecondsRange::GetInterpolatedTime(
+ uint64_t item_index, uint64_t begin_of_time_nanos,
+ const LinuxPerfZeroTscConversion &tsc_conversion) const {
+ uint64_t items_since_last_tsc = item_index - first_item_index;
+
+ auto interpolate = [&](uint64_t next_range_start_ns) {
+ if (next_range_start_ns == nanos) {
+ // If the resolution of the conversion formula is bad enough to consider
+ // these two timestamps as equal, then we just increase the next one by 1
+ // for correction
+ next_range_start_ns++;
+ }
+ long double item_duration =
+ static_cast<long double>(items_count) / (next_range_start_ns - nanos);
+ return (nanos - begin_of_time_nanos) + items_since_last_tsc * item_duration;
+ };
+
+ if (!next_range) {
+ // If this is the last TSC range, so we have to extrapolate. In this case,
+ // we assume that each instruction took one TSC, which is what an
+ // instruction would take if no parallelism is achieved and the frequency
+ // multiplier is 1.
+ return interpolate(tsc_conversion.ToNanos(tsc + items_count));
+ }
+ if (items_count < (next_range->tsc - tsc)) {
+ // If the numbers of items in this range is less than the total TSC duration
+ // of this range, i.e. each instruction taking longer than 1 TSC, then we
+ // can assume that something else happened between these TSCs (e.g. a
+ // context switch, change to kernel, decoding errors, etc). In this case, we
+ // also assume that each instruction took 1 TSC. A proper way to improve
+ // this would be to analize the next events in the trace looking for context
+ // switches or trace disablement events, but for now, as we only want an
+ // approximation, we keep it simple. We are also guaranteed that the time in
+ // nanos of the next range is
diff erent to the current one, just because of
+ // the definition of a NanosecondsRange.
+ return interpolate(
+ std::min(tsc_conversion.ToNanos(tsc + items_count), next_range->nanos));
+ }
+
+ // In this case, each item took less than 1 TSC, so some parallelism was
+ // achieved, which is an indication that we didn't suffered of any kind of
+ // interruption.
+ return interpolate(next_range->nanos);
}
-lldb::addr_t DecodedThread::GetInstructionLoadAddress(size_t item_index) const {
+uint64_t DecodedThread::GetItemsCount() const { return m_item_kinds.size(); }
+
+lldb::addr_t
+DecodedThread::GetInstructionLoadAddress(uint64_t item_index) const {
return m_item_data[item_index].load_address;
}
@@ -58,33 +112,69 @@ DecodedThread::TraceItemStorage &
DecodedThread::CreateNewTraceItem(lldb::TraceItemKind kind) {
m_item_kinds.push_back(kind);
m_item_data.emplace_back();
+ if (m_last_tsc)
+ (*m_last_tsc)->second.items_count++;
+ if (m_last_nanoseconds)
+ (*m_last_nanoseconds)->second.items_count++;
return m_item_data.back();
}
-void DecodedThread::NotifyTsc(uint64_t tsc) {
- if (!m_last_tsc || *m_last_tsc != tsc) {
- m_timestamps.emplace(m_item_kinds.size(), tsc);
- m_last_tsc = tsc;
+void DecodedThread::NotifyTsc(TSC tsc) {
+ if (m_last_tsc && (*m_last_tsc)->second.tsc == tsc)
+ return;
+
+ m_last_tsc =
+ m_tscs.emplace(GetItemsCount(), TSCRange{tsc, 0, GetItemsCount()}).first;
+
+ if (m_tsc_conversion) {
+ uint64_t nanos = m_tsc_conversion->ToNanos(tsc);
+ if (!m_last_nanoseconds || (*m_last_nanoseconds)->second.nanos != nanos) {
+ m_last_nanoseconds =
+ m_nanoseconds
+ .emplace(GetItemsCount(), NanosecondsRange{nanos, tsc, nullptr, 0,
+ GetItemsCount()})
+ .first;
+ if (*m_last_nanoseconds != m_nanoseconds.begin()) {
+ auto prev_range = prev(*m_last_nanoseconds);
+ prev_range->second.next_range = &(*m_last_nanoseconds)->second;
+ }
+ }
}
+ AppendEvent(lldb::eTraceEventHWClockTick);
}
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_cpus.emplace(GetItemsCount(), cpu_id);
m_last_cpu = cpu_id;
AppendEvent(lldb::eTraceEventCPUChanged);
}
}
Optional<lldb::cpu_id_t>
-DecodedThread::GetCPUByIndex(uint64_t insn_index) const {
- // Could possibly optimize the search
- auto it = m_cpus.upper_bound(insn_index);
+DecodedThread::GetCPUByIndex(uint64_t item_index) const {
+ auto it = m_cpus.upper_bound(item_index);
if (it == m_cpus.begin())
return None;
return prev(it)->second;
}
+Optional<DecodedThread::TSCRange>
+DecodedThread::GetTSCRangeByIndex(uint64_t item_index) const {
+ auto next_it = m_tscs.upper_bound(item_index);
+ if (next_it == m_tscs.begin())
+ return None;
+ return prev(next_it)->second;
+}
+
+Optional<DecodedThread::NanosecondsRange>
+DecodedThread::GetNanosecondsRangeByIndex(uint64_t item_index) {
+ auto next_it = m_nanoseconds.upper_bound(item_index);
+ if (next_it == m_nanoseconds.begin())
+ return None;
+ return prev(next_it)->second;
+}
+
void DecodedThread::AppendEvent(lldb::TraceEvent event) {
CreateNewTraceItem(lldb::eTraceItemKindEvent).event = event;
m_events_stats.RecordEvent(event);
@@ -134,90 +224,24 @@ void DecodedThread::EventsStats::RecordEvent(lldb::TraceEvent event) {
total_count++;
}
-Optional<DecodedThread::TscRange> DecodedThread::CalculateTscRange(
- size_t insn_index,
- const Optional<DecodedThread::TscRange> &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
- // arbitrary lookup.
- if (hint_range) {
- Optional<TscRange> candidate_range;
- if (insn_index < hint_range->GetStartInstructionIndex())
- candidate_range = hint_range->Prev();
- else if (insn_index > hint_range->GetEndInstructionIndex())
- candidate_range = hint_range->Next();
- else
- candidate_range = hint_range;
-
- if (candidate_range && candidate_range->InRange(insn_index))
- return candidate_range;
- }
- // Now we do a more expensive lookup
- auto it = m_timestamps.upper_bound(insn_index);
- if (it == m_timestamps.begin())
- return None;
-
- 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<lldb::TraceItemKind>(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<TraceCursorIntelPT>(m_thread_sp, shared_from_this());
-}
+DecodedThread::DecodedThread(
+ ThreadSP thread_sp,
+ const llvm::Optional<LinuxPerfZeroTscConversion> &tsc_conversion)
+ : m_thread_sp(thread_sp), m_tsc_conversion(tsc_conversion) {}
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_timestamps.size() +
- (sizeof(size_t) + sizeof(lldb::cpu_id_t)) * m_cpus.size();
-}
-
-DecodedThread::TscRange::TscRange(std::map<size_t, uint64_t>::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<uint64_t>::max()
- : next_it->first - 1;
-}
-
-size_t DecodedThread::TscRange::GetTsc() const { return m_it->second; }
-
-size_t DecodedThread::TscRange::GetStartInstructionIndex() const {
- return m_it->first;
-}
-
-size_t DecodedThread::TscRange::GetEndInstructionIndex() const {
- return m_end_index;
-}
-
-bool DecodedThread::TscRange::InRange(size_t insn_index) const {
- return GetStartInstructionIndex() <= insn_index &&
- insn_index <= GetEndInstructionIndex();
-}
-
-Optional<DecodedThread::TscRange> DecodedThread::TscRange::Next() const {
- auto next_it = m_it;
- ++next_it;
- if (next_it == m_decoded_thread->m_timestamps.end())
- return None;
- return TscRange(next_it, *m_decoded_thread);
-}
-
-Optional<DecodedThread::TscRange> DecodedThread::TscRange::Prev() const {
- if (m_it == m_decoded_thread->m_timestamps.begin())
- return None;
- auto prev_it = m_it;
- --prev_it;
- return TscRange(prev_it, *m_decoded_thread);
+ (sizeof(uint64_t) + sizeof(TSC)) * m_tscs.size() +
+ (sizeof(uint64_t) + sizeof(uint64_t)) * m_nanoseconds.size() +
+ (sizeof(uint64_t) + sizeof(lldb::cpu_id_t)) * m_cpus.size();
}
diff --git a/lldb/source/Plugins/Trace/intel-pt/DecodedThread.h b/lldb/source/Plugins/Trace/intel-pt/DecodedThread.h
index bd1a90aaf250..9376a0af169d 100644
--- a/lldb/source/Plugins/Trace/intel-pt/DecodedThread.h
+++ b/lldb/source/Plugins/Trace/intel-pt/DecodedThread.h
@@ -71,45 +71,7 @@ class IntelPTError : public llvm::ErrorInfo<IntelPTError> {
/// stopped at. See \a Trace::GetCursorPosition for more information.
class DecodedThread : public std::enable_shared_from_this<DecodedThread> {
public:
- /// \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
- /// decoded trace.
- ///
- /// TSC timestamps are emitted by the decoder infrequently, which means
- /// that each TSC covers a range of instruction indices, which can be used to
- /// speed up TSC lookups.
- class TscRange {
- public:
- /// Check if this TSC range includes the given instruction index.
- bool InRange(size_t insn_index) const;
-
- /// Get the next range chronologically.
- llvm::Optional<TscRange> Next() const;
-
- /// Get the previous range chronologically.
- llvm::Optional<TscRange> Prev() const;
-
- /// Get the TSC value.
- size_t GetTsc() const;
- /// Get the smallest instruction index that has this TSC.
- size_t GetStartInstructionIndex() const;
- /// Get the largest instruction index that has this TSC.
- size_t GetEndInstructionIndex() const;
-
- private:
- friend class DecodedThread;
-
- TscRange(std::map<size_t, uint64_t>::const_iterator it,
- const DecodedThread &decoded_thread);
-
- /// The iterator pointing to the beginning of the range.
- std::map<size_t, uint64_t>::const_iterator m_it;
- /// The largest instruction index that has this TSC.
- size_t m_end_index;
-
- const DecodedThread *m_decoded_thread;
- };
+ using TSC = uint64_t;
// Struct holding counts for libipts errors;
struct LibiptErrorsStats {
@@ -120,6 +82,61 @@ class DecodedThread : public std::enable_shared_from_this<DecodedThread> {
void RecordError(int libipt_error_code);
};
+ /// A structure that represents a maximal range of trace items associated to
+ /// the same TSC value.
+ struct TSCRange {
+ TSC tsc;
+ /// Number of trace items in this range.
+ uint64_t items_count;
+ /// Index of the first trace item in this range.
+ uint64_t first_item_index;
+
+ /// \return
+ /// \b true if and only if the given \p item_index is covered by this
+ /// range.
+ bool InRange(uint64_t item_index) const;
+ };
+
+ /// A structure that represents a maximal range of trace items associated to
+ /// the same non-interpolated timestamps in nanoseconds.
+ struct NanosecondsRange {
+ /// The nanoseconds value for this range.
+ uint64_t nanos;
+ /// The corresponding TSC value for this range.
+ TSC tsc;
+ /// A nullable pointer to the next range.
+ NanosecondsRange *next_range;
+ /// Number of trace items in this range.
+ uint64_t items_count;
+ /// Index of the first trace item in this range.
+ uint64_t first_item_index;
+
+ /// Calculate an interpolated timestamp in nanoseconds for the given item
+ /// index. It's guaranteed that two
diff erent item indices will produce
+ ///
diff erent interpolated values.
+ ///
+ /// \param[in] item_index
+ /// The index of the item whose timestamp will be estimated. It has to be
+ /// part of this range.
+ ///
+ /// \param[in] beginning_of_time_nanos
+ /// The timestamp at which tracing started.
+ ///
+ /// \param[in] tsc_conversion
+ /// The tsc -> nanos conversion utility
+ ///
+ /// \return
+ /// An interpolated timestamp value for the given trace item.
+ double
+ GetInterpolatedTime(uint64_t item_index, uint64_t beginning_of_time_nanos,
+ const LinuxPerfZeroTscConversion &tsc_conversion) const;
+
+ /// \return
+ /// \b true if and only if the given \p item_index is covered by this
+ /// range.
+ bool InRange(uint64_t item_index) const;
+ };
+
// Struct holding counts for events;
struct EventsStats {
/// A count for each individual event kind. We use an unordered map instead
@@ -130,39 +147,21 @@ class DecodedThread : public std::enable_shared_from_this<DecodedThread> {
void RecordEvent(lldb::TraceEvent event);
};
- DecodedThread(lldb::ThreadSP thread_sp);
-
- /// Utility constructor that initializes the trace with a provided error.
- DecodedThread(lldb::ThreadSP thread_sp, llvm::Error &&err);
+ DecodedThread(
+ lldb::ThreadSP thread_sp,
+ const llvm::Optional<LinuxPerfZeroTscConversion> &tsc_conversion);
/// Get the total number of instruction, errors and events from the decoded
/// trace.
- int64_t GetItemsCount() const;
-
- /// Construct the TSC range that covers the given instruction index.
- /// This operation is O(logn) and should be used sparingly.
- /// If the trace was collected with TSC support, all the instructions of
- /// the trace will have associated TSCs. This means that this method will
- /// only return \b llvm::None if there are no TSCs whatsoever in the trace.
- ///
- /// \param[in] insn_index
- /// The instruction index in question.
- ///
- /// \param[in] hint_range
- /// An optional range that might include the given index or might be a
- /// neighbor of it. It might help speed it traversals of the trace with
- /// short jumps.
- llvm::Optional<TscRange> CalculateTscRange(
- size_t insn_index,
- const llvm::Optional<DecodedThread::TscRange> &hint_range) const;
+ uint64_t GetItemsCount() 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.
@@ -177,12 +176,31 @@ class DecodedThread : public std::enable_shared_from_this<DecodedThread> {
/// The requested cpu id, or \a llvm::None if not available.
llvm::Optional<lldb::cpu_id_t> GetCPUByIndex(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.
+ ///
+ /// \param[in] item_index
+ /// The trace item index to compare with.
+ ///
+ /// \return
+ /// The requested TSC range, or \a llvm::None if not available.
+ llvm::Optional<DecodedThread::TSCRange>
+ GetTSCRangeByIndex(uint64_t item_index) const;
+
+ /// Get a maximal range of trace items that include the given \p item_index
+ /// that have the same nanoseconds timestamp without interpolation.
+ ///
+ /// \param[in] item_index
+ /// The trace item index to compare with.
+ ///
+ /// \return
+ /// The requested nanoseconds range, or \a llvm::None if not available.
+ llvm::Optional<DecodedThread::NanosecondsRange>
+ GetNanosecondsRangeByIndex(uint64_t item_index);
+
/// \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 +232,7 @@ class DecodedThread : public std::enable_shared_from_this<DecodedThread> {
/// 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.
@@ -262,15 +280,22 @@ class DecodedThread : public std::enable_shared_from_this<DecodedThread> {
/// it in TraceItemStorage to avoid padding.
std::vector<uint8_t> m_item_kinds;
- /// This map contains the TSCs of the decoded instructions. It maps
- /// `instruction index -> TSC`, where `instruction index` is the first index
- /// at which the mapped TSC appears. We use this representation because TSCs
- /// 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<uint64_t, uint64_t> m_timestamps;
+ /// This map contains the TSCs of the decoded trace items. It maps
+ /// `item index -> TSC`, where `item index` is the first index
+ /// at which the mapped TSC first appears. We use this representation because
+ /// TSCs are sporadic and we can think of them as ranges.
+ std::map<uint64_t, TSCRange> m_tscs;
/// This is the chronologically last TSC that has been added.
- llvm::Optional<uint64_t> m_last_tsc = llvm::None;
+ llvm::Optional<std::map<uint64_t, TSCRange>::iterator> m_last_tsc =
+ llvm::None;
+ /// This map contains the non-interpolated nanoseconds timestamps of the
+ /// decoded trace items. It maps `item index -> nanoseconds`, where `item
+ /// index` is the first index at which the mapped nanoseconds first appears.
+ /// We use this representation because timestamps are sporadic and we think of
+ /// them as ranges.
+ std::map<uint64_t, NanosecondsRange> m_nanoseconds;
+ 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`
// A CPU is associated with the next instructions that follow until the next
@@ -279,6 +304,9 @@ class DecodedThread : public std::enable_shared_from_this<DecodedThread> {
/// This is the chronologically last CPU ID.
llvm::Optional<uint64_t> m_last_cpu = llvm::None;
+ /// 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.
diff --git a/lldb/source/Plugins/Trace/intel-pt/LibiptDecoder.cpp b/lldb/source/Plugins/Trace/intel-pt/LibiptDecoder.cpp
index a98337a4e058..234b9f917d32 100644
--- a/lldb/source/Plugins/Trace/intel-pt/LibiptDecoder.cpp
+++ b/lldb/source/Plugins/Trace/intel-pt/LibiptDecoder.cpp
@@ -285,9 +285,23 @@ Error lldb_private::trace_intel_pt::DecodeSystemWideTraceForThread(
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;
+ // We report the TSCs we are sure of
+ switch (variant) {
+ case ThreadContinuousExecution::Variant::Complete:
+ decoded_thread.NotifyTsc(execution.thread_execution.tscs.complete.start);
+ break;
+ case ThreadContinuousExecution::Variant::OnlyStart:
+ decoded_thread.NotifyTsc(
+ execution.thread_execution.tscs.only_start.start);
+ break;
+ default:
+ break;
+ }
+
+ decoded_thread.NotifyCPU(execution.thread_execution.cpu_id);
+
// If we haven't seen a PSB yet, then it's fine not to show errors
if (has_seen_psbs) {
if (execution.intelpt_subtraces.empty()) {
@@ -299,12 +313,12 @@ Error lldb_private::trace_intel_pt::DecodeSystemWideTraceForThread(
}
// If the first execution is incomplete because it doesn't have a previous
- // context switch in its cpu, all good.
+ // context switch in its cpu, all good, otherwise we report the error.
if (variant == ThreadContinuousExecution::Variant::OnlyEnd ||
variant == ThreadContinuousExecution::Variant::HintedStart) {
decoded_thread.AppendCustomError(
- formatv("Thread execution starting on cpu id = {0} doesn't "
- "have a matching context switch in.",
+ formatv("Unable to find the context switch in for the thread "
+ "execution starting on cpu id = {0}",
execution.thread_execution.cpu_id)
.str());
}
@@ -318,6 +332,18 @@ Error lldb_private::trace_intel_pt::DecodeSystemWideTraceForThread(
decoder.DecodePSB(intel_pt_execution.psb_offset);
}
+ // We report the TSCs we are sure of
+ switch (variant) {
+ case ThreadContinuousExecution::Variant::Complete:
+ decoded_thread.NotifyTsc(execution.thread_execution.tscs.complete.end);
+ break;
+ case ThreadContinuousExecution::Variant::OnlyEnd:
+ decoded_thread.NotifyTsc(execution.thread_execution.tscs.only_end.end);
+ break;
+ default:
+ break;
+ }
+
// If we haven't seen a PSB yet, then it's fine not to show errors
if (has_seen_psbs) {
// If the last execution is incomplete because it doesn't have a following
@@ -326,8 +352,8 @@ Error lldb_private::trace_intel_pt::DecodeSystemWideTraceForThread(
i + 1 != executions.size()) ||
variant == ThreadContinuousExecution::Variant::HintedEnd) {
decoded_thread.AppendCustomError(
- formatv("Thread execution on cpu id = {0} doesn't have a "
- "matching context switch out",
+ formatv("Unable to find the context switch out for the thread "
+ "execution on cpu id = {0}",
execution.thread_execution.cpu_id)
.str());
}
@@ -380,3 +406,22 @@ lldb_private::trace_intel_pt::SplitTraceInContinuousExecutions(
}
return executions;
}
+
+Expected<Optional<uint64_t>>
+lldb_private::trace_intel_pt::FindLowestTSCInTrace(TraceIntelPT &trace_intel_pt,
+ ArrayRef<uint8_t> buffer) {
+ Expected<PtInsnDecoderUP> decoder_up =
+ CreateInstructionDecoder(trace_intel_pt, buffer);
+ if (!decoder_up)
+ return decoder_up.takeError();
+
+ pt_insn_decoder *decoder = decoder_up.get().get();
+ int status = pte_ok;
+ if (IsLibiptError(status = pt_insn_sync_forward(decoder)))
+ return None;
+
+ uint64_t tsc;
+ if (IsLibiptError(pt_insn_time(decoder, &tsc, nullptr, nullptr)))
+ return None;
+ return tsc;
+}
diff --git a/lldb/source/Plugins/Trace/intel-pt/LibiptDecoder.h b/lldb/source/Plugins/Trace/intel-pt/LibiptDecoder.h
index cad4d39fcf24..66f3798cd600 100644
--- a/lldb/source/Plugins/Trace/intel-pt/LibiptDecoder.h
+++ b/lldb/source/Plugins/Trace/intel-pt/LibiptDecoder.h
@@ -94,6 +94,16 @@ llvm::Expected<std::vector<IntelPTThreadSubtrace>>
SplitTraceInContinuousExecutions(TraceIntelPT &trace_intel_pt,
llvm::ArrayRef<uint8_t> buffer);
+/// Find the lowest TSC in the given trace.
+///
+/// \return
+/// The lowest TSC value in this trace if available, \a llvm::None if the
+/// trace is empty or the trace contains no timing information, or an \a
+/// llvm::Error if it was not possible to set up the decoder.
+llvm::Expected<llvm::Optional<uint64_t>>
+FindLowestTSCInTrace(TraceIntelPT &trace_intel_pt,
+ llvm::ArrayRef<uint8_t> buffer);
+
} // namespace trace_intel_pt
} // namespace lldb_private
diff --git a/lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.cpp b/lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.cpp
index d3ac61f7e658..920992d9d636 100644
--- a/lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.cpp
+++ b/lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.cpp
@@ -23,6 +23,21 @@ using namespace llvm;
ThreadDecoder::ThreadDecoder(const ThreadSP &thread_sp, TraceIntelPT &trace)
: m_thread_sp(thread_sp), m_trace(trace) {}
+Expected<Optional<uint64_t>> ThreadDecoder::FindLowestTSC() {
+ Optional<uint64_t> lowest_tsc;
+ Error err = m_trace.OnThreadBufferRead(
+ m_thread_sp->GetID(), [&](llvm::ArrayRef<uint8_t> data) -> llvm::Error {
+ Expected<Optional<uint64_t>> tsc = FindLowestTSCInTrace(m_trace, data);
+ if (!tsc)
+ return tsc.takeError();
+ lowest_tsc = *tsc;
+ return Error::success();
+ });
+ if (err)
+ return std::move(err);
+ return lowest_tsc;
+}
+
Expected<DecodedThreadSP> ThreadDecoder::Decode() {
if (!m_decoded_thread.hasValue()) {
if (Expected<DecodedThreadSP> decoded_thread = DoDecode()) {
@@ -38,8 +53,8 @@ llvm::Expected<DecodedThreadSP> ThreadDecoder::DoDecode() {
return m_trace.GetThreadTimer(m_thread_sp->GetID())
.TimeTask(
"Decoding instructions", [&]() -> Expected<DecodedThreadSP> {
- DecodedThreadSP decoded_thread_sp =
- std::make_shared<DecodedThread>(m_thread_sp);
+ DecodedThreadSP decoded_thread_sp = std::make_shared<DecodedThread>(
+ m_thread_sp, m_trace.GetPerfZeroTscConversion());
Error err = m_trace.OnThreadBufferRead(
m_thread_sp->GetID(), [&](llvm::ArrayRef<uint8_t> data) {
diff --git a/lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.h b/lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.h
index 5c77ad93d27a..d580bc4dd335 100644
--- a/lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.h
+++ b/lldb/source/Plugins/Trace/intel-pt/ThreadDecoder.h
@@ -36,6 +36,12 @@ class ThreadDecoder {
/// A \a DecodedThread instance.
llvm::Expected<DecodedThreadSP> Decode();
+ /// \return
+ /// The lowest TSC value in this trace if available, \a llvm::None if the
+ /// trace is empty or the trace contains no timing information, or an \a
+ /// llvm::Error if it was not possible to set up the decoder.
+ llvm::Expected<llvm::Optional<uint64_t>> FindLowestTSC();
+
ThreadDecoder(const ThreadDecoder &other) = delete;
ThreadDecoder &operator=(const ThreadDecoder &other) = delete;
diff --git a/lldb/source/Plugins/Trace/intel-pt/TraceCursorIntelPT.cpp b/lldb/source/Plugins/Trace/intel-pt/TraceCursorIntelPT.cpp
index 185c02b6bcd9..a4d86fb48ebe 100644
--- a/lldb/source/Plugins/Trace/intel-pt/TraceCursorIntelPT.cpp
+++ b/lldb/source/Plugins/Trace/intel-pt/TraceCursorIntelPT.cpp
@@ -17,28 +17,55 @@ using namespace lldb_private;
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 Optional<LinuxPerfZeroTscConversion> &tsc_conversion,
+ Optional<uint64_t> beginning_of_time_nanos)
+ : TraceCursor(thread_sp), m_decoded_thread_sp(decoded_thread_sp),
+ m_tsc_conversion(tsc_conversion),
+ m_beginning_of_time_nanos(beginning_of_time_nanos) {
Seek(0, SeekType::End);
}
-void TraceCursorIntelPT::CalculateTscRange() {
- // If we failed, then we look for the exact range
- if (!m_tsc_range || !m_tsc_range->InRange(m_pos))
- m_tsc_range = m_decoded_thread_sp->CalculateTscRange(
- m_pos, /*hit_range=*/m_tsc_range);
-}
-
void TraceCursorIntelPT::Next() {
m_pos += IsForwards() ? 1 : -1;
+ ClearTimingRangesIfInvalid();
+}
+
+void TraceCursorIntelPT::ClearTimingRangesIfInvalid() {
+ if (m_tsc_range_calculated) {
+ if (!m_tsc_range || m_pos < 0 || !m_tsc_range->InRange(m_pos)) {
+ m_tsc_range = None;
+ m_tsc_range_calculated = false;
+ }
+ }
+
+ if (m_nanoseconds_range_calculated) {
+ if (!m_nanoseconds_range || m_pos < 0 ||
+ !m_nanoseconds_range->InRange(m_pos)) {
+ m_nanoseconds_range = None;
+ m_nanoseconds_range_calculated = false;
+ }
+ }
+}
- // We try to go to a neighbor tsc range that might contain the current pos
- if (m_tsc_range && !m_tsc_range->InRange(m_pos))
- m_tsc_range = IsForwards() ? m_tsc_range->Next() : m_tsc_range->Prev();
+const Optional<DecodedThread::TSCRange> &
+TraceCursorIntelPT::GetTSCRange() const {
+ if (!m_tsc_range_calculated) {
+ m_tsc_range_calculated = true;
+ m_tsc_range = m_decoded_thread_sp->GetTSCRangeByIndex(m_pos);
+ }
+ return m_tsc_range;
+}
- // If we failed, this call will fix it
- CalculateTscRange();
+const Optional<DecodedThread::NanosecondsRange> &
+TraceCursorIntelPT::GetNanosecondsRange() const {
+ if (!m_nanoseconds_range_calculated) {
+ m_nanoseconds_range_calculated = true;
+ m_nanoseconds_range =
+ m_decoded_thread_sp->GetNanosecondsRangeByIndex(m_pos);
+ }
+ return m_nanoseconds_range;
}
bool TraceCursorIntelPT::Seek(int64_t offset, SeekType origin) {
@@ -52,13 +79,15 @@ bool TraceCursorIntelPT::Seek(int64_t offset, SeekType origin) {
case TraceCursor::SeekType::Current:
m_pos += offset;
}
- CalculateTscRange();
+
+ ClearTimingRangesIfInvalid();
return HasValue();
}
bool TraceCursorIntelPT::HasValue() const {
- return m_pos >= 0 && m_pos < m_decoded_thread_sp->GetItemsCount();
+ return m_pos >= 0 &&
+ static_cast<uint64_t>(m_pos) < m_decoded_thread_sp->GetItemsCount();
}
lldb::TraceItemKind TraceCursorIntelPT::GetItemKind() const {
@@ -73,15 +102,18 @@ lldb::addr_t TraceCursorIntelPT::GetLoadAddress() const {
return m_decoded_thread_sp->GetInstructionLoadAddress(m_pos);
}
-Optional<uint64_t>
-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<uint64_t> TraceCursorIntelPT::GetHWClock() const {
+ if (const Optional<DecodedThread::TSCRange> &range = GetTSCRange())
+ return range->tsc;
+ return None;
+}
+
+Optional<double> TraceCursorIntelPT::GetWallClockTime() const {
+ if (const Optional<DecodedThread::NanosecondsRange> &range =
+ GetNanosecondsRange())
+ return range->GetInterpolatedTime(m_pos, *m_beginning_of_time_nanos,
+ *m_tsc_conversion);
+ return None;
}
Optional<lldb::cpu_id_t> TraceCursorIntelPT::GetCPU() const {
@@ -96,13 +128,12 @@ bool TraceCursorIntelPT::GoToId(user_id_t id) {
if (!HasId(id))
return false;
m_pos = id;
- m_tsc_range = m_decoded_thread_sp->CalculateTscRange(m_pos, m_tsc_range);
-
+ ClearTimingRangesIfInvalid();
return true;
}
bool TraceCursorIntelPT::HasId(lldb::user_id_t id) const {
- return static_cast<int64_t>(id) < m_decoded_thread_sp->GetItemsCount();
+ return id < m_decoded_thread_sp->GetItemsCount();
}
user_id_t TraceCursorIntelPT::GetId() const { return m_pos; }
diff --git a/lldb/source/Plugins/Trace/intel-pt/TraceCursorIntelPT.h b/lldb/source/Plugins/Trace/intel-pt/TraceCursorIntelPT.h
index 2e0f67e67dfc..3cd9ab831f5e 100644
--- a/lldb/source/Plugins/Trace/intel-pt/TraceCursorIntelPT.h
+++ b/lldb/source/Plugins/Trace/intel-pt/TraceCursorIntelPT.h
@@ -16,8 +16,10 @@ namespace trace_intel_pt {
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<LinuxPerfZeroTscConversion> &tsc_conversion,
+ llvm::Optional<uint64_t> beginning_of_time_nanos);
bool Seek(int64_t offset, SeekType origin) override;
@@ -29,13 +31,12 @@ class TraceCursorIntelPT : public TraceCursor {
lldb::addr_t GetLoadAddress() const override;
- llvm::Optional<uint64_t>
- GetCounter(lldb::TraceCounter counter_type) const override;
-
lldb::TraceEvent GetEventType() const override;
llvm::Optional<lldb::cpu_id_t> GetCPU() const override;
+ llvm::Optional<uint64_t> GetHWClock() const override;
+
lldb::TraceItemKind GetItemKind() const override;
bool GoToId(lldb::user_id_t id) override;
@@ -44,16 +45,43 @@ class TraceCursorIntelPT : public TraceCursor {
bool HasId(lldb::user_id_t id) const override;
+ llvm::Optional<double> GetWallClockTime() const override;
+
private:
- /// Calculate the tsc range for the current position if needed.
- void CalculateTscRange();
+ /// Clear the current TSC and nanoseconds ranges if after moving they are not
+ /// valid anymore.
+ void ClearTimingRangesIfInvalid();
+
+ /// Get or calculate the TSC range that includes the current trace item.
+ const llvm::Optional<DecodedThread::TSCRange> &GetTSCRange() const;
+
+ /// Get or calculate the TSC range that includes the current trace item.
+ const llvm::Optional<DecodedThread::NanosecondsRange> &
+ GetNanosecondsRange() const;
/// Storage of the actual instructions
DecodedThreadSP m_decoded_thread_sp;
/// Internal instruction index currently pointing at.
int64_t m_pos;
- /// Tsc range covering the current instruction.
- llvm::Optional<DecodedThread::TscRange> m_tsc_range;
+
+ /// Timing information and cached values.
+ /// \{
+
+ /// TSC -> nanos conversion utility. \a None if not available at all.
+ llvm::Optional<LinuxPerfZeroTscConversion> m_tsc_conversion;
+ /// Lowest nanoseconds timestamp seen in any thread trace, \a None if not
+ /// available at all.
+ llvm::Optional<uint64_t> m_beginning_of_time_nanos;
+ /// Range of trace items with the same TSC that includes the current trace
+ /// item, \a None if not calculated or not available.
+ llvm::Optional<DecodedThread::TSCRange> mutable m_tsc_range;
+ bool mutable m_tsc_range_calculated = false;
+ /// Range of trace items with the same non-interpolated timestamps in
+ /// nanoseconds that includes the current trace item, \a None if not
+ /// calculated or not available.
+ llvm::Optional<DecodedThread::NanosecondsRange> mutable m_nanoseconds_range;
+ bool mutable m_nanoseconds_range_calculated = false;
+ /// \}
};
} // namespace trace_intel_pt
diff --git a/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.cpp b/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.cpp
index 57433ffb14cb..f3f0a513e3fa 100644
--- 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"
@@ -138,11 +140,53 @@ Expected<DecodedThreadSP> TraceIntelPT::Decode(Thread &thread) {
return it->second->Decode();
}
+Expected<Optional<uint64_t>> TraceIntelPT::FindBeginningOfTimeNanos() {
+ Storage &storage = GetUpdatedStorage();
+ if (storage.beginning_of_time_nanos_calculated)
+ return storage.beginning_of_time_nanos;
+ storage.beginning_of_time_nanos_calculated = true;
+
+ if (!storage.tsc_conversion)
+ return None;
+
+ Optional<uint64_t> lowest_tsc;
+
+ if (storage.multicpu_decoder) {
+ if (Expected<Optional<uint64_t>> tsc =
+ storage.multicpu_decoder->FindLowestTSC()) {
+ lowest_tsc = *tsc;
+ } else {
+ return tsc.takeError();
+ }
+ }
+
+ for (auto &decoder : storage.thread_decoders) {
+ Expected<Optional<uint64_t>> tsc = decoder.second->FindLowestTSC();
+ if (!tsc)
+ return tsc.takeError();
+
+ if (*tsc && (!lowest_tsc || *lowest_tsc > **tsc))
+ lowest_tsc = **tsc;
+ }
+
+ if (lowest_tsc) {
+ storage.beginning_of_time_nanos =
+ storage.tsc_conversion->ToNanos(*lowest_tsc);
+ }
+ return storage.beginning_of_time_nanos;
+}
+
llvm::Expected<lldb::TraceCursorUP>
TraceIntelPT::CreateNewCursor(Thread &thread) {
- if (Expected<DecodedThreadSP> decoded_thread = Decode(thread))
- return decoded_thread.get()->CreateNewCursor();
- else
+ if (Expected<DecodedThreadSP> decoded_thread = Decode(thread)) {
+ if (Expected<Optional<uint64_t>> beginning_of_time =
+ FindBeginningOfTimeNanos())
+ return std::make_unique<TraceCursorIntelPT>(
+ thread.shared_from_this(), *decoded_thread, m_storage.tsc_conversion,
+ *beginning_of_time);
+ else
+ return beginning_of_time.takeError();
+ } else
return decoded_thread.takeError();
}
diff --git a/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.h b/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.h
index d3e58374867d..7f2c3f8dda5d 100644
--- a/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.h
+++ b/lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.h
@@ -220,6 +220,13 @@ class TraceIntelPT : public Trace {
/// returned if the decoder couldn't be properly set up.
llvm::Expected<DecodedThreadSP> Decode(Thread &thread);
+ /// \return
+ /// The lowest timestamp in nanoseconds in all traces if available, \a
+ /// llvm::None if all the traces were empty or no trace contained no
+ /// timing information, or an \a llvm::Error if it was not possible to set
+ /// up the decoder for some trace.
+ llvm::Expected<llvm::Optional<uint64_t>> FindBeginningOfTimeNanos();
+
// Dump out trace info in JSON format
void DumpTraceInfoAsJson(Thread &thread, Stream &s, bool verbose);
@@ -236,6 +243,8 @@ class TraceIntelPT : public Trace {
/// It is provided by either a trace bundle or a live process to convert TSC
/// counters to and from nanos. It might not be available on all hosts.
llvm::Optional<LinuxPerfZeroTscConversion> tsc_conversion;
+ llvm::Optional<uint64_t> beginning_of_time_nanos;
+ bool beginning_of_time_nanos_calculated = false;
} m_storage;
/// It is provided by either a trace bundle or a live process' "cpuInfo"
diff --git a/lldb/source/Plugins/Trace/intel-pt/TraceIntelPTMultiCpuDecoder.cpp b/lldb/source/Plugins/Trace/intel-pt/TraceIntelPTMultiCpuDecoder.cpp
index e547032f739d..08f54b582e3f 100644
--- a/lldb/source/Plugins/Trace/intel-pt/TraceIntelPTMultiCpuDecoder.cpp
+++ b/lldb/source/Plugins/Trace/intel-pt/TraceIntelPTMultiCpuDecoder.cpp
@@ -35,6 +35,28 @@ bool TraceIntelPTMultiCpuDecoder::TracesThread(lldb::tid_t tid) const {
return m_tids.count(tid);
}
+Expected<Optional<uint64_t>> TraceIntelPTMultiCpuDecoder::FindLowestTSC() {
+ Optional<uint64_t> lowest_tsc;
+ TraceIntelPTSP trace_sp = GetTrace();
+
+ Error err = GetTrace()->OnAllCpusBinaryDataRead(
+ IntelPTDataKinds::kIptTrace,
+ [&](const DenseMap<cpu_id_t, ArrayRef<uint8_t>> &buffers) -> Error {
+ for (auto &cpu_id_to_buffer : buffers) {
+ Expected<Optional<uint64_t>> tsc =
+ FindLowestTSCInTrace(*trace_sp, cpu_id_to_buffer.second);
+ if (!tsc)
+ return tsc.takeError();
+ if (*tsc && (!lowest_tsc || *lowest_tsc > **tsc))
+ lowest_tsc = **tsc;
+ }
+ return Error::success();
+ });
+ if (err)
+ return std::move(err);
+ return lowest_tsc;
+}
+
Expected<DecodedThreadSP> TraceIntelPTMultiCpuDecoder::Decode(Thread &thread) {
if (Error err = CorrelateContextSwitchesAndIntelPtTraces())
return std::move(err);
@@ -48,8 +70,8 @@ Expected<DecodedThreadSP> TraceIntelPTMultiCpuDecoder::Decode(Thread &thread) {
if (it != m_decoded_threads.end())
return it->second;
- DecodedThreadSP decoded_thread_sp =
- std::make_shared<DecodedThread>(thread.shared_from_this());
+ DecodedThreadSP decoded_thread_sp = std::make_shared<DecodedThread>(
+ thread.shared_from_this(), trace_sp->GetPerfZeroTscConversion());
Error err = trace_sp->OnAllCpusBinaryDataRead(
IntelPTDataKinds::kIptTrace,
diff --git a/lldb/source/Plugins/Trace/intel-pt/TraceIntelPTMultiCpuDecoder.h b/lldb/source/Plugins/Trace/intel-pt/TraceIntelPTMultiCpuDecoder.h
index 3b7926760f3c..87c370e88ae6 100644
--- a/lldb/source/Plugins/Trace/intel-pt/TraceIntelPTMultiCpuDecoder.h
+++ b/lldb/source/Plugins/Trace/intel-pt/TraceIntelPTMultiCpuDecoder.h
@@ -66,6 +66,12 @@ class TraceIntelPTMultiCpuDecoder {
/// The total number of PSB blocks in all cores.
size_t GetTotalPSBBlocksCount() const;
+ /// \return
+ /// The lowest TSC value in this trace if available, \a llvm::None if the
+ /// trace is empty or the trace contains no timing information, or an \a
+ /// llvm::Error if it was not possible to set up the decoder.
+ llvm::Expected<llvm::Optional<uint64_t>> FindLowestTSC();
+
private:
/// Traverse the context switch traces and the basic intel pt continuous
/// subtraces and produce a list of continuous executions for each process and
diff --git a/lldb/source/Target/TraceCursor.cpp b/lldb/source/Target/TraceCursor.cpp
index f99b0d28c154..de3f9bf1b33d 100644
--- a/lldb/source/Target/TraceCursor.cpp
+++ b/lldb/source/Target/TraceCursor.cpp
@@ -50,6 +50,8 @@ const char *TraceCursor::EventKindToString(lldb::TraceEvent event_kind) {
return "software disabled tracing";
case lldb::eTraceEventCPUChanged:
return "CPU core changed";
+ case lldb::eTraceEventHWClockTick:
+ return "HW clock tick";
}
llvm_unreachable("Fully covered switch above");
}
diff --git a/lldb/source/Target/TraceDumper.cpp b/lldb/source/Target/TraceDumper.cpp
index c9ef3aa5bd6b..5b71e9e4e97a 100644
--- a/lldb/source/Target/TraceDumper.cpp
+++ b/lldb/source/Target/TraceDumper.cpp
@@ -128,16 +128,26 @@ class OutputWriterCLI : public TraceDumper::OutputWriter {
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
+ ? formatv("{0:3} ns", *item.timestamp).str()
+ : "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 @@ class OutputWriterJSON : public TraceDumper::OutputWriter {
| {
"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 @@ class OutputWriterJSON : public TraceDumper::OutputWriter {
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 @@ class OutputWriterJSON : public TraceDumper::OutputWriter {
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::string>(std::to_string(*item.tsc)) : None);
+ if (m_options.show_timestamps)
+ m_j.attribute("timestamp_ns", item.timestamp
+ ? Optional<std::string>(
+ std::to_string(*item.timestamp))
+ : None);
if (item.event) {
DumpEvent(item);
@@ -289,8 +310,8 @@ TraceDumper::TraceItem TraceDumper::CreatRawTraceItem() {
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 @@ Optional<lldb::user_id_t> TraceDumper::DumpInstructions(size_t count) {
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 {
diff --git a/lldb/test/API/commands/trace/TestTraceEvents.py b/lldb/test/API/commands/trace/TestTraceEvents.py
index 83d6677a2ae2..11d00f1d6309 100644
--- a/lldb/test/API/commands/trace/TestTraceEvents.py
+++ b/lldb/test/API/commands/trace/TestTraceEvents.py
@@ -13,12 +13,19 @@ def testCPUEvents(self):
self.expect("thread trace dump instructions 3 -e --forward -c 5",
substrs=['''thread #3: tid = 3497496
- 0: (event) CPU core changed [new CPU=51]
+ 0: (event) HW clock tick [40450075477621505]
+ 1: (event) CPU core changed [new CPU=51]
+ 2: (event) HW clock tick [40450075477657246]
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": "HW clock tick",
+ "hwClock": 40450075477621505
+ },
+ {
+ "id": 1,
"event": "CPU core changed",
"cpuId": 51
}'''])
diff --git a/lldb/test/API/commands/trace/TestTraceLoad.py b/lldb/test/API/commands/trace/TestTraceLoad.py
index 6a4c82d99f77..3e5488a13d92 100644
--- a/lldb/test/API/commands/trace/TestTraceLoad.py
+++ b/lldb/test/API/commands/trace/TestTraceLoad.py
@@ -13,11 +13,11 @@ def testLoadMultiCoreTrace(self):
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=["19523: [tsc=40450075478109270] (error) expected tracing enabled event",
+ substrs=["19531: [20456511.000 ns] (error) expected tracing enabled event",
"m.out`foo() + 65 at multi_thread.cpp:12:21",
- "19521: [tsc=40450075477657246] 0x0000000000400ba7 jg 0x400bb3"])
+ "19523: [19691630.216 ns] 0x0000000000400ba7 jg 0x400bb3"])
self.expect("thread trace dump instructions 3 -t",
- substrs=["67912: [tsc=40450075477799536] 0x0000000000400bd7 addl $0x1, -0x4(%rbp)",
+ substrs=["67919: [19736130.084 ns] 0x0000000000400bd7 addl $0x1, -0x4(%rbp)",
"m.out`bar() + 26 at multi_thread.cpp:20:6"])
self.expect("thread trace dump info --json",
@@ -60,17 +60,18 @@ def testLoadMultiCoreTrace(self):
"traceTechnology": "intel-pt",
"threadStats": {
"tid": 3497496,
- "traceItemsCount": 19524,
+ "traceItemsCount": 19533,
"memoryUsage": {
- "totalInBytes": "175760",
+ "totalInBytes": "176097",
"avgPerItemInBytes": 9.''', '''},
"timingInSeconds": {
"Decoding instructions": ''', '''
},
"events": {
- "totalCount": 2,
+ "totalCount": 11,
"individualCounts": {
"software disabled tracing": 1,
+ "HW clock tick": 9,
"CPU core changed": 1
}
},
@@ -110,11 +111,11 @@ def testLoadCompactMultiCoreTrace(self):
# we'll load the compact trace and make sure it works
self.traceLoad(os.path.join(compact_trace_bundle_dir, "trace.json"), substrs=["intel-pt"])
self.expect("thread trace dump instructions 2 -t",
- substrs=["19523: [tsc=40450075478109270] (error) expected tracing enabled event",
+ substrs=["19531: [20456511.000 ns] (error) expected tracing enabled event",
"m.out`foo() + 65 at multi_thread.cpp:12:21",
- "19521: [tsc=40450075477657246] 0x0000000000400ba7 jg 0x400bb3"])
+ "19523: [19691630.216 ns] 0x0000000000400ba7 jg 0x400bb3"])
self.expect("thread trace dump instructions 3 -t",
- substrs=["67912: [tsc=40450075477799536] 0x0000000000400bd7 addl $0x1, -0x4(%rbp)",
+ substrs=["67919: [19736130.084 ns] 0x0000000000400bd7 addl $0x1, -0x4(%rbp)",
"m.out`bar() + 26 at multi_thread.cpp:20:6"])
# This reduced the number of continuous executions to look at
@@ -129,11 +130,11 @@ def testLoadMultiCoreTraceWithStringNumbers(self):
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=["19523: [tsc=40450075478109270] (error) expected tracing enabled event",
+ substrs=["19531: [20456511.000 ns] (error) expected tracing enabled event",
"m.out`foo() + 65 at multi_thread.cpp:12:21",
- "19521: [tsc=40450075477657246] 0x0000000000400ba7 jg 0x400bb3"])
+ "19523: [19691630.216 ns] 0x0000000000400ba7 jg 0x400bb3"])
self.expect("thread trace dump instructions 3 -t",
- substrs=["67912: [tsc=40450075477799536] 0x0000000000400bd7 addl $0x1, -0x4(%rbp)",
+ substrs=["67919: [19736130.084 ns] 0x0000000000400bd7 addl $0x1, -0x4(%rbp)",
"m.out`bar() + 26 at multi_thread.cpp:20:6"])
@testSBAPIAndCommands
@@ -142,11 +143,11 @@ def testLoadMultiCoreTraceWithMissingThreads(self):
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=["19523: [tsc=40450075478109270] (error) expected tracing enabled event",
+ substrs=["19531: [20456511.000 ns] (error) expected tracing enabled event",
"m.out`foo() + 65 at multi_thread.cpp:12:21",
- "19521: [tsc=40450075477657246] 0x0000000000400ba7 jg 0x400bb3"])
+ "19523: [19691630.216 ns] 0x0000000000400ba7 jg 0x400bb3"])
self.expect("thread trace dump instructions 2 -t",
- substrs=["67912: [tsc=40450075477799536] 0x0000000000400bd7 addl $0x1, -0x4(%rbp)",
+ substrs=["67919: [19736130.084 ns] 0x0000000000400bd7 addl $0x1, -0x4(%rbp)",
"m.out`bar() + 26 at multi_thread.cpp:20:6"])
@testSBAPIAndCommands
diff --git a/lldb/test/API/commands/trace/TestTraceTSC.py b/lldb/test/API/commands/trace/TestTraceTSC.py
index 619deb32d191..5d2e69bf4af2 100644
--- a/lldb/test/API/commands/trace/TestTraceTSC.py
+++ b/lldb/test/API/commands/trace/TestTraceTSC.py
@@ -16,8 +16,8 @@ def testTscPerThread(self):
self.traceStartThread(enableTsc=True)
self.expect("n")
- self.expect("thread trace dump instructions --tsc -c 1",
- patterns=["0: \[tsc=\d+\] 0x0000000000400511 movl"])
+ self.expect("thread trace dump instructions -t -c 1",
+ patterns=[": \[\d+.\d+ ns\] 0x0000000000400511 movl"])
@testSBAPIAndCommands
@skipIf(oslist=no_match(['linux']), archs=no_match(['i386', 'x86_64']))
@@ -34,18 +34,18 @@ def testMultipleTscsPerThread(self):
self.expect("si")
# We'll get the most recent instructions, with at least 3
diff erent TSCs
- self.runCmd("thread trace dump instructions --tsc --raw --forward")
- id_to_tsc = {}
+ self.runCmd("thread trace dump instructions -t --raw --forward")
+ id_to_timestamp = {}
for line in self.res.GetOutput().splitlines():
- m = re.search(" (.+): \[tsc=(.+)\].*", line)
+ m = re.search(" (.+): \[(.+)\ ns].*", line)
if m:
- id_to_tsc[int(m.group(1))] = m.group(2)
- self.assertEqual(len(id_to_tsc), 3)
+ id_to_timestamp[int(m.group(1))] = m.group(2)
+ self.assertEqual(len(id_to_timestamp), 3)
# We check that the values are right when dumping a specific id
- for id, tsc in id_to_tsc.items():
- self.expect(f"thread trace dump instructions --tsc --id {id} -c 1",
- substrs=[f"{id}: [tsc={tsc}"])
+ for id, timestamp in id_to_timestamp.items():
+ self.expect(f"thread trace dump instructions -t --id {id} -c 1",
+ substrs=[f"{id}: [{timestamp} ns]"])
@testSBAPIAndCommands
@skipIf(oslist=no_match(['linux']), archs=no_match(['i386', 'x86_64']))
@@ -57,11 +57,11 @@ def testTscPerProcess(self):
self.traceStartProcess(enableTsc=True)
self.expect("n")
- self.expect("thread trace dump instructions --tsc -c 1",
- patterns=["0: \[tsc=\d+\] 0x0000000000400511 movl"])
+ self.expect("thread trace dump instructions -t -c 1",
+ patterns=[": \[\d+.\d+ ns\] 0x0000000000400511 movl"])
- self.expect("thread trace dump instructions --tsc -c 1 --pretty-json",
- patterns=['''"tsc": "\d+"'''])
+ self.expect("thread trace dump instructions -t -c 1 --pretty-json",
+ patterns=['''"timestamp_ns": "\d+.\d+"'''])
@testSBAPIAndCommands
@skipIf(oslist=no_match(['linux']), archs=no_match(['i386', 'x86_64']))
@@ -73,11 +73,11 @@ def testDumpingAfterTracingWithoutTsc(self):
self.traceStartThread(enableTsc=False)
self.expect("n")
- self.expect("thread trace dump instructions --tsc -c 1",
- patterns=["0: \[tsc=unavailable\] 0x0000000000400511 movl"])
+ self.expect("thread trace dump instructions -t -c 1",
+ patterns=[": \[unavailable\] 0x0000000000400511 movl"])
- self.expect("thread trace dump instructions --tsc -c 1 --json",
- substrs=['''"tsc":null'''])
+ self.expect("thread trace dump instructions -t -c 1 --json",
+ substrs=['''"timestamp_ns":null'''])
@testSBAPIAndCommands
@skipIf(oslist=no_match(['linux']), archs=no_match(['i386', 'x86_64']))
More information about the lldb-commits
mailing list