Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1522389
| From | Namhyung Kim <namhyung@kernel.org> |
|---|---|
| Newsgroups | linux.kernel |
| Subject | Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v1) |
| Date | 2016-11-15 08:00 +0100 |
| Message-ID | <sDFSN-1t7-1@gated-at.bofh.it> (permalink) |
| References | <sDs9b-RG-3@gated-at.bofh.it> <sDFJ8-1pY-13@gated-at.bofh.it> |
| Organization | linux.* mail to news gateway |
Hi Ingo, On Tue, Nov 15, 2016 at 07:42:14AM +0100, Ingo Molnar wrote: > > * Namhyung Kim <namhyung@kernel.org> wrote: > > > Hello, > > > > This patchset is a rebased version of David's sched timehist work [1]. > > I plan to improve perf sched command more and think that having > > timehist command before the work looks good. It seems David is busy > > these days, so I'm retrying it by myself. > > > > This implements only basic feature and a few options. I just split > > the patch to make it easier to review and did some cosmetic changes. > > More patches will come later. > > > > The below is from the David's original description: > > > > ------------------------8<------------------------- > > 'perf sched timehist' provides an analysis of scheduling events. > > > > Example usage: > > perf sched record -- sleep 1 > > perf sched timehist > > > Cool, very nice! :) > > > By default it shows the individual schedule events, including the time between > > sched-in events for the task, the task scheduling delay (time between wakeup > > and actually running) and run time for the task: > > > > time cpu task name[tid/pid] b/n time sch delay run time > > ------------- ---- -------------------- --------- --------- --------- > > 79371.874569 [11] gcc[31949] 0.014 0.000 1.148 > > 79371.874591 [10] gcc[31951] 0.000 0.000 0.024 > > 79371.874603 [10] migration/10[59] 3.350 0.004 0.011 > > 79371.874604 [11] <idle> 1.148 0.000 0.035 > > 79371.874723 [05] <idle> 0.016 0.000 1.383 > > 79371.874746 [05] gcc[31949] 0.153 0.078 0.022 > > ... > > What does the 'b/n' abbreviation stand for? 'Between'? Could we call the column > 'sch wait' instead, or so? Looks better, or what about 'wait time'? > > > > Times are in msec.usec. > > > > If callchains were recorded they are appended to the line with a default stack depth of 5: > > > > 79371.874569 [11] gcc[31949] 0.000014 0.000000 0.001148 wait_for_completion_killable do_fork sys_vfork stub_vfork __vfork > > 79371.874591 [10] gcc[31951] 0.000000 0.000000 0.000024 __cond_resched _cond_resched wait_for_completion stop_one_cpu sched_exec > > 79371.874603 [10] migration/10[59] 0.003350 0.000004 0.000011 smpboot_thread_fn kthread ret_from_fork > > 79371.874604 [11] <idle> 0.001148 0.000000 0.000035 cpu_startup_entry start_secondary > > 79371.874723 [05] <idle> 0.000016 0.000000 0.001383 cpu_startup_entry start_secondary > > 79371.874746 [05] gcc[31949] 0.000153 0.000078 0.000022 do_wait sys_wait4 system_call_fastpath __GI___waitpid > > So when I first saw this it was hard for me to disambiguate individual function > names. Wouldn't this be a bit more readable: > > > 79371.874569 [11] gcc[31949] 0.000014 0.000000 0.001148 wait_for_completion_killable() <- do_fork sys_vfork stub_vfork() <- __vfork() > > 79371.874591 [10] gcc[31951] 0.000000 0.000000 0.000024 __cond_resched() <- _cond_resched() <- wait_for_completion() <- stop_one_cpu() <- sched_exec() > > 79371.874603 [10] migration/10[59] 0.003350 0.000004 0.000011 smpboot_thread_fn() <- kthread() <- ret_from_fork() > > 79371.874604 [11] <idle> 0.001148 0.000000 0.000035 cpu_startup_entry() <- start_secondary() > > 79371.874723 [05] <idle> 0.000016 0.000000 0.001383 cpu_startup_entry() <- start_secondary() > > 79371.874746 [05] gcc[31949] 0.000153 0.000078 0.000022 do_wait() <- sys_wait4() <- system_call_fastpath() <- __GI___waitpid() > > Or: > > > 79371.874569 [11] gcc[31949] 0.000014 0.000000 0.001148 wait_for_completion_killable() <- do_fork sys_vfork stub_vfork() <- __vfork() > > 79371.874591 [10] gcc[31951] 0.000000 0.000000 0.000024 __cond_resched() <- _cond_resched() <- wait_for_completion() <- stop_one_cpu() <- sched_exec() > > 79371.874603 [10] migration/10[59] 0.003350 0.000004 0.000011 smpboot_thread_fn() <- kthread() <- ret_from_fork() > > 79371.874604 [11] <idle> 0.001148 0.000000 0.000035 cpu_startup_entry() <- start_secondary() > > 79371.874723 [05] <idle> 0.000016 0.000000 0.001383 cpu_startup_entry() <- start_secondary() > > 79371.874746 [05] gcc[31949] 0.000153 0.000078 0.000022 do_wait() <- sys_wait4() <- system_call_fastpath() <- __GI___waitpid() > > (i.e. visually separate the first entry - and list the rest.) > > Or maybe it could be ASCII color coded so that the different entries are easier to > separate: for example the functions could be printed in alternating white/grey > color? I'd go with the first option - simply adding arrows. It's good enough to identify each function IMHO. Thanks, Namhyung
Back to linux.kernel | Previous | Next — Previous in thread | Next in thread | Find similar | Unroll thread
[PATCHSET 0/7] perf sched: Introduce timehist command, again (v1) Namhyung Kim <namhyung@kernel.org> - 2016-11-14 17:20 +0100
[PATCH 4/7] perf sched timehist: Add -w/--wakeups option Namhyung Kim <namhyung@kernel.org> - 2016-11-14 17:20 +0100
[PATCH 5/7] perf sched timehist: Add call graph options Namhyung Kim <namhyung@kernel.org> - 2016-11-14 17:20 +0100
[PATCH 6/7] perf sched timehist: Add -V/--cpu-visual option Namhyung Kim <namhyung@kernel.org> - 2016-11-14 17:20 +0100
[PATCH 3/7] perf sched timehist: Add summary options Namhyung Kim <namhyung@kernel.org> - 2016-11-14 17:20 +0100
[PATCH 7/7] perf sched: Add documentation for timehist options Namhyung Kim <namhyung@kernel.org> - 2016-11-14 17:30 +0100
Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v1) David Ahern <dsahern@gmail.com> - 2016-11-14 17:30 +0100
[PATCH RESEND 1/7] perf symbol: Print symbol offsets conditionally Namhyung Kim <namhyung@kernel.org> - 2016-11-14 17:40 +0100
Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v1) Ingo Molnar <mingo@kernel.org> - 2016-11-15 07:50 +0100
Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v1) Namhyung Kim <namhyung@kernel.org> - 2016-11-15 08:00 +0100
Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v1) Ingo Molnar <mingo@kernel.org> - 2016-11-15 08:40 +0100
Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v1) David Ahern <dsahern@gmail.com> - 2016-11-15 16:20 +0100
Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v1) Namhyung Kim <namhyung@kernel.org> - 2016-11-15 16:40 +0100
Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v1) David Ahern <dsahern@gmail.com> - 2016-11-15 19:30 +0100
csiph-web