Em Wed, Mar 04, 2015 at 10:01:23AM +0900, Namhyung Kim escreveu: > On Tue, Mar 03, 2015 at 01:49:40PM -0300, Arnaldo Carvalho de Melo wrote: > > Hi, > > > > Just a preview, but this is something David had mentioned at some > > point, a major problem with 'perf trace' was that it wasn't using > > 'perf_session' event reordering mechanism, so I've been working on making it > > use it, refactoring the ordered_events code so that it can be used by tools > > that don't deal with perf.data files. > At a conceptual level, I think event processing should be done with > session. Even if perf trace does not do anything with a data file it > can have a (live) session like perf top does. This way we can avoid
perf top is another one I want to move away from perf_session, as it doesn't use any perf.data file, but needs to have events ordered. But then I really need to look at what you done in your patchset, probably I am missing something (or a lot). > internal API changes. > > Also, in my multi-thread work, I don't use ordered_events API much > since all samples are already ordered for each cpu or thread. So I'd > like to decouple it as much as possible. > > I still have to investigate why there are so many sched_wakeup at the > > beginning, > > but probably they are really being generated by the kernel and 'perf trace' > > has to make > > this output more compact, perhaps noticing that a number of similar events > > appeared on > > the stream and instead of writing N lines, print some prefix ([N*] perhaps) > > and then > > the line. > > > > Also its keeping pointers to the ring buffer, probably we'll need to > > copy or > > store the perf_sample somehow in the 'ordered_event' instance. > > > > But as this is touching things that Namhyung is touching as well, I > > thought about > > sharing this stuff, its on my tree, branch tmp.perf/trace_ordered_events. > > Thanks for letting me know. > Namhyung > > > > > > Lunchtime, bbl! > > > > - Arnaldo > > > > [root@ssdandy ~]# trace --ev sched:* usleep 1 > > 0.000 ( ): sched:sched_wakeup:comm=trace pid=4677 prio=120 > > success=1 target_cpu=001) > > 0.001 ( ): sched:sched_wakeup:comm=trace pid=4677 prio=120 > > success=1 target_cpu=001) > > 0.002 ( ): sched:sched_wakeup:comm=trace pid=4677 prio=120 > > success=1 target_cpu=001) > > 0.002 ( ): sched:sched_wakeup:comm=trace pid=4677 prio=120 > > success=1 target_cpu=001) > > 0.003 ( ): sched:sched_wakeup:comm=trace pid=4677 prio=120 > > success=1 target_cpu=001) > > 0.003 ( ): sched:sched_wakeup:comm=trace pid=4677 prio=120 > > success=1 target_cpu=001) > > 0.003 ( ): sched:sched_wakeup:comm=trace pid=4677 prio=120 > > success=1 target_cpu=001) > > 0.004 ( ): sched:sched_wakeup:comm=trace pid=4677 prio=120 > > success=1 target_cpu=001) > > 1.367 ( ): sched:sched_wakeup:comm=trace pid=4677 prio=120 > > success=1 target_cpu=003) > > 1.368 ( ): sched:sched_wakeup:comm=trace pid=4677 prio=120 > > success=1 target_cpu=003) > > 1.369 ( ): sched:sched_wakeup:comm=trace pid=4677 prio=120 > > success=1 target_cpu=003) > > 1.369 ( ): sched:sched_wakeup:comm=trace pid=4677 prio=120 > > success=1 target_cpu=003) > > 1.369 ( ): sched:sched_wakeup:comm=trace pid=4677 prio=120 > > success=1 target_cpu=003) > > 1.370 ( ): sched:sched_wakeup:comm=trace pid=4677 prio=120 > > success=1 target_cpu=003) > > 1.370 ( ): sched:sched_wakeup:comm=trace pid=4677 prio=120 > > success=1 target_cpu=003) > > 1.371 ( ): sched:sched_wakeup:comm=trace pid=4677 prio=120 > > success=1 target_cpu=003) > > 1.615 ( ): sched:sched_process_exec:filename=/bin/usleep > > pid=4677 old_pid=4677) > > 1.621 ( ): sched:sched_wakeup:comm=rcuop/3 pid=16 prio=120 > > success=1 target_cpu=005) > > 1.640 ( 0.001 ms): usleep/4677 brk( > > ) = 0x64e000 > > 1.662 ( 0.005 ms): usleep/4677 mmap(len: 4096, prot: READ|WRITE, > > flags: PRIVATE|ANONYMOUS, fd: -1 ) = 0x7f3d1d7ef000 > > 1.675 ( 0.005 ms): usleep/4677 access(filename: 0x7f3d1d5edbe0, mode: > > R ) = -1 ENOENT No such file or directory > > 1.687 ( 0.004 ms): usleep/4677 open(filename: 0x7f3d1d5ec4d8, flags: > > CLOEXEC ) = 3 > > 1.689 ( 0.001 ms): usleep/4677 fstat(fd: 3, statbuf: 0x7fff28219d10 > > ) = 0 > > 1.695 ( 0.005 ms): usleep/4677 mmap(len: 68635, prot: READ, flags: > > PRIVATE, fd: 3 ) = 0x7f3d1d7de000 > > 1.696 ( 0.001 ms): usleep/4677 close(fd: 3 > > ) = 0 > > 1.714 ( 0.007 ms): usleep/4677 open(filename: 0x7f3d1d7e867d, flags: > > CLOEXEC ) = 3 > > 1.716 ( 0.002 ms): usleep/4677 read(fd: 3, buf: 0x7fff28219eb0, count: > > 832 ) = 832 > > 1.719 ( 0.001 ms): usleep/4677 fstat(fd: 3, statbuf: 0x7fff28219d60 > > ) = 0 > > 1.727 ( 0.006 ms): usleep/4677 mmap(len: 2135088, prot: EXEC|READ, > > flags: PRIVATE|DENYWRITE, fd: 3 ) = 0x7f3d1d3c6000 > > 1.734 ( 0.007 ms): usleep/4677 mprotect(start: 0x7f3d1d3cf000, len: > > 2093056 ) = 0 > > 1.741 ( 0.007 ms): usleep/4677 mmap(addr: 0x7f3d1d5ce000, len: 8192, > > prot: READ|WRITE, flags: PRIVATE|DENYWRITE|FIXED, fd: 3, off: 32768) = > > 0x7f3d1d5ce000 > > 1.748 ( 0.001 ms): usleep/4677 close(fd: 3 > > ) = 0 > > 1.763 ( 0.006 ms): usleep/4677 open(filename: 0x7f3d1d7ed5fa, flags: > > CLOEXEC ) = 3 > > 1.765 ( 0.002 ms): usleep/4677 read(fd: 3, buf: 0x7fff28219e80, count: > > 832 ) = 832 > > 1.767 ( 0.001 ms): usleep/4677 fstat(fd: 3, statbuf: 0x7fff28219d30 > > ) = 0 > > 1.775 ( 0.006 ms): usleep/4677 mmap(len: 3932736, prot: EXEC|READ, > > flags: PRIVATE|DENYWRITE, fd: 3 ) = 0x7f3d1d005000 > > 1.782 ( 0.007 ms): usleep/4677 mprotect(start: 0x7f3d1d1bb000, len: > > 2097152 ) = 0 > > 1.790 ( 0.008 ms): usleep/4677 mmap(addr: 0x7f3d1d3bb000, len: 24576, > > prot: READ|WRITE, flags: PRIVATE|DENYWRITE|FIXED, fd: 3, off: 1794048) ... > > 1.790 ( ): sched:sched_stat_runtime:comm=usleep pid=4677 > > runtime=426124 [ns] vruntime=569867840059 [ns]) > > 1.793 ( ): sched:sched_wakeup:comm=rcuc/3 pid=56 prio=97 > > success=1 target_cpu=003) > > 1.794 ( ): sched:sched_wakeup:comm=ksoftirqd/3 pid=58 prio=98 > > success=1 target_cpu=003) > > 1.797 ( ): sched:sched_stat_runtime:comm=usleep pid=4677 > > runtime=2371 [ns] vruntime=569867842430 [ns]) > > 1.798 ( ): sched:sched_switch:prev_comm=usleep prev_pid=4677 > > prev_prio=120 prev_state=R+ ==> next_comm=rcuc/3 next_pid=56 next_prio=97) > > 1.832 ( 0.049 ms): usleep/4677 ... [continued]: mmap()) = > > 0x7f3d1d3bb000 > > 1.844 ( 0.007 ms): usleep/4677 mmap(addr: 0x7f3d1d3c1000, len: 16960, > > prot: READ|WRITE, flags: PRIVATE|ANONYMOUS|FIXED, fd: -1) = 0x7f3d1d3c1000 > > 1.849 ( 0.001 ms): usleep/4677 close(fd: 3 > > ) = 0 > > 1.859 ( 0.005 ms): usleep/4677 mmap(len: 4096, prot: READ|WRITE, > > flags: PRIVATE|ANONYMOUS, fd: -1 ) = 0x7f3d1d7dd000 > > 1.873 ( 0.005 ms): usleep/4677 mmap(len: 8192, prot: READ|WRITE, > > flags: PRIVATE|ANONYMOUS, fd: -1 ) = 0x7f3d1d7db000 > > 1.879 ( 0.001 ms): usleep/4677 arch_prctl(option: 4098, arg2: > > 139900464510784, arg3: 139900464513104, arg4: 34, arg5: 4294967295) = 0 > > 1.969 ( 0.009 ms): usleep/4677 mprotect(start: 0x7f3d1d3bb000, len: > > 16384, prot: READ ) = 0 > > 1.982 ( 0.007 ms): usleep/4677 mprotect(start: 0x7f3d1d5ce000, len: > > 4096, prot: READ ) = 0 > > 1.991 ( 0.006 ms): usleep/4677 mprotect(start: 0x601000, len: 4096, > > prot: READ ) = 0 > > 2.001 ( 0.007 ms): usleep/4677 mprotect(start: 0x7f3d1d7f0000, len: > > 4096, prot: READ ) = 0 > > 2.009 ( 0.007 ms): usleep/4677 munmap(addr: 0x7f3d1d7de000, len: 68635 > > ) = 0 > > 2.049 ( ): sched:sched_stat_runtime:comm=usleep pid=4677 > > runtime=220367 [ns] vruntime=569868062797 [ns]) > > 2.050 ( ): sched:sched_switch:prev_comm=usleep prev_pid=4677 > > prev_prio=120 prev_state=R ==> next_comm=irq/51-enp0s25 next_pid=1164 > > next_prio=49) > > 2.097 ( ): sched:sched_stat_runtime:comm=usleep pid=4677 > > runtime=29987 [ns] vruntime=569868092784 [ns]) > > 2.099 ( ): sched:sched_switch:prev_comm=usleep prev_pid=4677 > > prev_prio=120 prev_state=R+ ==> next_comm=irq/51-enp0s25 next_pid=1164 > > next_prio=49) > > 2.121 ( 0.001 ms): usleep/4677 brk( > > ) = 0x64e000 > > 2.126 ( 0.005 ms): usleep/4677 brk(brk: 0x66f000 > > ) = 0x66f000 > > 2.129 ( 0.001 ms): usleep/4677 brk( > > ) = 0x66f000 > > 2.148 ( ): sched:sched_stat_runtime:comm=usleep pid=4677 > > runtime=34634 [ns] vruntime=569868127418 [ns]) > > 2.149 ( ): sched:sched_switch:prev_comm=usleep prev_pid=4677 > > prev_prio=120 prev_state=R+ ==> next_comm=irq/51-enp0s25 next_pid=1164 > > next_prio=49) > > 2.173 ( 0.002 ms): usleep/4677 nanosleep(rqtp: 0x7fff2821a4e0 > > ) ... > > 2.173 ( ): sched:sched_stat_runtime:comm=usleep pid=4677 > > runtime=11440 [ns] vruntime=569868138858 [ns]) > > 2.174 ( ): sched:sched_switch:prev_comm=usleep prev_pid=4677 > > prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120) > > 2.227 ( ): sched:sched_wakeup:comm=usleep pid=4677 prio=120 > > success=1 target_cpu=003) > > 2.228 ( ): sched:sched_wakeup:comm=usleep pid=4677 prio=120 > > success=1 target_cpu=003) > > 2.228 ( ): sched:sched_wakeup:comm=usleep pid=4677 prio=120 > > success=1 target_cpu=003) > > 2.229 ( ): sched:sched_wakeup:comm=usleep pid=4677 prio=120 > > success=1 target_cpu=003) > > 2.230 ( ): sched:sched_wakeup:comm=usleep pid=4677 prio=120 > > success=1 target_cpu=003) > > 2.230 ( ): sched:sched_wakeup:comm=usleep pid=4677 prio=120 > > success=1 target_cpu=003) > > 2.230 ( ): sched:sched_wakeup:comm=usleep pid=4677 prio=120 > > success=1 target_cpu=003) > > 2.231 ( ): sched:sched_wakeup:comm=usleep pid=4677 prio=120 > > success=1 target_cpu=003) > > 2.237 ( 0.067 ms): usleep/4677 ... [continued]: nanosleep()) = 0 > > 2.243 ( 0.000 ms): usleep/4677 exit_group( > > > > 2.289 ( ): sched:sched_process_exit:comm=usleep pid=4677 > > prio=120) > > [root@ssdandy ~]# -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
