* Intel PT not work on 4.5.0-rc
@ 2016-02-25 14:21 Arnaldo Carvalho de Melo
2016-02-25 21:59 ` Adrian Hunter
0 siblings, 1 reply; 7+ messages in thread
From: Arnaldo Carvalho de Melo @ 2016-02-25 14:21 UTC (permalink / raw)
To: Adrian Hunter
Cc: Jiri Olsa, Wang Nan, Alexander Shishkin, Ingo Molnar, David Ahern,
Namhyung Kim, Linux Kernel Mailing List
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?
[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
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 ~]#
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Intel PT not work on 4.5.0-rc
2016-02-25 14:21 Intel PT not work on 4.5.0-rc Arnaldo Carvalho de Melo
@ 2016-02-25 21:59 ` Adrian Hunter
2016-03-01 15:40 ` Adrian Hunter
0 siblings, 1 reply; 7+ messages in thread
From: Adrian Hunter @ 2016-02-25 21:59 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo
Cc: Jiri Olsa, Wang Nan, Alexander Shishkin, Ingo Molnar, David Ahern,
Namhyung Kim, Linux Kernel Mailing List
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.
>
> [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 ~]#
>
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Intel PT not work on 4.5.0-rc
2016-02-25 21:59 ` Adrian Hunter
@ 2016-03-01 15:40 ` Adrian Hunter
2016-03-01 15:59 ` Arnaldo Carvalho de Melo
0 siblings, 1 reply; 7+ messages in thread
From: Adrian Hunter @ 2016-03-01 15:40 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo
Cc: Jiri Olsa, Wang Nan, Alexander Shishkin, Ingo Molnar, David Ahern,
Namhyung Kim, Linux Kernel Mailing List
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 ~]#
>>
>
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Intel PT not work on 4.5.0-rc
2016-03-01 15:40 ` Adrian Hunter
@ 2016-03-01 15:59 ` Arnaldo Carvalho de Melo
2016-03-01 18:20 ` Arnaldo Carvalho de Melo
0 siblings, 1 reply; 7+ messages in thread
From: Arnaldo Carvalho de Melo @ 2016-03-01 15:59 UTC (permalink / raw)
To: Adrian Hunter
Cc: Jiri Olsa, Wang Nan, Alexander Shishkin, Ingo Molnar, David Ahern,
Namhyung Kim, Linux Kernel Mailing List
Em Tue, Mar 01, 2016 at 05:40:49PM +0200, Adrian Hunter escreveu:
> 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 linux]# perf trace --no-inherit -e mmap perf record -e intel_pt//u -a sleep 0.001 2>&1 | grep SHARED
25.797 ( 0.067 ms): mmap(len: 528384, prot: READ|WRITE, flags: SHARED, fd: 3<anon_inode:[perf_event]>) = 0x7f0250418000
26.168 ( 0.367 ms): mmap(len: 4194304, prot: READ|WRITE, flags: SHARED, fd: 3<anon_inode:[perf_event]>, off: 528384) = 0x7f024c47b000
26.264 ( 0.076 ms): mmap(len: 528384, prot: READ|WRITE, flags: SHARED, fd: 4<anon_inode:[perf_event]>) = 0x7f0250397000
26.631 ( 0.364 ms): mmap(len: 4194304, prot: READ|WRITE, flags: SHARED, fd: 4<anon_inode:[perf_event]>, off: 528384) = 0x7f024c07b000
26.723 ( 0.081 ms): mmap(len: 528384, prot: READ|WRITE, flags: SHARED, fd: 5<anon_inode:[perf_event]>) = 0x7f0250316000
27.094 ( 0.365 ms): mmap(len: 4194304, prot: READ|WRITE, flags: SHARED, fd: 5<anon_inode:[perf_event]>, off: 528384) = 0x7f024bc7b000
27.203 ( 0.099 ms): mmap(len: 528384, prot: READ|WRITE, flags: SHARED, fd: 7<anon_inode:[perf_event]>) = 0x7f024bbfa000
Binary file (standard input) matches
[root@jouet linux]#
It somehow misses one mmap :-/ Will check where is the problem, haven't see any
THROTTLE or LOST events :-\
Anyway, 'strace' shows the 4 pairs of mmaps, but it still doesn't work, rebooting:
[root@jouet linux]# strace -e mmap perf record -e intel_pt//u -a sleep 0.001 2>&1 | grep SHARED
mmap(NULL, 528384, PROT_READ|PROT_WRITE, MAP_SHARED, 3, 0) = 0x7fc3f8818000
mmap(NULL, 4194304, PROT_READ|PROT_WRITE, MAP_SHARED, 3, 0x81000) = 0x7fc3f487b000
mmap(NULL, 528384, PROT_READ|PROT_WRITE, MAP_SHARED, 4, 0) = 0x7fc3f8797000
mmap(NULL, 4194304, PROT_READ|PROT_WRITE, MAP_SHARED, 4, 0x81000) = 0x7fc3f447b000
mmap(NULL, 528384, PROT_READ|PROT_WRITE, MAP_SHARED, 5, 0) = 0x7fc3f8716000
mmap(NULL, 4194304, PROT_READ|PROT_WRITE, MAP_SHARED, 5, 0x81000) = 0x7fc3f407b000
mmap(NULL, 528384, PROT_READ|PROT_WRITE, MAP_SHARED, 7, 0) = 0x7fc3f3ffa000
mmap(NULL, 4194304, PROT_READ|PROT_WRITE, MAP_SHARED, 7, 0x81000) = 0x7fc3f3bfa000
Binary file (standard input) matches
[root@jouet linux]# perf script
[root@jouet linux]#
>
> >
> >>
> >> [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 ~]#
> >>
> >
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Intel PT not work on 4.5.0-rc
2016-03-01 15:59 ` Arnaldo Carvalho de Melo
@ 2016-03-01 18:20 ` Arnaldo Carvalho de Melo
2016-03-01 18:24 ` Arnaldo Carvalho de Melo
0 siblings, 1 reply; 7+ messages in thread
From: Arnaldo Carvalho de Melo @ 2016-03-01 18:20 UTC (permalink / raw)
To: Adrian Hunter
Cc: Jiri Olsa, Wang Nan, Alexander Shishkin, Ingo Molnar, David Ahern,
Namhyung Kim, Linux Kernel Mailing List
Em Tue, Mar 01, 2016 at 12:59:21PM -0300, Arnaldo Carvalho de Melo escreveu:
> Anyway, 'strace' shows the 4 pairs of mmaps, but it still doesn't work, rebooting:
After I reboot, all works:
[root@jouet ~]# perf record -e intel_pt//u -a sleep 0.001
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 1.119 MB perf.data ]
[root@jouet ~]# perf script | head -10
perf 3797 [002] 8136.590828: 1 branches:u: 0 [unknown] ([unknown]) => 7fcb3f240707 __GI___ioctl (/usr/lib64/libc-2.22.so)
perf 3797 [002] 8136.590828: 1 branches:u: 7fcb3f24070f __GI___ioctl (/usr/lib64/libc-2.22.so) => 497e56 perf_evsel__enable (/home/acme/bin/perf)
perf 3797 [002] 8136.590828: 1 branches:u: 497e58 perf_evsel__enable (/home/acme/bin/perf) => 497e20 perf_evsel__enable (/home/acme/bin/perf)
perf 3797 [002] 8136.590828: 1 branches:u: 497e27 perf_evsel__enable (/home/acme/bin/perf) => 497e80 perf_evsel__enable (/home/acme/bin/perf)
perf 3797 [002] 8136.590828: 1 branches:u: 497e87 perf_evsel__enable (/home/acme/bin/perf) => 497e14 perf_evsel__enable (/home/acme/bin/perf)
perf 3797 [002] 8136.590828: 1 branches:u: 497e1b perf_evsel__enable (/home/acme/bin/perf) => 497e29 perf_evsel__enable (/home/acme/bin/perf)
perf 3797 [002] 8136.590828: 1 branches:u: 497e51 perf_evsel__enable (/home/acme/bin/perf) => 421d00 ioctl@plt (/home/acme/bin/perf)
perf 3797 [002] 8136.590828: 1 branches:u: 421d00 ioctl@plt (/home/acme/bin/perf) => 7fcb3f240700 __GI___ioctl (/usr/lib64/libc-2.22.so)
perf 3797 [002] 8136.590828: 1 branches:u: 7fcb3f240705 __GI___ioctl (/usr/lib64/libc-2.22.so) => 0 [unknown] ([unknown])
perf 3797 [002] 8136.590834: 1 branches:u: 0 [unknown] ([unknown]) => 7fcb3f240707 __GI___ioctl (/usr/lib64/libc-2.22.so)
[root@jouet ~]#
[root@jouet ~]# perf report -D | tail -20
. 0020: 00 00 00 00 00 00 00 00 07 14 b9 72 66 07 00 00 ...........rf...
. 0030: 03 00 00 00 00 00 00 00 1e 00 00 00 00 00 00 00 ................
3 8136592790535 0x11e688 [0x40]: PERF_RECORD_AUX offset: 0x28 size: 0x28 flags: 0 []
Aggregated stats: (excludes AUX area (e.g. instruction trace) decoded / synthesized events)
TOTAL events: 8859
MMAP events: 120
COMM events: 509
EXIT events: 1
FORK events: 507
MMAP2 events: 7673
AUX events: 8
ITRACE_START events: 4
SWITCH_CPU_WIDE events: 26
FINISHED_ROUND events: 2
AUXTRACE_INFO events: 1
AUXTRACE events: 8
intel_pt//u stats:
dummy:u stats:
[root@jouet ~]#
Trying a suspend/resume now...
- Arnaldo
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Intel PT not work on 4.5.0-rc
2016-03-01 18:20 ` Arnaldo Carvalho de Melo
@ 2016-03-01 18:24 ` Arnaldo Carvalho de Melo
2016-03-01 19:12 ` Arnaldo Carvalho de Melo
0 siblings, 1 reply; 7+ messages in thread
From: Arnaldo Carvalho de Melo @ 2016-03-01 18:24 UTC (permalink / raw)
To: Adrian Hunter
Cc: Jiri Olsa, Wang Nan, Alexander Shishkin, Ingo Molnar, David Ahern,
Namhyung Kim, Linux Kernel Mailing List
Em Tue, Mar 01, 2016 at 03:20:35PM -0300, Arnaldo Carvalho de Melo escreveu:
> Em Tue, Mar 01, 2016 at 12:59:21PM -0300, Arnaldo Carvalho de Melo escreveu:
> > Anyway, 'strace' shows the 4 pairs of mmaps, but it still doesn't work, rebooting:
>
> After I reboot, all works:
>
> [root@jouet ~]# perf record -e intel_pt//u -a sleep 0.001
> [ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 1.119 MB perf.data ]
> [root@jouet ~]# perf script | head -10
> perf 3797 [002] 8136.590828: 1 branches:u: 0 [unknown] ([unknown]) => 7fcb3f240707 __GI___ioctl (/usr/lib64/libc-2.22.so)
> perf 3797 [002] 8136.590828: 1 branches:u: 7fcb3f24070f __GI___ioctl (/usr/lib64/libc-2.22.so) => 497e56 perf_evsel__enable (/home/acme/bin/perf)
> perf 3797 [002] 8136.590828: 1 branches:u: 497e58 perf_evsel__enable (/home/acme/bin/perf) => 497e20 perf_evsel__enable (/home/acme/bin/perf)
> perf 3797 [002] 8136.590828: 1 branches:u: 497e27 perf_evsel__enable (/home/acme/bin/perf) => 497e80 perf_evsel__enable (/home/acme/bin/perf)
> perf 3797 [002] 8136.590828: 1 branches:u: 497e87 perf_evsel__enable (/home/acme/bin/perf) => 497e14 perf_evsel__enable (/home/acme/bin/perf)
> perf 3797 [002] 8136.590828: 1 branches:u: 497e1b perf_evsel__enable (/home/acme/bin/perf) => 497e29 perf_evsel__enable (/home/acme/bin/perf)
> perf 3797 [002] 8136.590828: 1 branches:u: 497e51 perf_evsel__enable (/home/acme/bin/perf) => 421d00 ioctl@plt (/home/acme/bin/perf)
> perf 3797 [002] 8136.590828: 1 branches:u: 421d00 ioctl@plt (/home/acme/bin/perf) => 7fcb3f240700 __GI___ioctl (/usr/lib64/libc-2.22.so)
> perf 3797 [002] 8136.590828: 1 branches:u: 7fcb3f240705 __GI___ioctl (/usr/lib64/libc-2.22.so) => 0 [unknown] ([unknown])
> perf 3797 [002] 8136.590834: 1 branches:u: 0 [unknown] ([unknown]) => 7fcb3f240707 __GI___ioctl (/usr/lib64/libc-2.22.so)
> [root@jouet ~]#
> [root@jouet ~]# perf report -D | tail -20
> . 0020: 00 00 00 00 00 00 00 00 07 14 b9 72 66 07 00 00 ...........rf...
> . 0030: 03 00 00 00 00 00 00 00 1e 00 00 00 00 00 00 00 ................
>
> 3 8136592790535 0x11e688 [0x40]: PERF_RECORD_AUX offset: 0x28 size: 0x28 flags: 0 []
>
> Aggregated stats: (excludes AUX area (e.g. instruction trace) decoded / synthesized events)
> TOTAL events: 8859
> MMAP events: 120
> COMM events: 509
> EXIT events: 1
> FORK events: 507
> MMAP2 events: 7673
> AUX events: 8
> ITRACE_START events: 4
> SWITCH_CPU_WIDE events: 26
> FINISHED_ROUND events: 2
> AUXTRACE_INFO events: 1
> AUXTRACE events: 8
> intel_pt//u stats:
> dummy:u stats:
> [root@jouet ~]#
>
> Trying a suspend/resume now...
Scrap that theory, it still works after two suspend/resume cycles :-\
- ARnaldo
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Intel PT not work on 4.5.0-rc
2016-03-01 18:24 ` Arnaldo Carvalho de Melo
@ 2016-03-01 19:12 ` Arnaldo Carvalho de Melo
0 siblings, 0 replies; 7+ messages in thread
From: Arnaldo Carvalho de Melo @ 2016-03-01 19:12 UTC (permalink / raw)
To: Adrian Hunter
Cc: Jiri Olsa, Wang Nan, Alexander Shishkin, Ingo Molnar, David Ahern,
Namhyung Kim, Andi Kleen, Linux Kernel Mailing List
Em Tue, Mar 01, 2016 at 03:24:55PM -0300, Arnaldo Carvalho de Melo escreveu:
> Em Tue, Mar 01, 2016 at 03:20:35PM -0300, Arnaldo Carvalho de Melo escreveu:
> > Em Tue, Mar 01, 2016 at 12:59:21PM -0300, Arnaldo Carvalho de Melo escreveu:
> > > Anyway, 'strace' shows the 4 pairs of mmaps, but it still doesn't work, rebooting:
> >
> > After I reboot, all works:
> >
> > [root@jouet ~]# perf record -e intel_pt//u -a sleep 0.001
> > [ perf record: Woken up 1 times to write data ]
> > [ perf record: Captured and wrote 1.119 MB perf.data ]
> > [root@jouet ~]# perf script | head -10
> > perf 3797 [002] 8136.590828: 1 branches:u: 0 [unknown] ([unknown]) => 7fcb3f240707 __GI___ioctl (/usr/lib64/libc-2.22.so)
> > perf 3797 [002] 8136.590828: 1 branches:u: 7fcb3f24070f __GI___ioctl (/usr/lib64/libc-2.22.so) => 497e56 perf_evsel__enable (/home/acme/bin/perf)
> > perf 3797 [002] 8136.590828: 1 branches:u: 497e58 perf_evsel__enable (/home/acme/bin/perf) => 497e20 perf_evsel__enable (/home/acme/bin/perf)
> > perf 3797 [002] 8136.590828: 1 branches:u: 497e27 perf_evsel__enable (/home/acme/bin/perf) => 497e80 perf_evsel__enable (/home/acme/bin/perf)
> > perf 3797 [002] 8136.590828: 1 branches:u: 497e87 perf_evsel__enable (/home/acme/bin/perf) => 497e14 perf_evsel__enable (/home/acme/bin/perf)
> > perf 3797 [002] 8136.590828: 1 branches:u: 497e1b perf_evsel__enable (/home/acme/bin/perf) => 497e29 perf_evsel__enable (/home/acme/bin/perf)
> > perf 3797 [002] 8136.590828: 1 branches:u: 497e51 perf_evsel__enable (/home/acme/bin/perf) => 421d00 ioctl@plt (/home/acme/bin/perf)
> > perf 3797 [002] 8136.590828: 1 branches:u: 421d00 ioctl@plt (/home/acme/bin/perf) => 7fcb3f240700 __GI___ioctl (/usr/lib64/libc-2.22.so)
> > perf 3797 [002] 8136.590828: 1 branches:u: 7fcb3f240705 __GI___ioctl (/usr/lib64/libc-2.22.so) => 0 [unknown] ([unknown])
> > perf 3797 [002] 8136.590834: 1 branches:u: 0 [unknown] ([unknown]) => 7fcb3f240707 __GI___ioctl (/usr/lib64/libc-2.22.so)
> > [root@jouet ~]#
> > [root@jouet ~]# perf report -D | tail -20
> > . 0020: 00 00 00 00 00 00 00 00 07 14 b9 72 66 07 00 00 ...........rf...
> > . 0030: 03 00 00 00 00 00 00 00 1e 00 00 00 00 00 00 00 ................
> >
> > 3 8136592790535 0x11e688 [0x40]: PERF_RECORD_AUX offset: 0x28 size: 0x28 flags: 0 []
So, it stopped working again, the other thing I did besides
suspend/resumes was to start a KVM instance, and as soon as I have no
kvm instances running, it works, as soon as I start one, it stops:
ot@jouet ~]# perf record -e intel_pt//u sleep 0.001 2>&1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.021 MB perf.data ]
[root@jouet ~]# perf script
[root@jouet ~]# virsh list
Id Name State
----------------------------------------------------
2 rhel6.sandy running
[root@jouet ~]# virsh shutdown rhel6.sandy
Domain rhel6.sandy is being shutdown
[root@jouet ~]# virsh list
Id Name State
----------------------------------------------------
[root@jouet ~]# perf record -e intel_pt//u sleep 0.001 2>&1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.041 MB perf.data ]
[root@jouet ~]# perf script
sleep 12079 [003] 10799.018032: 1 branches:u: 0 [unknown] ([unknown]) => 7fb83b967c80 _start (/usr/lib64/ld-2.22.s
sleep 12079 [003] 10799.018032: 1 branches:u: 7fb83b967c80 _start (/usr/lib64/ld-2.22.so) => 0 [unknown] ([unknown
sleep 12079 [003] 10799.018036: 1 branches:u: 0 [unknown] ([unknown]) => 7fb83b967c80 _start (/usr/lib64/ld-2.22.s
sleep 12079 [003] 10799.018036: 1 branches:u: 7fb83b967c83 _start (/usr/lib64/ld-2.22.so) => 7fb83b96b860 _dl_start (/usr/lib
sleep 12079 [003] 10799.018036: 1 branches:u: 7fb83b96b886 _dl_start (/usr/lib64/ld-2.22.so) => 0 [unknown] ([unkn
sleep 12079 [003] 10799.018038: 1 branches:u: 0 [unknown] ([unknown]) => 7fb83b96b886 _dl_start (/usr/lib64/ld-2.2
sleep 12079 [003] 10799.018038: 1 branches:u: 7fb83b96b8f1 _dl_start (/usr/lib64/ld-2.22.so) => 7fb83b96b90f _dl_start (/usr/
sleep 12079 [003] 10799.018038: 1 branches:u: 7fb83b96b913 _dl_start (/usr/lib64/ld-2.22.so) => 7fb83b96b8f8 _dl_start (/usr/
sleep 12079 [003] 10799.018038: 1 branches:u: 7fb83b96b913 _dl_start (/usr/lib64/ld-2.22.so) => 7fb83b96b8f8 _dl_start (/usr/
sleep 12079 [003] 10799.018038: 1 branches:u: 7fb83b96b91f _dl_start (/usr/lib64/ld-2.22.so) => 7fb83b96bae8 _dl_start (/usr/
sleep 12079 [003] 10799.018038: 1 branches:u: 7fb83b96baf0 _dl_start (/usr/lib64/ld-2.22.so) => 7fb83b96bb10 _dl_start (/usr/
sleep 12079 [003] 10799.018038: 1 branches:u: 7fb83b96bb1a _dl_start (/usr/lib64/ld-2.22.so) => 7fb83b96bb30 _dl_start (/usr/
sleep 12079 [003] 10799.018038: 1 branches:u: 7fb83b96bb47 _dl_start (/usr/lib64/ld-2.22.so) => 7fb83b96b903 _dl_start (/usr/
sleep 12079 [003] 10799.018038: 1 branches:u: 7fb83b96b913 _dl_start (/usr/lib64/ld-2.22.so) => 7fb83b96b8f8 _dl_start (/usr/
sleep 12079 [003] 10799.018038: 1 branches:u: 7fb83b96b913 _dl_start (/usr/lib64/ld-2.22.so) => 7fb83b96b8f8 _dl_start (/usr/
sleep 12079 [003] 10799.018038: 1 branches:u: 7fb83b96b913 _dl_start (/usr/lib64/ld-2.22.so) => 7fb83b96b8f8 _dl_start (/usr/
So, just before hitting send again, lemme try once more, yeah, repeatable, so
please try intel_pt on a machine where KVM is running. Is this a known
limitation? This is the first machine where I run KVM + intel_pt, a Broadwell
class notebook (t450s), in the past I tested intel_pt on remore, test lab
machines, where I think there weren't virtual machines running.
For completeness:
[root@jouet ~]# virsh list
Id Name State
----------------------------------------------------
[root@jouet ~]# perf record -e intel_pt//u sleep 0.001
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.040 MB perf.data ]
[root@jouet ~]# perf script | head -5
sleep 12186 [000] 11184.786838: 1 branches:u: 0 [unknown] ([unknown]) => 7f800affec80 _start (/usr/lib64/ld-2.22.so)
sleep 12186 [000] 11184.786838: 1 branches:u: 7f800affec80 _start (/usr/lib64/ld-2.22.so) => 0 [unknown] ([unknown])
sleep 12186 [000] 11184.786840: 1 branches:u: 0 [unknown] ([unknown]) => 7f800affec80 _start (/usr/lib64/ld-2.22.so)
sleep 12186 [000] 11184.786840: 1 branches:u: 7f800affec83 _start (/usr/lib64/ld-2.22.so) => 7f800b002860 _dl_start (/usr/lib64/ld-2.22.so)
sleep 12186 [000] 11184.786840: 1 branches:u: 7f800b002860 _dl_start (/usr/lib64/ld-2.22.so) => 0 [unknown] ([unknown])
[root@jouet ~]#
[root@jouet ~]# perf report -D | tail -20
. 0010: 99 2f 00 00 99 2f 00 00 a0 47 55 29 2c 0a 00 00 ./.../...GU),...
. 0020: 03 00 00 00 00 00 00 00 87 21 00 00 00 00 00 00 .........!......
3 11184788293536 0xa3e0 [0x30]: PERF_RECORD_SWITCH_CPU_WIDE IN prev pid/tid: 0/0
Aggregated stats: (excludes AUX area (e.g. instruction trace) decoded / synthesized events)
TOTAL events: 171
MMAP events: 124
COMM events: 2
EXIT events: 1
MMAP2 events: 4
AUX events: 2
ITRACE_START events: 1
SWITCH_CPU_WIDE events: 34
FINISHED_ROUND events: 1
AUXTRACE_INFO events: 1
AUXTRACE events: 1
intel_pt//u stats:
dummy:u stats:
dummy:u stats:
[root@jouet ~]# virsh start rhel6.sandy
Domain rhel6.sandy started
[root@jouet ~]# perf record -e intel_pt//u sleep 0.001
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.020 MB perf.data ]
[root@jouet ~]# perf script | head -5
[root@jouet ~]# perf report -D | tail -20
. ... raw event: size 48 bytes
. 0000: 0f 00 00 00 00 00 30 00 59 30 00 00 59 30 00 00 ......0.Y0..Y0..
. 0010: 00 00 00 00 00 00 00 00 a2 f6 f7 02 32 0a 00 00 ............2...
. 0020: 00 00 00 00 00 00 00 00 98 21 00 00 00 00 00 00 .........!......
0 11209914447522 0x4d98 [0x30]: PERF_RECORD_SWITCH_CPU_WIDE IN prev pid/tid: 12377/12377
Aggregated stats: (excludes AUX area (e.g. instruction trace) decoded / synthesized events)
TOTAL events: 180
MMAP events: 124
COMM events: 2
EXIT events: 1
MMAP2 events: 4
ITRACE_START events: 1
SWITCH_CPU_WIDE events: 44
FINISHED_ROUND events: 3
AUXTRACE_INFO events: 1
intel_pt//u stats:
dummy:u stats:
dummy:u stats:
[root@jouet ~]#
- Arnaldo
^ permalink raw reply [flat|nested] 7+ messages in thread
end of thread, other threads:[~2016-03-01 19:12 UTC | newest]
Thread overview: 7+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2016-02-25 14:21 Intel PT not work on 4.5.0-rc Arnaldo Carvalho de Melo
2016-02-25 21:59 ` Adrian Hunter
2016-03-01 15:40 ` Adrian Hunter
2016-03-01 15:59 ` Arnaldo Carvalho de Melo
2016-03-01 18:20 ` Arnaldo Carvalho de Melo
2016-03-01 18:24 ` Arnaldo Carvalho de Melo
2016-03-01 19:12 ` Arnaldo Carvalho de Melo
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).