[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

3 files changed, 42 insertions, 34 deletions

diff --git a/lldb/test/API/commands/trace/TestTraceEvents.py b/lldb/test/API/commands/trace/TestTraceEvents.py
index 83d6677..11d00f1 100644
--- a/lldb/test/API/commands/trace/TestTraceEvents.py
+++ b/lldb/test/API/commands/trace/TestTraceEvents.py
@@ -13,12 +13,19 @@ class TestTraceEvents(TraceIntelPTTestCaseBase):
 
       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 6a4c82d..3e5488a 100644
--- a/lldb/test/API/commands/trace/TestTraceLoad.py
+++ b/lldb/test/API/commands/trace/TestTraceLoad.py
@@ -13,11 +13,11 @@ class TestTraceLoad(TraceIntelPTTestCaseBase):
         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 @@ class TestTraceLoad(TraceIntelPTTestCaseBase):
   "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 @@ class TestTraceLoad(TraceIntelPTTestCaseBase):
         # 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 @@ class TestTraceLoad(TraceIntelPTTestCaseBase):
         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 @@ class TestTraceLoad(TraceIntelPTTestCaseBase):
         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 619deb3..5d2e69b 100644
--- a/lldb/test/API/commands/trace/TestTraceTSC.py
+++ b/lldb/test/API/commands/trace/TestTraceTSC.py
@@ -16,8 +16,8 @@ class TestTraceTimestampCounters(TraceIntelPTTestCaseBase):
         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 @@ class TestTraceTimestampCounters(TraceIntelPTTestCaseBase):
         self.expect("si")
 
         # We'll get the most recent instructions, with at least 3 different 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 @@ class TestTraceTimestampCounters(TraceIntelPTTestCaseBase):
         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 @@ class TestTraceTimestampCounters(TraceIntelPTTestCaseBase):
         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']))