This is an archive of the discontinued LLVM Phabricator instance.

[trace][intel pt] Fix per-psb packet decoding
ClosedPublic

Authored by wallace on Aug 10 2022, 4:15 PM.

Details

Summary

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

Diff Detail

Event Timeline

wallace created this revision.Aug 10 2022, 4:15 PM
Herald added a project: Restricted Project. · View Herald TranscriptAug 10 2022, 4:15 PM
wallace requested review of this revision.Aug 10 2022, 4:15 PM
Herald added a project: Restricted Project. · View Herald TranscriptAug 10 2022, 4:15 PM
wallace updated this revision to Diff 451670.Aug 10 2022, 4:21 PM
wallace edited the summary of this revision. (Show Details)

nit

wallace updated this revision to Diff 451685.Aug 10 2022, 5:02 PM

improve documentation

jj10306 requested changes to this revision.Aug 11 2022, 12:17 PM
jj10306 added inline comments.
lldb/source/Plugins/Trace/intel-pt/LibiptDecoder.cpp
164–192

should this be trace_intel_pt?

476–478

so is this inner loop what's actually doing the work of getting to the next PSB? is the assumption that if an event has a tsc then it's a PSB?
Can you explain what the two different while loops are doing?

lldb/source/Plugins/Trace/intel-pt/LibiptDecoder.h
106

should we rename now that we are using PSBBlock everywhere?

lldb/source/Plugins/Trace/intel-pt/TraceIntelPTMultiCpuDecoder.cpp
95

rename?

This revision now requires changes to proceed.Aug 11 2022, 12:17 PM
wallace marked 4 inline comments as done.Aug 12 2022, 1:21 PM
wallace added inline comments.
lldb/source/Plugins/Trace/intel-pt/LibiptDecoder.cpp
476–478

discussed offline. Every invocation to pt_qry_event will get a new PSB. the event loop is just for getting the first TSC.

jj10306 accepted this revision.Aug 12 2022, 2:46 PM
jj10306 added inline comments.
lldb/source/Plugins/Trace/intel-pt/LibiptDecoder.cpp
440–441

consider renaming?

This revision is now accepted and ready to land.Aug 12 2022, 2:46 PM
wallace updated this revision to Diff 452313.Aug 12 2022, 3:13 PM
wallace marked an inline comment as done.

update

This revision was landed with ongoing or failed builds.Aug 12 2022, 3:14 PM
This revision was automatically updated to reflect the committed changes.