Message ID | 20171203020044.81680-7-wangnan0@huawei.com |
---|---|
State | New |
Headers | show |
Series | perf tools: perf tools: Clarify overwrite and backward, bugfix | expand |
Hi, On Sun, Dec 03, 2017 at 02:00:42AM +0000, Wang Nan wrote: > perf record backward recording doesn't work as we expected: it never > overwrite when ring buffer full. > > Test: > > (Run a busy printing task background like this: > > while True: > print 123 > > send SIGUSR2 to perf to capture snapshot.) > > # ./perf record --overwrite -e raw_syscalls:sys_enter -e raw_syscalls:sys_exit --exclude-perf -a --switch-output > [ perf record: dump data: Woken up 1 times ] > [ perf record: Dump perf.data.2017110101520743 ] > [ perf record: dump data: Woken up 1 times ] > [ perf record: Dump perf.data.2017110101521251 ] > [ perf record: dump data: Woken up 1 times ] > [ perf record: Dump perf.data.2017110101521692 ] > ^C[ perf record: Woken up 1 times to write data ] > [ perf record: Dump perf.data.2017110101521936 ] > [ perf record: Captured and wrote 0.826 MB perf.data.<timestamp> ] > > # ./perf script -i ./perf.data.2017110101520743 | head -n3 > perf 2717 [000] 12449.310785: raw_syscalls:sys_enter: NR 16 (5, 2400, 0, 59, 100, 0) > perf 2717 [000] 12449.310790: raw_syscalls:sys_enter: NR 7 (4112340, 2, ffffffff, 3df, 100, 0) > python 2545 [000] 12449.310800: raw_syscalls:sys_exit: NR 1 = 4 > # ./perf script -i ./perf.data.2017110101521251 | head -n3 > perf 2717 [000] 12449.310785: raw_syscalls:sys_enter: NR 16 (5, 2400, 0, 59, 100, 0) > perf 2717 [000] 12449.310790: raw_syscalls:sys_enter: NR 7 (4112340, 2, ffffffff, 3df, 100, 0) > python 2545 [000] 12449.310800: raw_syscalls:sys_exit: NR 1 = 4 > # ./perf script -i ./perf.data.2017110101521692 | head -n3 > perf 2717 [000] 12449.310785: raw_syscalls:sys_enter: NR 16 (5, 2400, 0, 59, 100, 0) > perf 2717 [000] 12449.310790: raw_syscalls:sys_enter: NR 7 (4112340, 2, ffffffff, 3df, 100, 0) > python 2545 [000] 12449.310800: raw_syscalls:sys_exit: NR 1 = 4 > > Timestamps are never change, but my background task is a dead loop, can > easily overwhelme the ring buffer. > > This patch fix it by force unsetting PROT_WRITE for backward ring > buffer, so all backward ring buffer become overwrite ring buffer. > > Test result: > > # ./perf record --overwrite -e raw_syscalls:sys_enter -e raw_syscalls:sys_exit --exclude-perf -a --switch-output > [ perf record: dump data: Woken up 1 times ] > [ perf record: Dump perf.data.2017110101285323 ] > [ perf record: dump data: Woken up 1 times ] > [ perf record: Dump perf.data.2017110101290053 ] > [ perf record: dump data: Woken up 1 times ] > [ perf record: Dump perf.data.2017110101290446 ] > ^C[ perf record: Woken up 1 times to write data ] > [ perf record: Dump perf.data.2017110101290837 ] > [ perf record: Captured and wrote 0.826 MB perf.data.<timestamp> ] > # ./perf script -i ./perf.data.2017110101285323 | head -n3 > python 2545 [000] 11064.268083: raw_syscalls:sys_exit: NR 1 = 4 > python 2545 [000] 11064.268084: raw_syscalls:sys_enter: NR 1 (1, 12cc330, 4, 7fc237280370, 7fc2373d0700, 2c7b0) > python 2545 [000] 11064.268086: raw_syscalls:sys_exit: NR 1 = 4 > # ./perf script -i ./perf.data.2017110101290 | head -n3 > failed to open ./perf.data.2017110101290: No such file or directory > # ./perf script -i ./perf.data.2017110101290053 | head -n3 > python 2545 [000] 11071.564062: raw_syscalls:sys_enter: NR 1 (1, 12cc330, 4, 7fc237280370, 7fc2373d0700, 2c7b0) > python 2545 [000] 11071.564064: raw_syscalls:sys_exit: NR 1 = 4 > python 2545 [000] 11071.564066: raw_syscalls:sys_enter: NR 1 (1, 12cc330, 4, 7fc237280370, 7fc2373d0700, 2c7b0) > # ./perf script -i ./perf.data.2017110101290 | head -n3 > perf.data.2017110101290053 perf.data.2017110101290446 perf.data.2017110101290837 > # ./perf script -i ./perf.data.2017110101290446 | head -n3 > sshd 1321 [000] 11075.499473: raw_syscalls:sys_exit: NR 14 = 0 > sshd 1321 [000] 11075.499474: raw_syscalls:sys_enter: NR 14 (2, 7ffe98899490, 0, 8, 0, 3000) > sshd 1321 [000] 11075.499474: raw_syscalls:sys_exit: NR 14 = 0 > # ./perf script -i ./perf.data.2017110101290837 | head -n3 > python 2545 [000] 11079.280844: raw_syscalls:sys_exit: NR 1 = 4 > python 2545 [000] 11079.280847: raw_syscalls:sys_enter: NR 1 (1, 12cc330, 4, 7fc237280370, 7fc2373d0700, 2c7b0) > python 2545 [000] 11079.280850: raw_syscalls:sys_exit: NR 1 = 4 > > Signed-off-by: Wang Nan <wangnan0@huawei.com> > --- > tools/perf/util/evlist.c | 9 +++++---- > 1 file changed, 5 insertions(+), 4 deletions(-) > > diff --git a/tools/perf/util/evlist.c b/tools/perf/util/evlist.c > index 68c1f95..bb70aef 100644 > --- a/tools/perf/util/evlist.c > +++ b/tools/perf/util/evlist.c > @@ -799,7 +799,7 @@ perf_evlist__should_poll(struct perf_evlist *evlist __maybe_unused, > } > > static int perf_evlist__mmap_per_evsel(struct perf_evlist *evlist, int idx, > - struct mmap_params *mp, int cpu_idx, > + struct mmap_params mp, int cpu_idx, > int thread, int *_output, int *_output_backward) > { > struct perf_evsel *evsel; > @@ -824,6 +824,7 @@ static int perf_evlist__mmap_per_evsel(struct perf_evlist *evlist, int idx, > if (evlist->bkw_mmap_state == BKW_MMAP_NOTREADY) > perf_evlist__toggle_bkw_mmap(evlist, BKW_MMAP_RUNNING); > } > + mp.prot &= ~PROT_WRITE; > } > > if (evsel->system_wide && thread) > @@ -838,7 +839,7 @@ static int perf_evlist__mmap_per_evsel(struct perf_evlist *evlist, int idx, > if (*output == -1) { > *output = fd; > I still prefer updating mp->prot based on evsel->attr.write_backward here (instead of passing mp as value). It'd create a minimal change. Thanks, Namhyung > - if (perf_mmap__mmap(&maps[idx], mp, *output) < 0) > + if (perf_mmap__mmap(&maps[idx], &mp, *output) < 0) > return -1; > } else { > if (ioctl(fd, PERF_EVENT_IOC_SET_OUTPUT, *output) != 0) > @@ -890,7 +891,7 @@ static int perf_evlist__mmap_per_cpu(struct perf_evlist *evlist, > true); > > for (thread = 0; thread < nr_threads; thread++) { > - if (perf_evlist__mmap_per_evsel(evlist, cpu, mp, cpu, > + if (perf_evlist__mmap_per_evsel(evlist, cpu, *mp, cpu, > thread, &output, &output_backward)) > goto out_unmap; > } > @@ -917,7 +918,7 @@ static int perf_evlist__mmap_per_thread(struct perf_evlist *evlist, > auxtrace_mmap_params__set_idx(&mp->auxtrace_mp, evlist, thread, > false); > > - if (perf_evlist__mmap_per_evsel(evlist, thread, mp, 0, thread, > + if (perf_evlist__mmap_per_evsel(evlist, thread, *mp, 0, thread, > &output, &output_backward)) > goto out_unmap; > } > -- > 2.10.1 >
Em Mon, Dec 04, 2017 at 02:37:44PM +0900, Namhyung Kim escreveu: > Hi, > > On Sun, Dec 03, 2017 at 02:00:42AM +0000, Wang Nan wrote: > > perf record backward recording doesn't work as we expected: it never > > overwrite when ring buffer full. > > > > Test: > > > > (Run a busy printing task background like this: > > > > while True: > > print 123 > > > > send SIGUSR2 to perf to capture snapshot.) > > > > # ./perf record --overwrite -e raw_syscalls:sys_enter -e raw_syscalls:sys_exit --exclude-perf -a --switch-output > > [ perf record: dump data: Woken up 1 times ] > > [ perf record: Dump perf.data.2017110101520743 ] > > [ perf record: dump data: Woken up 1 times ] > > [ perf record: Dump perf.data.2017110101521251 ] > > [ perf record: dump data: Woken up 1 times ] > > [ perf record: Dump perf.data.2017110101521692 ] > > ^C[ perf record: Woken up 1 times to write data ] > > [ perf record: Dump perf.data.2017110101521936 ] > > [ perf record: Captured and wrote 0.826 MB perf.data.<timestamp> ] > > > > # ./perf script -i ./perf.data.2017110101520743 | head -n3 > > perf 2717 [000] 12449.310785: raw_syscalls:sys_enter: NR 16 (5, 2400, 0, 59, 100, 0) > > perf 2717 [000] 12449.310790: raw_syscalls:sys_enter: NR 7 (4112340, 2, ffffffff, 3df, 100, 0) > > python 2545 [000] 12449.310800: raw_syscalls:sys_exit: NR 1 = 4 > > # ./perf script -i ./perf.data.2017110101521251 | head -n3 > > perf 2717 [000] 12449.310785: raw_syscalls:sys_enter: NR 16 (5, 2400, 0, 59, 100, 0) > > perf 2717 [000] 12449.310790: raw_syscalls:sys_enter: NR 7 (4112340, 2, ffffffff, 3df, 100, 0) > > python 2545 [000] 12449.310800: raw_syscalls:sys_exit: NR 1 = 4 > > # ./perf script -i ./perf.data.2017110101521692 | head -n3 > > perf 2717 [000] 12449.310785: raw_syscalls:sys_enter: NR 16 (5, 2400, 0, 59, 100, 0) > > perf 2717 [000] 12449.310790: raw_syscalls:sys_enter: NR 7 (4112340, 2, ffffffff, 3df, 100, 0) > > python 2545 [000] 12449.310800: raw_syscalls:sys_exit: NR 1 = 4 > > > > Timestamps are never change, but my background task is a dead loop, can > > easily overwhelme the ring buffer. > > > > This patch fix it by force unsetting PROT_WRITE for backward ring > > buffer, so all backward ring buffer become overwrite ring buffer. > > > > Test result: > > > > # ./perf record --overwrite -e raw_syscalls:sys_enter -e raw_syscalls:sys_exit --exclude-perf -a --switch-output > > [ perf record: dump data: Woken up 1 times ] > > [ perf record: Dump perf.data.2017110101285323 ] > > [ perf record: dump data: Woken up 1 times ] > > [ perf record: Dump perf.data.2017110101290053 ] > > [ perf record: dump data: Woken up 1 times ] > > [ perf record: Dump perf.data.2017110101290446 ] > > ^C[ perf record: Woken up 1 times to write data ] > > [ perf record: Dump perf.data.2017110101290837 ] > > [ perf record: Captured and wrote 0.826 MB perf.data.<timestamp> ] > > # ./perf script -i ./perf.data.2017110101285323 | head -n3 > > python 2545 [000] 11064.268083: raw_syscalls:sys_exit: NR 1 = 4 > > python 2545 [000] 11064.268084: raw_syscalls:sys_enter: NR 1 (1, 12cc330, 4, 7fc237280370, 7fc2373d0700, 2c7b0) > > python 2545 [000] 11064.268086: raw_syscalls:sys_exit: NR 1 = 4 > > # ./perf script -i ./perf.data.2017110101290 | head -n3 > > failed to open ./perf.data.2017110101290: No such file or directory > > # ./perf script -i ./perf.data.2017110101290053 | head -n3 > > python 2545 [000] 11071.564062: raw_syscalls:sys_enter: NR 1 (1, 12cc330, 4, 7fc237280370, 7fc2373d0700, 2c7b0) > > python 2545 [000] 11071.564064: raw_syscalls:sys_exit: NR 1 = 4 > > python 2545 [000] 11071.564066: raw_syscalls:sys_enter: NR 1 (1, 12cc330, 4, 7fc237280370, 7fc2373d0700, 2c7b0) > > # ./perf script -i ./perf.data.2017110101290 | head -n3 > > perf.data.2017110101290053 perf.data.2017110101290446 perf.data.2017110101290837 > > # ./perf script -i ./perf.data.2017110101290446 | head -n3 > > sshd 1321 [000] 11075.499473: raw_syscalls:sys_exit: NR 14 = 0 > > sshd 1321 [000] 11075.499474: raw_syscalls:sys_enter: NR 14 (2, 7ffe98899490, 0, 8, 0, 3000) > > sshd 1321 [000] 11075.499474: raw_syscalls:sys_exit: NR 14 = 0 > > # ./perf script -i ./perf.data.2017110101290837 | head -n3 > > python 2545 [000] 11079.280844: raw_syscalls:sys_exit: NR 1 = 4 > > python 2545 [000] 11079.280847: raw_syscalls:sys_enter: NR 1 (1, 12cc330, 4, 7fc237280370, 7fc2373d0700, 2c7b0) > > python 2545 [000] 11079.280850: raw_syscalls:sys_exit: NR 1 = 4 > > > > Signed-off-by: Wang Nan <wangnan0@huawei.com> > > --- > > tools/perf/util/evlist.c | 9 +++++---- > > 1 file changed, 5 insertions(+), 4 deletions(-) > > > > diff --git a/tools/perf/util/evlist.c b/tools/perf/util/evlist.c > > index 68c1f95..bb70aef 100644 > > --- a/tools/perf/util/evlist.c > > +++ b/tools/perf/util/evlist.c > > @@ -799,7 +799,7 @@ perf_evlist__should_poll(struct perf_evlist *evlist __maybe_unused, > > } > > > > static int perf_evlist__mmap_per_evsel(struct perf_evlist *evlist, int idx, > > - struct mmap_params *mp, int cpu_idx, > > + struct mmap_params mp, int cpu_idx, > > int thread, int *_output, int *_output_backward) > > { > > struct perf_evsel *evsel; > > @@ -824,6 +824,7 @@ static int perf_evlist__mmap_per_evsel(struct perf_evlist *evlist, int idx, > > if (evlist->bkw_mmap_state == BKW_MMAP_NOTREADY) > > perf_evlist__toggle_bkw_mmap(evlist, BKW_MMAP_RUNNING); > > } > > + mp.prot &= ~PROT_WRITE; > > } > > > > if (evsel->system_wide && thread) > > @@ -838,7 +839,7 @@ static int perf_evlist__mmap_per_evsel(struct perf_evlist *evlist, int idx, > > if (*output == -1) { > > *output = fd; > > > > I still prefer updating mp->prot based on evsel->attr.write_backward > here (instead of passing mp as value). It'd create a minimal change. Wang? I applied 1-5 in this series, waiting now for this to settle, - Arnaldo
diff --git a/tools/perf/util/evlist.c b/tools/perf/util/evlist.c index 68c1f95..bb70aef 100644 --- a/tools/perf/util/evlist.c +++ b/tools/perf/util/evlist.c @@ -799,7 +799,7 @@ perf_evlist__should_poll(struct perf_evlist *evlist __maybe_unused, } static int perf_evlist__mmap_per_evsel(struct perf_evlist *evlist, int idx, - struct mmap_params *mp, int cpu_idx, + struct mmap_params mp, int cpu_idx, int thread, int *_output, int *_output_backward) { struct perf_evsel *evsel; @@ -824,6 +824,7 @@ static int perf_evlist__mmap_per_evsel(struct perf_evlist *evlist, int idx, if (evlist->bkw_mmap_state == BKW_MMAP_NOTREADY) perf_evlist__toggle_bkw_mmap(evlist, BKW_MMAP_RUNNING); } + mp.prot &= ~PROT_WRITE; } if (evsel->system_wide && thread) @@ -838,7 +839,7 @@ static int perf_evlist__mmap_per_evsel(struct perf_evlist *evlist, int idx, if (*output == -1) { *output = fd; - if (perf_mmap__mmap(&maps[idx], mp, *output) < 0) + if (perf_mmap__mmap(&maps[idx], &mp, *output) < 0) return -1; } else { if (ioctl(fd, PERF_EVENT_IOC_SET_OUTPUT, *output) != 0) @@ -890,7 +891,7 @@ static int perf_evlist__mmap_per_cpu(struct perf_evlist *evlist, true); for (thread = 0; thread < nr_threads; thread++) { - if (perf_evlist__mmap_per_evsel(evlist, cpu, mp, cpu, + if (perf_evlist__mmap_per_evsel(evlist, cpu, *mp, cpu, thread, &output, &output_backward)) goto out_unmap; } @@ -917,7 +918,7 @@ static int perf_evlist__mmap_per_thread(struct perf_evlist *evlist, auxtrace_mmap_params__set_idx(&mp->auxtrace_mp, evlist, thread, false); - if (perf_evlist__mmap_per_evsel(evlist, thread, mp, 0, thread, + if (perf_evlist__mmap_per_evsel(evlist, thread, *mp, 0, thread, &output, &output_backward)) goto out_unmap; }
perf record backward recording doesn't work as we expected: it never overwrite when ring buffer full. Test: (Run a busy printing task background like this: while True: print 123 send SIGUSR2 to perf to capture snapshot.) # ./perf record --overwrite -e raw_syscalls:sys_enter -e raw_syscalls:sys_exit --exclude-perf -a --switch-output [ perf record: dump data: Woken up 1 times ] [ perf record: Dump perf.data.2017110101520743 ] [ perf record: dump data: Woken up 1 times ] [ perf record: Dump perf.data.2017110101521251 ] [ perf record: dump data: Woken up 1 times ] [ perf record: Dump perf.data.2017110101521692 ] ^C[ perf record: Woken up 1 times to write data ] [ perf record: Dump perf.data.2017110101521936 ] [ perf record: Captured and wrote 0.826 MB perf.data.<timestamp> ] # ./perf script -i ./perf.data.2017110101520743 | head -n3 perf 2717 [000] 12449.310785: raw_syscalls:sys_enter: NR 16 (5, 2400, 0, 59, 100, 0) perf 2717 [000] 12449.310790: raw_syscalls:sys_enter: NR 7 (4112340, 2, ffffffff, 3df, 100, 0) python 2545 [000] 12449.310800: raw_syscalls:sys_exit: NR 1 = 4 # ./perf script -i ./perf.data.2017110101521251 | head -n3 perf 2717 [000] 12449.310785: raw_syscalls:sys_enter: NR 16 (5, 2400, 0, 59, 100, 0) perf 2717 [000] 12449.310790: raw_syscalls:sys_enter: NR 7 (4112340, 2, ffffffff, 3df, 100, 0) python 2545 [000] 12449.310800: raw_syscalls:sys_exit: NR 1 = 4 # ./perf script -i ./perf.data.2017110101521692 | head -n3 perf 2717 [000] 12449.310785: raw_syscalls:sys_enter: NR 16 (5, 2400, 0, 59, 100, 0) perf 2717 [000] 12449.310790: raw_syscalls:sys_enter: NR 7 (4112340, 2, ffffffff, 3df, 100, 0) python 2545 [000] 12449.310800: raw_syscalls:sys_exit: NR 1 = 4 Timestamps are never change, but my background task is a dead loop, can easily overwhelme the ring buffer. This patch fix it by force unsetting PROT_WRITE for backward ring buffer, so all backward ring buffer become overwrite ring buffer. Test result: # ./perf record --overwrite -e raw_syscalls:sys_enter -e raw_syscalls:sys_exit --exclude-perf -a --switch-output [ perf record: dump data: Woken up 1 times ] [ perf record: Dump perf.data.2017110101285323 ] [ perf record: dump data: Woken up 1 times ] [ perf record: Dump perf.data.2017110101290053 ] [ perf record: dump data: Woken up 1 times ] [ perf record: Dump perf.data.2017110101290446 ] ^C[ perf record: Woken up 1 times to write data ] [ perf record: Dump perf.data.2017110101290837 ] [ perf record: Captured and wrote 0.826 MB perf.data.<timestamp> ] # ./perf script -i ./perf.data.2017110101285323 | head -n3 python 2545 [000] 11064.268083: raw_syscalls:sys_exit: NR 1 = 4 python 2545 [000] 11064.268084: raw_syscalls:sys_enter: NR 1 (1, 12cc330, 4, 7fc237280370, 7fc2373d0700, 2c7b0) python 2545 [000] 11064.268086: raw_syscalls:sys_exit: NR 1 = 4 # ./perf script -i ./perf.data.2017110101290 | head -n3 failed to open ./perf.data.2017110101290: No such file or directory # ./perf script -i ./perf.data.2017110101290053 | head -n3 python 2545 [000] 11071.564062: raw_syscalls:sys_enter: NR 1 (1, 12cc330, 4, 7fc237280370, 7fc2373d0700, 2c7b0) python 2545 [000] 11071.564064: raw_syscalls:sys_exit: NR 1 = 4 python 2545 [000] 11071.564066: raw_syscalls:sys_enter: NR 1 (1, 12cc330, 4, 7fc237280370, 7fc2373d0700, 2c7b0) # ./perf script -i ./perf.data.2017110101290 | head -n3 perf.data.2017110101290053 perf.data.2017110101290446 perf.data.2017110101290837 # ./perf script -i ./perf.data.2017110101290446 | head -n3 sshd 1321 [000] 11075.499473: raw_syscalls:sys_exit: NR 14 = 0 sshd 1321 [000] 11075.499474: raw_syscalls:sys_enter: NR 14 (2, 7ffe98899490, 0, 8, 0, 3000) sshd 1321 [000] 11075.499474: raw_syscalls:sys_exit: NR 14 = 0 # ./perf script -i ./perf.data.2017110101290837 | head -n3 python 2545 [000] 11079.280844: raw_syscalls:sys_exit: NR 1 = 4 python 2545 [000] 11079.280847: raw_syscalls:sys_enter: NR 1 (1, 12cc330, 4, 7fc237280370, 7fc2373d0700, 2c7b0) python 2545 [000] 11079.280850: raw_syscalls:sys_exit: NR 1 = 4 Signed-off-by: Wang Nan <wangnan0@huawei.com> --- tools/perf/util/evlist.c | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) -- 2.10.1