This was causing some process to wrongfully be handled by ProcessTrace.
The only place this was being used is in the intel pt plugin, but it
doesn't even build anymore, so I'm sure no one is using it.
[lldb] Part 2 of 2 - Refactor `CommandObject::DoExecute(...)` to return
`void` instead of ~~`bool`~~
Justifications:
- The code doesn't ultimately apply the `true`/`false` return values.
- The methods already pass around a `CommandReturnObject`, typically
with a `result` parameter.
- Each command return object already contains:
- A more precise status
- The error code(s) that apply to that status
Part 1 refactors the `CommandObject::Execute(...)` method.
- See
[https://github.com/llvm/llvm-project/pull/69989](https://github.com/llvm/llvm-project/pull/69989)
rdar://117378957
The way it works now, it stores a `const char *` that it does not
explicitly own. It's owned by the ConstString StringPool. This is purely
to manage its lifetime, we don't really benefit from deduplication (nor
should we try to, they are errors). We also don't really benefit from
quick comparisons.
This may make the size of TraceItemStorage larger, but you have to pay
the cost of owning the data somewhere. The ConstString StringPool is an
attractive choice but ultimately a poor one.
Differential Revision: https://reviews.llvm.org/D152326
These probably do not need to be in the ConstString StringPool as they
don't really need any of the advantages that ConstStrings offer.
Lifetime for these things is always static and we never need to perform
comparisons for setting descriptions.
Differential Revision: https://reviews.llvm.org/D148679
Mention that the LLVM/clang triple must be provided if the trace will be
consumed via `SBTraceCursor`
Test Plan:
Differential Revision: https://reviews.llvm.org/D137509
Occasionally the assertion that enforces increasing TSC values in `DecodedThread::NotifyTsc`
would get tripped during large multi CPU trace decoding.
The root cause of this issue was an assumption that all the data of a
PSB will fit within the start,end TSC of the "owning"
`ThreadContinuousExecution`. After investigating, this is not the case
because PSBs can have multiple TSCs.
This diff works around this issue by introducing a TSC upper bound for
each `PSBBlockDecoder`. This fixes the assertion failure by simply
"dropping" the remaining data of PSB whenever the TSC upper bound is
exceeded during decoding.
Future work will do a larger refactor of the multi CPU decoding to
remove the dependencies on this incorrect assumption so that PSB blocks
that span multiple `ThreadContinuousExecutions` are correctly handled.
correctly
Test Plan:
Differential Revision: https://reviews.llvm.org/D136610
The low-level decoder might fall into an infinite decoding loop for
various reasons, the simplest being an infinite direct loop reached due
to wrong handling of self-modified code in the kernel, e.g. it might
reach
```
0x0A: pause
0x0C: jump to 0x0A
```
In this case, all the code is sequential and requires no packets to be
decoded. The low-level decoder would produce an output like the
following
```
0x0A: pause
0x0C: jump to 0x0A
0x0A: pause
0x0C: jump to 0x0A
0x0A: pause
0x0C: jump to 0x0A
... infinite amount of times
```
These cases require stopping the decoder to avoid infinite work and signal this
at least as a trace error.
- Add a check that breaks decoding of a single PSB once 500k instructions have been decoded since the last packet was processed.
- Add a check that looks for infinite loops after certain amount of instructions have been decoded since the last packet was processed.
- Add some `settings` properties for tweaking the thresholds of the checks above. This is also nice because it does the basic work needed for future settings.
- Add an AnomalyDetector class that inspects the DecodedThread and the libipt decoder in search for anomalies. These anomalies are then signaled as fatal errors in the trace.
- Add an ErrorStats class that keeps track of all the errors in a DecodedThread, with a special counter for fatal errors.
- Add an entry for decoded thread errors in the `dump info` command.
Some notes are added in the code and in the documention of the settings,
so please read them.
Besides that, I haven't been unable to create a test case in LLVM style, but
I've found an anomaly in the thread #12 of the trace
72533820-3eb8-4465-b8e4-4e6bf0ccca99 at Meta. We have to figure out how to
artificially create traces with this kind of anomalies in LLVM style.
With this change, that anomalous thread now shows:
```
(lldb)thread trace dump instructions 12 -e -i 23101
thread #12: tid = 8
...missing instructions
23101: (error) anomalous trace: possible infinite loop detected of size 2
vmlinux-5.12.0-0_fbk8_clang_6656_gc85768aa64da`panic_smp_self_stop + 5 [inlined] rep_nop at processor.h:13:2
23100: 0xffffffff81342785 pause
vmlinux-5.12.0-0_fbk8_clang_6656_gc85768aa64da`panic_smp_self_stop + 7 at panic.c:87:2
23099: 0xffffffff81342787 jmp 0xffffffff81342785 ; <+5> [inlined] rep_nop at processor.h:13:2
vmlinux-5.12.0-0_fbk8_clang_6656_gc85768aa64da`panic_smp_self_stop + 5 [inlined] rep_nop at processor.h:13:2
23098: 0xffffffff81342785 pause
vmlinux-5.12.0-0_fbk8_clang_6656_gc85768aa64da`panic_smp_self_stop + 7 at panic.c:87:2
23097: 0xffffffff81342787 jmp 0xffffffff81342785 ; <+5> [inlined] rep_nop at processor.h:13:2
vmlinux-5.12.0-0_fbk8_clang_6656_gc85768aa64da`panic_smp_self_stop + 5 [inlined] rep_nop at processor.h:13:2
23096: 0xffffffff81342785 pause
vmlinux-5.12.0-0_fbk8_clang_6656_gc85768aa64da`panic_smp_self_stop + 7 at panic.c:87:2
23095: 0xffffffff81342787 jmp 0xffffffff81342785 ; <+5> [inlined] rep_nop at processor.h:13:2
```
It used to be in an infinite loop where the decoder never stopped.
Besides that, the dump info command shows
```
(lldb) thread trace dump info 12
Errors:
Number of individual errors: 32
Number of fatal errors: 1
Number of other errors: 31
```
and in json format
```
(lldb) thread trace dump info 12 -j
"errors": {
"totalCount": 32,
"libiptErrors": {},
"fatalErrors": 1,
"otherErrors": 31
}
```
Differential Revision: https://reviews.llvm.org/D136557
The per-PSB packet decoding logic was wrong because it was assuming that pt_insn_get_sync_offset was being udpated after every PSB. Silly me, that is not true. It returns the offset of the PSB packet after invoking pt_insn_sync_forward regardless of how many PSBs are visited later. Instead, I'm now following the approach described in https://github.com/intel/libipt/blob/master/doc/howto_libipt.md#parallel-decode for parallel decoding, which is basically what we need.
A nasty error that happened because of this is that when we had two PSBs (A and B), the following was happening
1. PSB A was processed all the way up to the end of the trace, which includes PSB B.
2. PSB B was then processed until the end of the trace.
The instructions emitted by step 2. were also emitted as part of step 1. so our trace had duplicated chunks. This problem becomes worse when you many PSBs.
As part of making sure this diff is correct, I added some other features that are very useful.
- Added a "synchronization point" event to the TraceCursor, so we can inspect when PSBs are emitted.
- Removed the single-thread decoder. Now the per-cpu decoder and single-thread decoder use the same code paths.
- Use the query decoder to fetch PSBs and timestamps. It turns out that the pt_insn_sync_forward of the instruction decoder can move past several PSBs (this means that we could skip some TSCs). On the other hand, the pt_query_sync_forward method doesn't skip PSBs, so we can get more accurate sync events and timing information.
- Turned LibiptDecoder into PSBBlockDecoder, which decodes single PSB blocks. It is the fundamental processing unit for decoding.
- Added many comments, asserts and improved error handling for clarity.
- Improved DecodeSystemWideTraceForThread so that a TSC is emitted always before a cpu change event. This was a bug that was annoying me before.
- SplitTraceInContinuousExecutions and FindLowestTSCInTrace are now using the query decoder, which can identify precisely each PSB along with their TSCs.
- Added an "only-events" option to the trace dumper to inspect only events.
I did extensive testing and I think we should have an in-house testing CI. The LLVM buildbots are not capable of supporting testing post-mortem traces of hundreds of megabytes. I'll leave that for later, but at least for now the current tests were able to catch most of the issues I encountered when doing this task.
A sample output of a program that I was single stepping is the following. You can see that only one PSB is emitted even though stepping happened!
```
thread #1: tid = 3578223
0: (event) trace synchronization point [offset = 0x0xef0]
a.out`main + 20 at main.cpp:29:20
1: 0x0000000000402479 leaq -0x1210(%rbp), %rax
2: (event) software disabled tracing
3: 0x0000000000402480 movq %rax, %rdi
4: (event) software disabled tracing
5: (event) software disabled tracing
6: 0x0000000000402483 callq 0x403bd4 ; std::vector<int, std::allocator<int>>::vector at stl_vector.h:391:7
7: (event) software disabled tracing
a.out`std::vector<int, std::allocator<int>>::vector() at stl_vector.h:391:7
8: 0x0000000000403bd4 pushq %rbp
9: (event) software disabled tracing
10: 0x0000000000403bd5 movq %rsp, %rbp
11: (event) software disabled tracing
```
This is another trace of a long program with a few PSBs.
```
(lldb) thread trace dump instructions -E -f thread #1: tid = 3603082
0: (event) trace synchronization point [offset = 0x0x80]
47417: (event) software disabled tracing
129231: (event) trace synchronization point [offset = 0x0x800]
146747: (event) software disabled tracing
246076: (event) software disabled tracing
259068: (event) trace synchronization point [offset = 0x0xf78]
259276: (event) software disabled tracing
259278: (event) software disabled tracing
no more data
```
Differential Revision: https://reviews.llvm.org/D131630
Pavel Labath taught me that clang-format sorts headers automatically
using llvm's rules, and it's better not to have spaces between
So in this diff I'm removing those spaces and formatting them as well.
I used `clang-format -i` to format these files.
Add a new "kernel" section with following schema.
```
"kernel": {
"loadAddress"?: decimal | hex string | string decimal
# This is optional. If it's not specified, use default address 0xffffffff81000000.
"file": string
# path to the kernel image
}
```
Here's more details of the diff:
- If "kernel" section exist, it means current tracing mode is //KernelMode//.
- If tracing mode is //KernelMode//, the "processes" section must be empty and the "kernel" and "cpus" section must be provided. This is tested with `TestTraceLoad`.
- "kernel" section is parsed and turned into a new process with a single module which is the kernel image. The kernel process has N fake threads, one for each cpu.
Reviewed By: wallace
Differential Revision: https://reviews.llvm.org/D130805
Add bindings for the `TraceCursor` to allow for programatic traversal of
traces.
This diff adds bindings for all public `TraceCursor` methods except
`GetHwClock` and also adds `SBTrace::CreateNewCursor`. A new unittest
has been added to TestTraceLoad.py that uses the new `SBTraceCursor` API
to test that the sequential and random access APIs of the `TraceCursor`
are equivalent.
This diff depends on D130925.
Test Plan:
`ninja lldb-dotest && ./bin/lldb-dotest -p TestTraceLoad`
Differential Revision: https://reviews.llvm.org/D130930
The use of `std::unique_ptr` with `TraceCursor` adds unnecessary complexity to adding `SBTraceCursor` bindings
Specifically, since `TraceCursor` is an abstract class there's no clean
way to provide "deep clone" semantics for `TraceCursorUP` short of
creating a pure virtual `clone()` method (afaict).
After discussing with @wallace, we decided there is no strong reason to
favor wrapping `TraceCursor` with `std::unique_ptr` over `std::shared_ptr`, thus this diff
replaces all usages of `std::unique_ptr<TraceCursor>` with `std::shared_ptr<TraceCursor>`.
This sets the stage for future diffs to introduce `SBTraceCursor`
bindings in a more clean fashion.
Test Plan:
Differential Revision: https://reviews.llvm.org/D130925
D130309 introduced changes to the FileSpec API which broke usages of
`GetCString()` in TraceIntelPTBundleSaver.cpp. This diff replaces usages
of `GetCString()` with `GetPath().c_str()` as suggested by D130309.
Test Plan:
Building with the trace plug-in now succeeds
Differential Revision: https://reviews.llvm.org/D130924
Refactor the command option enum values and the command argument table
to connect the two. This has two benefits:
- We guarantee that two options that use the same argument type have
the same accepted values.
- We can print the enum values and their description in the help
output. (D129707)
Differential revision: https://reviews.llvm.org/D129703
Thanks to ymeng@fb.com for coming up with this change.
`thread trace dump info` can dump some metrics that can be useful for
analyzing the performance and quality of a trace. This diff adds a --json
option for dumping this information in json format that can be easily
understood my machines.
Differential Revision: https://reviews.llvm.org/D129332
It turns out that cgroup filtering is relatively trivial and works
really nicely. Thid diffs adds automatic cgroup filtering when in
per-cpu mode, unless a new --disable-cgroup-filtering flag is passed in
the start command. At least on Meta machines, all processes are spawned
inside a cgroup by default, which comes super handy, because per cpu
tracing is now much more precise.
A manual test gave me this result
- Without filtering:
Total number of trace items: 36083
Total number of continuous executions found: 229
Number of continuous executions for this thread: 2
Total number of PSB blocks found: 98
Number of PSB blocks for this thread 2
Total number of unattributed PSB blocks found: 38
- With filtering:
Total number of trace items: 87756
Total number of continuous executions found: 123
Number of continuous executions for this thread: 2
Total number of PSB blocks found: 10
Number of PSB blocks for this thread 3
Total number of unattributed PSB blocks found: 2
Filtering gives us great results. The number of instructions collected
more than double (probalby because we have less noise in the trace), and
we have much less unattributed PSBs blocks and unrelated PSBs in
general. The ones that are unrelated probably belong to other processes
in the same cgroup.
Differential Revision: https://reviews.llvm.org/D129257
Thanks to fredzhou@fb.com 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
A trace bundle contains many trace files, and, in the case of intel pt, the
largest files are often the context switch traces because they are not
compressed by default. As a way to improve this, I'm adding a --compact option
to the `trace save` command that filters out unwanted processes from the
context switch traces. Eventually we can do the same for intel pt traces as
well.
Differential Revision: https://reviews.llvm.org/D129239
This metric was missing. We were only measuring in per-thread mode, and
this completes the work.
For a sample trace I have, the `dump info` command shows
```
Timing for this thread:
Decoding instructions: 0.12s
```
I also improved a bit the TaskTime function so that callers don't need to
specify the template argument
Differential Revision: https://reviews.llvm.org/D129249
Thanks to rnofenko@fb.com for coming up with these changes.
This diff adds support for passing units in the trace size inputs. For example,
it's now possible to specify 64KB as the trace size, instead of the
problematic 65536. This makes the user experience a bit friendlier.
Differential Revision: https://reviews.llvm.org/D129613
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
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
As previously discussed with @jj10306, we didn't really have a name for
the post-mortem (or offline) trace session representation, which is in
fact a folder with a bunch of files. We decided to call this folder
"trace bundle", and the main JSON file in it "trace bundle description
file". This naming is pretty decent, so I'm refactoring all the existing
code to account for that.
Differential Revision: https://reviews.llvm.org/D128484
In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go.
- add a -j option for printing the dump in json
- add a -J option for pretty printing the json output
- add a -F option for specifying an output file
- add a -a option for dumping all the instructions available starting at the initial point configured with the other flags
- add tests for all cases
- refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable
sample output:
```
(lldb) thread trace dump instructions -t -a --id 100 -J
[
{
"id": 100,
"tsc": "43591204528448966"
"loadAddress": "0x407a91",
"module": "a.out",
"symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)",
"mnemonic": "movq",
"source": "/usr/include/c++/8/bits/deque.tcc",
"line": 492,
"column": 30
},
...
```
Differential Revision: https://reviews.llvm.org/D128316
Having a member variable TraceIntelPT * makes it look as if it was
optional. I'm using instead a weak_ptr to indicate that it's not
optional and the object is under the ownership of TraceIntelPT.
Besides that, I've simplified the Perf aux and data buffers copying by
using vector.insert.
I'm also renaming Lookup2 to Lookup. The 2 in the name is confusing.
Differential Revision: https://reviews.llvm.org/D127881
llvm's JSON parser supports 64 bit integers, but other tools like the
ones written in JS don't support numbers that big, so we need to
represent these possibly big numbers as a string. This diff uses that to
represent addresses and tsc zero. The former is printed in hex for and
the latter in decimal string form. The schema was updated mentioning
that.
Besides that, I fixed some remaining issues and now all test pass. Before I wasn't running all tests because for some reason my computer reverted perf_paranoid to 1.
Differential Revision: https://reviews.llvm.org/D127819
As discusses offline with @jj10305, we are updating some naming used throughout the code, specially in the json schema
- traceBuffer -> iptTrace
- core -> cpu
Differential Revision: https://reviews.llvm.org/D127817
This addresses the issues in diffs [13], [14] and [16]
- Add better documentation
- Fix some castings by making them safer
- Simplify CorrelateContextSwitchesAndIntelPtTraces
- Rename some functions
Differential Revision: https://reviews.llvm.org/D127804
