Re: Intel PT not work on 4.5.0-rc

[Adrian Hunter]

On 25/02/16 23:59, Adrian Hunter wrote:
> On 25/02/2016 4:21 p.m., Arnaldo Carvalho de Melo wrote:
>> Hi Adrian,
>>
>>     While fixing a problem I introducing in parsing 'intel_pt//',
>> i.e. the empty '//' part, which is fixed in my perf/core by now, I tried
>> using intel_pt with 4.5.0-rc4 and couldn't get any trace :-\
>>
>>     Talking with Jiri he tried it on his side, also a Broadwell
>> machine, and it worked, same tooling (acme/perf/core) but with a fedora
>> kernel, 4.3.5-200.fc22.x86_64.
>>
>>     Later I'll try switching to the kernel Jiri is using to see if it works
>> for me with that one.
>>
>>     I'm busy now and this Broadwell machine is my main workstation,
>> can you check if you reproduce this problem?
> 
> I am on vacation until some time next week.  I will try to look at
> it before then but might not manage it.

Checked it now and was not able to reproduce.

Was this happening every time, or did it just happen once?

One possible explanation is that the AUX area mmaps fail or don't
happen and that is somehow not reported as an error.

One way to check that is:

# strace perf record  -e intel_pt//u -a sleep 0.001 2>&1 | grep mmap | grep MAP_SHARED
mmap(NULL, 528384, PROT_READ|PROT_WRITE, MAP_SHARED, 3, 0) = 0x7f6627239000
mmap(NULL, 4194304, PROT_READ|PROT_WRITE, MAP_SHARED, 3, 0x81000) = 0x7f6623927000
mmap(NULL, 528384, PROT_READ|PROT_WRITE, MAP_SHARED, 4, 0) = 0x7f66271b8000
mmap(NULL, 4194304, PROT_READ|PROT_WRITE, MAP_SHARED, 4, 0x81000) = 0x7f6623527000
mmap(NULL, 528384, PROT_READ|PROT_WRITE, MAP_SHARED, 5, 0) = 0x7f6627137000
mmap(NULL, 4194304, PROT_READ|PROT_WRITE, MAP_SHARED, 5, 0x81000) = 0x7f6623127000
mmap(NULL, 528384, PROT_READ|PROT_WRITE, MAP_SHARED, 7, 0) = 0x7f66230a6000
mmap(NULL, 4194304, PROT_READ|PROT_WRITE, MAP_SHARED, 7, 0x81000) = 0x7f6622ca6000

That shows the normal events buffer (512KiB + 1 page) and the
AUX area buffer (4MiB) for each of 4 cpus.


> 
>>
>> [root@jouet ~]# perf --version
>> perf version 4.5.rc4.gbb109a
>> [root@jouet ~]# perf record -e intel_pt//u -a sleep 10
>> [ perf record: Woken up 1 times to write data ]
>> [ perf record: Captured and wrote 1.767 MB perf.data ]
>> [root@jouet ~]# perf evlist -v
>> intel_pt//u: type: 7, size: 112, config: 0x400, { sample_period,
>> sample_freq }: 1, sample_type: IP|TID|TIME|CPU|IDENTIFIER, read_format:
>> ID, disabled: 1, inherit: 1, exclude_kernel: 1, exclude_hv: 1,
>> sample_id_all: 1
>> dummy:u: type: 1, size: 112, config: 0x9, { sample_period, sample_freq }:
>> 1, sample_type: IP|TID|TIME|CPU|IDENTIFIER, read_format: ID, disabled: 1,
>> inherit: 1, exclude_kernel: 1, exclude_hv: 1, mmap: 1, comm: 1, task: 1,
>> sample_id_all: 1, mmap2: 1, comm_exec: 1, context_switch: 1
>> [root@jouet ~]# perf script
>> [root@jouet ~]#
>>
>>  From 'perf report -D'
>>
>> 0x1a8 [0x88]: event: 70
>> .
>> . ... raw event: size 136 bytes
>> .  0000:  46 00 00 00 00 00 88 00 01 00 00 00 00 00 00 00  F...............
>> .  0010:  07 00 00 00 00 00 00 00 1f 00 00 00 00 00 00 00  ................
>> .  0020:  14 01 58 31 00 00 00 00 69 84 20 d9 d5 3b 00 00  ..X1....i. ..;..
>> .  0030:  01 00 00 00 00 00 00 00 00 04 00 00 00 00 00 00  ................
>> .  0040:  00 08 00 00 00 00 00 00 03 00 00 00 00 00 00 00  ................
>> .  0050:  00 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00  ................
>> .  0060:  00 02 00 00 00 00 00 00 00 c0 03 00 00 00 00 00  ................
>> .  0070:  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
>> .  0080:  02 00 00 00 00 00 00 00                          ........
>>
>> 0x1a8 [0x88]: PERF_RECORD_AUXTRACE_INFO type: 1
>>    PMU Type            7
>>    Time Shift          31
>>    Time Muliplier      827851028
>>    Time Zero           65789656859753
>>    Cap Time Zero       1
>>    TSC bit             0x400
>>    NoRETComp bit       0x800
>>    Have sched_switch   3
>>    Snapshot mode       0
>>    Per-cpu maps        1
>>    MTC bit             0x200
>>    TSC:CTC numerator   0
>>    TSC:CTC denominator 0
>>    CYC bit             0x2
>>
>> [root@jouet ~]# perf report -D | tail -13
>> Aggregated stats: (excludes AUX area (e.g. instruction trace) decoded /
>> synthesized events)
>>             TOTAL events:      21753
>>              MMAP events:        130
>>              COMM events:        596
>>              EXIT events:          2
>>              FORK events:        594
>>             MMAP2 events:       8541
> 
> There ought to be AUX events here, so it looks like no data has been captured,
> so a problem with recording.
> 
>>      ITRACE_START events:          4
>>   SWITCH_CPU_WIDE events:      11882
>>    FINISHED_ROUND events:          3
>>     AUXTRACE_INFO events:          1
>> intel_pt//u stats:
>> dummy:u stats:
>> [root@jouet ~]#
>>
>