lkml.org 
[lkml]   [2016]   [Mar]   [1]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    Date
    From
    SubjectRe: Intel PT not work on 4.5.0-rc
    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 ~]#
    > >>
    > >

    \
     
     \ /
      Last update: 2016-03-01 17:41    [W:6.754 / U:0.024 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site