Intel PT not work on 4.5.0-rc
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 ~]#
Quoted 1 line
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 ~]#
Quoted 10 lines · Arnaldo Carvalho de Melo
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 usingintel_ptwith 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.
Quoted 5 lines
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.
Quoted 43 lines
[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_INFOtype: 1PMU 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 0TSC:CTC denominator 0
CYC bit0x2
Quoted 8 lines
[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.
Quoted 8 lines
ITRACE_STARTevents: 4
SWITCH_CPU_WIDEevents: 11882
FINISHED_ROUNDevents: 3
AUXTRACE_INFOevents: 1
intel_pt//u stats:
dummy:u stats:
[root@jouet ~]#
Quoted 11 lines · Adrian Hunter
Quoted 10 lines · Arnaldo Carvalho de Melo
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 usingintel_ptwith 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.
Quoted 8 lines
Quoted 5 lines
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.
Quoted 72 lines
Quoted 50 lines
[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_INFOtype: 1PMU 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 0TSC:CTC denominator 0
CYC bit0x2Quoted 9 lines
[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: 8541There ought to be AUX events here, so it looks like no data has been captured, so a problem with recording.
Quoted 8 lines
ITRACE_STARTevents: 4
SWITCH_CPU_WIDEevents: 11882
FINISHED_ROUNDevents: 3
AUXTRACE_INFOevents: 1
intel_pt//u stats:
dummy:u stats:
[root@jouet ~]#
Em Tue, Mar 01, 2016 at 05:40:49PM +0200, Adrian Hunter escreveu:
Quoted 40 lines · Adrian Hunter
Quoted 11 lines · Arnaldo Carvalho de Melo
Quoted 10 lines
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 usingintel_ptwith 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.Quoted 8 lines
Quoted 5 lines
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
Quoted 2 lines
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]>) = 0x7f024bbfa000Binary 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]#
Quoted 73 lines
Quoted 73 lines
Quoted 51 lines
[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_INFOtype: 1PMU 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 0TSC:CTC denominator 0
CYC bit0x2Quoted 9 lines
[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: 8541There ought to be AUX events here, so it looks like no data has been captured, so a problem with recording.
Quoted 8 lines
ITRACE_STARTevents: 4
SWITCH_CPU_WIDEevents: 11882
FINISHED_ROUNDevents: 3
AUXTRACE_INFOevents: 1
intel_pt//u stats:
dummy:u stats:
[root@jouet ~]#
Em Tue, Mar 01, 2016 at 12:59:21PM -0300, Arnaldo Carvalho de Melo escreveu:
Quoted 1 line
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: 8intel_pt//u stats:
dummy:u stats:
[root@jouet ~]#
Trying a suspend/resume now...
- Arnaldo
Em Tue, Mar 01, 2016 at 03:20:35PM -0300, Arnaldo Carvalho de Melo escreveu:
Quoted 36 lines
Em Tue, Mar 01, 2016 at 12:59:21PM -0300, Arnaldo Carvalho de Melo escreveu:
Quoted 1 line
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_AUXoffset:0x28size:0x28flags: 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_STARTevents: 4
SWITCH_CPU_WIDEevents: 26
Quoted 8 lines
FINISHED_ROUND events: 2 AUXTRACE_INFO events: 1 AUXTRACE events: 8intel_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
Em Tue, Mar 01, 2016 at 03:24:55PM -0300, Arnaldo Carvalho de Melo escreveu:
Quoted 26 lines
Em Tue, Mar 01, 2016 at 03:20:35PM -0300, Arnaldo Carvalho de Melo escreveu:
Quoted 25 lines
Em Tue, Mar 01, 2016 at 12:59:21PM -0300, Arnaldo Carvalho de Melo escreveu:
Quoted 1 line
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_AUXoffset:0x28size:0x28flags: 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: 1intel_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