- 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
133 lines
5.0 KiB
Python
133 lines
5.0 KiB
Python
import lldb
|
|
from intelpt_testcase import *
|
|
from lldbsuite.test.lldbtest import *
|
|
from lldbsuite.test import lldbutil
|
|
from lldbsuite.test.decorators import *
|
|
|
|
class TestTraceTimestampCounters(TraceIntelPTTestCaseBase):
|
|
|
|
@testSBAPIAndCommands
|
|
@skipIf(oslist=no_match(['linux']), archs=no_match(['i386', 'x86_64']))
|
|
def testTscPerThread(self):
|
|
self.expect("file " + os.path.join(self.getSourceDir(), "intelpt-trace", "a.out"))
|
|
self.expect("b main")
|
|
self.expect("r")
|
|
|
|
self.traceStartThread(enableTsc=True)
|
|
|
|
self.expect("n")
|
|
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']))
|
|
def testMultipleTscsPerThread(self):
|
|
self.expect("file " + os.path.join(self.getSourceDir(), "intelpt-trace", "a.out"))
|
|
self.expect("b main")
|
|
self.expect("r")
|
|
|
|
self.traceStartThread(enableTsc=True)
|
|
|
|
# After each stop there'll be a new TSC
|
|
self.expect("si")
|
|
self.expect("si")
|
|
self.expect("si")
|
|
|
|
# We'll get the most recent instructions, with at least 3 different TSCs
|
|
self.runCmd("thread trace dump instructions -t --raw --forward")
|
|
id_to_timestamp = {}
|
|
for line in self.res.GetOutput().splitlines():
|
|
m = re.search(" (.+): \[(.+)\ ns].*", line)
|
|
if m:
|
|
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, 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']))
|
|
def testTscPerProcess(self):
|
|
self.expect("file " + os.path.join(self.getSourceDir(), "intelpt-trace", "a.out"))
|
|
self.expect("b main")
|
|
self.expect("r")
|
|
|
|
self.traceStartProcess(enableTsc=True)
|
|
|
|
self.expect("n")
|
|
self.expect("thread trace dump instructions -t -c 1",
|
|
patterns=[": \[\d+.\d+ ns\] 0x0000000000400511 movl"])
|
|
|
|
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']))
|
|
def testDumpingAfterTracingWithoutTsc(self):
|
|
self.expect("file " + os.path.join(self.getSourceDir(), "intelpt-trace", "a.out"))
|
|
self.expect("b main")
|
|
self.expect("r")
|
|
|
|
self.traceStartThread(enableTsc=False)
|
|
|
|
self.expect("n")
|
|
self.expect("thread trace dump instructions -t -c 1",
|
|
patterns=[": \[unavailable\] 0x0000000000400511 movl"])
|
|
|
|
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']))
|
|
def testPSBPeriod(self):
|
|
def isPSBSupported():
|
|
caps_file = "/sys/bus/event_source/devices/intel_pt/caps/psb_cyc"
|
|
if not os.path.exists(caps_file):
|
|
return False
|
|
with open(caps_file, "r") as f:
|
|
val = int(f.readline())
|
|
if val != 1:
|
|
return False
|
|
return True
|
|
|
|
def getValidPSBValues():
|
|
values_file = "/sys/bus/event_source/devices/intel_pt/caps/psb_periods"
|
|
values = []
|
|
with open(values_file, "r") as f:
|
|
mask = int(f.readline(), 16)
|
|
for i in range(0, 32):
|
|
if (1 << i) & mask:
|
|
values.append(i)
|
|
return values
|
|
|
|
|
|
if not isPSBSupported():
|
|
self.skipTest("PSB period unsupported")
|
|
|
|
valid_psb_values = getValidPSBValues()
|
|
# 0 should always be valid, and it's assumed by lldb-server
|
|
self.assertEqual(valid_psb_values[0], 0)
|
|
|
|
self.expect("file " + (os.path.join(self.getSourceDir(), "intelpt-trace", "a.out")))
|
|
self.expect("b main")
|
|
self.expect("r")
|
|
|
|
# it's enough to test with two valid values
|
|
for psb_period in (valid_psb_values[0], valid_psb_values[-1]):
|
|
# we first test at thread level
|
|
self.traceStartThread(psbPeriod=psb_period)
|
|
self.traceStopThread()
|
|
|
|
# we now test at process level
|
|
self.traceStartProcess(psbPeriod=psb_period)
|
|
self.traceStopProcess()
|
|
|
|
# we now test invalid values
|
|
self.traceStartThread(psbPeriod=valid_psb_values[-1] + 1, error=True,
|
|
substrs=["Invalid psb_period. Valid values are: 0"])
|
|
|
|
# TODO: dump the perf_event_attr.config as part of the upcoming "trace dump info"
|
|
# command and check that the psb period is included there.
|