Re: [PATCH 01/17] perf report: Ask ordered events for --tasks option

From: Jiri Olsa
Date: Tue Feb 06 2018 - 14:07:58 EST


On Tue, Feb 06, 2018 at 03:48:20PM -0300, Arnaldo Carvalho de Melo wrote:
> Em Tue, Feb 06, 2018 at 07:17:57PM +0100, Jiri Olsa escreveu:
> > If we have the time in, keep the events in time order.
>
> Try to be more verbose, what actual effect this will have in this particular
> case?
>
> So, I had to try it to see the effects and explain them:
>
> --- /tmp/before 2018-02-06 15:40:29.536411625 -0300
> +++ /tmp/after 2018-02-06 15:40:51.963403599 -0300
> @@ -5,34 +5,34 @@
> 2540 2540 1818 | gnome-terminal-
> 3489 3489 2540 | bash
> 32433 32433 3489 | perf
> - 32434 32434 32433 | perf
> + 32434 32434 32433 | make
> 32441 32441 32434 | make
> 32514 32514 32441 | make
> 511 511 32514 | sh
> - 512 512 511 | sh
> + 512 512 511 | install
>
> We don't have perf calling perf calling make, etc, the second perf actually is
> 'make', i.e. there was reordering of PERF_RECORD_COMM/PERF_RECORD_FORK:
>
> Look for FORK and COMM meta events, for those tids:
>
> [root@jouet acme]# perf report -D | egrep 'PERF_RECORD_(FORK|COMM)' | egrep '3243[34]'
> 0 14774650990679 0x1a3cd8 [0x38]: PERF_RECORD_FORK(32433:32433):(3489:3489)
> 1 14774652080381 0x1d6568 [0x30]: PERF_RECORD_COMM exec: perf:32433/32433
> 1 14774742473340 0x1dbb48 [0x38]: PERF_RECORD_FORK(32434:32434):(32433:32433)
> 0 14774752005779 0x1a4af8 [0x30]: PERF_RECORD_COMM exec: make:32434/32434
> 0 14774753997960 0x1a5578 [0x38]: PERF_RECORD_FORK(32435:32435):(32434:32434)
> 0 14774756070782 0x1a5618 [0x38]: PERF_RECORD_FORK(32438:32438):(32434:32434)
> 0 14774757772939 0x1a5680 [0x38]: PERF_RECORD_FORK(32440:32440):(32434:32434)
> 0 14774758230600 0x1a56e8 [0x38]: PERF_RECORD_FORK(32441:32441):(32434:32434)
> [root@jouet acme]#
>
> So they are on different CPUs, thus ring buffers, and when we don't use
> ordered_events, we end up mixing that up, right?

right ;-) time sorted is always better..

thanks,
jirka