[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

[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

show more ...

[lldb] Silence a GCC warning about missing returns after a fully covered switch. NFC.

[trace][intel pt] Create a CPU change event and expose it in the dumper

Thanks to [email protected] for coming up with this feature.

When tracing in per-cpu mode, we have information of in which cpu

[trace][intel pt] Create a CPU change event and expose it in the dumper

Thanks to [email protected] for coming up with this feature.

When tracing in per-cpu mode, we have information of in which cpu we are execution each instruction, which comes from the context switch trace. This diff makes this information available as a `cpu changed event`, which an additional accessor in the cursor `GetCPU()`. As cpu changes are very infrequent, any consumer should listen to cpu change events instead of querying the actual cpu of a trace item. Once a cpu change event is seen, the consumer can invoke GetCPU() to get that information. Also, it's possible to invoke GetCPU() on an arbitrary instruction item, which will return the last cpu seen. However, this call is O(logn) and should be used sparingly.

Manually tested with a sample program that starts on cpu 52, then goes to 18, and then goes back to 52.

Differential Revision: https://reviews.llvm.org/D129340

show more ...

[trace] Make events first class items in the trace cursor and rework errors

We want to include events with metadata, like context switches, and this
requires the API to handle events with payloads (

[trace] Make events first class items in the trace cursor and rework errors

We want to include events with metadata, like context switches, and this
requires the API to handle events with payloads (e.g. information about
such context switches). Besides this, we want to support multiple
similar events between two consecutive instructions, like multiple
context switches. However, the current implementation is not good for this because
we are defining events as bitmask enums associated with specific
instructions. Thus, we need to decouple instructions from events and
make events actual items in the trace, just like instructions and
errors.

- Add accessors in the TraceCursor to know if an item is an event or not
- Modify from the TraceDumper all the way to DecodedThread to support
- Renamed the paused event to disabled.
- Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs.
event items. Fortunately this simplified many things
- As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions.

All test pass

Differential Revision: https://reviews.llvm.org/D128576

show more ...

[trace] Improve the TraceCursor iteration API

The current way ot traversing the cursor is a bit uncommon and it can't handle empty traces, in fact, its invariant is that it shold always point to a v

[trace] Improve the TraceCursor iteration API

The current way ot traversing the cursor is a bit uncommon and it can't handle empty traces, in fact, its invariant is that it shold always point to a valid item. This diff simplifies the cursor API and allows it to point to invalid items, thus being able to handle empty traces or to know it ran out of data.

- Removed all the granularity functionalities, because we are not actually making use of that. We can bring them back when they are actually needed.
- change the looping logic to the following:

```
for (; cursor->HasValue(); cursor->Next()) {
if (cursor->IsError()) {
.. do something for error
continue;
}
.. do something for instruction
}

```

- added a HasValue method that can be used to identify if the cursor ran out of data, the trace is empty, or the user tried to move to an invalid position via SetId() or Seek()
- made several simplifications to severals parts of the code.

Differential Revision: https://reviews.llvm.org/D128543

show more ...

[trace][intel pt] Support events

A trace might contain events traced during the target's execution. For
example, a thread might be paused for some period of time due to context
switches or breakpoin

[trace][intel pt] Support events

A trace might contain events traced during the target's execution. For
example, a thread might be paused for some period of time due to context
switches or breakpoints, which actually force a context switch. Not only
that, a trace might be paused because the CPU decides to trace only a
specific part of the target, like the address filtering provided by
intel pt, which will cause pause events. Besides this case, other kinds
of events might exist.

This patch adds the method `TraceCursor::GetEvents()`` that returns the
list of events that happened right before the instruction being pointed
at by the cursor. Some refactors were done to make this change simpler.

Besides this new API, the instruction dumper now supports the -e flag
which shows pause events, like in the following example, where pauses
happened due to breakpoints.

```
thread #1: tid = 2717361
a.out`main + 20 at main.cpp:27:20
0: 0x00000000004023d9 leaq -0x1200(%rbp), %rax
[paused]
1: 0x00000000004023e0 movq %rax, %rdi
[paused]
2: 0x00000000004023e3 callq 0x403a62 ; std::vector<int, std::allocator<int> >::vector at stl_vector.h:391:7
a.out`std::vector<int, std::allocator<int> >::vector() at stl_vector.h:391:7
3: 0x0000000000403a62 pushq %rbp
4: 0x0000000000403a63 movq %rsp, %rbp
```

The `dump info` command has also been updated and now it shows the
number of instructions that have associated events.

Differential Revision: https://reviews.llvm.org/D123982

show more ...

[trace][intel pt] Implement the Intel PT cursor

D104422 added the interface for TraceCursor, which is the main way to traverse instructions in a trace. This diff implements the corresponding cursor

[trace][intel pt] Implement the Intel PT cursor

D104422 added the interface for TraceCursor, which is the main way to traverse instructions in a trace. This diff implements the corresponding cursor class for Intel PT and deletes the now obsolete code.

Besides that, the logic for the "thread trace dump instructions" was adapted to use this cursor (pretty much I ended up moving code from Trace.cpp to TraceCursor.cpp). The command by default traverses the instructions backwards, and if the user passes --forwards, then it's not forwards. More information about that is in the Options.td file.

Regarding the Intel PT cursor. All Intel PT cursors for the same thread share the same DecodedThread instance. I'm not yet implementing lazy decoding because we don't need it. That'll be for later. For the time being, the entire thread trace is decoded when the first cursor for that thread is requested.

Differential Revision: https://reviews.llvm.org/D105531

show more ...

[trace] Add a TraceCursor class

As a follow up of D103588, I'm reinitiating the discussion with a new proposal for traversing instructions in a trace which uses the feedback gotten in that diff.

Se

[trace] Add a TraceCursor class

As a follow up of D103588, I'm reinitiating the discussion with a new proposal for traversing instructions in a trace which uses the feedback gotten in that diff.

See the embedded documentation in TraceCursor for more information. The idea is to offer an OOP way to traverse instructions exposing a minimal interface that makes no assumptions on:

- the number of instructions in the trace (i.e. having indices for instructions might be impractical for gigantic intel-pt traces, as it would require to decode the entire trace). This renders the use of indices to point to instructions impractical. Traces are big and expensive, and the consumer should try to do look linear lookups (forwards and/or backwards) and avoid random accesses (the API could be extended though, but for now I want to dicard that funcionality and leave the API extensible if needed).
- the way the instructions are represented internally by each Trace plug-in. They could be mmap'ed from a file, exist in plain vector or generated on the fly as the user requests the data.
- the actual data structure used internally for each plug-in. Ideas like having a struct TraceInstruction have been discarded because that would make the plug-in follow a certain data type, which might be costly. Instead, the user can ask the cursor for each independent property of the instruction it's pointing at.

The way to get a cursor is to ask Trace.h for the end or being cursor or a thread's trace.

There are some benefits of this approach:
- there's little cost to create a cursor, and this allows for lazily decoding a trace as the user requests data.
- each trace plug-in could decide how to cache the instructions it generates. For example, if a trace is small, it might decide to keep everything in memory, or if the trace is massive, it might decide to keep around the last thousands of instructions to speed up local searches.
- a cursor can outlive a stop point, which makes trace comparison for live processes feasible. An application of this is to compare profiling data of two runs of the same function, which should be doable with intel pt.

Differential Revision: https://reviews.llvm.org/D104422

show more ...