[v2,6/8] perf mmap: Fix perf backward recording

Message ID 20171203020044.81680-7-wangnan0@huawei.com
State New
Headers show
Series
  • perf tools: perf tools: Clarify overwrite and backward, bugfix
Related show

Commit Message

Wang Nan Dec. 3, 2017, 2 a.m.
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

Comments

Namhyung Kim Dec. 4, 2017, 5:37 a.m. | #1
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

>
Arnaldo Carvalho de Melo Dec. 4, 2017, 3:44 p.m. | #2
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

Patch

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;
 	}