lkml.org 
[lkml]   [2011]   [Feb]   [18]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    Date
    From
    SubjectRe: [PATCH 3/3] perf events: add timehist option to record and report
    On Fri, Feb 18, 2011 at 07:28:20AM -0700, David Ahern wrote:
    >
    >
    > On 02/18/11 00:06, Ingo Molnar wrote:
    > >
    > > * David Ahern <daahern@cisco.com> wrote:
    > >
    > >> +--timehist::
    > >> + Generate time history output. This shows each sample with a wall-clock
    > >> + timestamp and address to symbol conversions. The samples are output in
    > >> + the same order they exist in the perf.data file. The --timehist option
    > >> + must be used with the record to get wall-clock timestamps.
    > >
    > > Displaying samples this way is very useful, but how is this different from trace
    > > output - i.e. 'perf script' output?
    > >
    > > There's a 'live logging mode' feature:
    > >
    > > perf record ./myworkload | perf inject -v -b | perf script -i -
    > >
    > > ( There's also some work going on to have a separate 'perf trace' utility that will
    > > output a linear trace of whatever events in perf.data are. )
    > >
    > > So unless i'm missing something it would be more useful to extend 'perf script' (or
    > > the upcoming 'perf trace') to list regular samples in a perf.data (i.e. not rely on
    > > -R raw trace data alone), and of course allow a straightforward utilization of real
    > > timestamps, when available.
    >
    > To date I have not seen any option to show samples with wall-clock
    > timestamps. In a sense it pretty-prints the -R format. This allows perf
    > samples to be compared to other log files / sources of data to resolve
    > an issue.
    >
    > For example:
    >
    > Time-of-Day Kernel Timestamp cpu Event Command PID
    > IP Symbol Name (DSO Name)
    > 22:40:13.831567 858005051634 1 context-switches kworker/1:0 8
    > ffffffff8103251e perf_event_task_sched_out ([kernel.kallsyms])
    >
    > 22:40:13.831683 858005168139 1 context-switches sshd 897
    > ffffffff8103251e perf_event_task_sched_out ([kernel.kallsyms])
    >
    > With the stack callchain option it dumps a line for each address in the
    > stack (columns abbreviated here for email):
    >
    > 07:24:37.527728 1 sshd 819 ffffffff8103251e perf_event_task_sched_out
    > ([kernel.kallsyms])
    > 07:24:37.527728 1 sshd 819 ffffffff81377231 schedule ([kernel.kallsyms])
    > 07:24:37.527728 1 sshd 819 ffffffff81377f3a
    > schedule_hrtimeout_range_clock ([kernel.kallsyms])
    > 07:24:37.527728 1 sshd 819 ffffffff81378016 schedule_hrtimeout_range
    > ([kernel.kallsyms])
    > 07:24:37.527728 1 sshd 819 ffffffff81103e15 poll_schedule_timeout
    > ([kernel.kallsyms])
    > 07:24:37.527728 1 sshd 819 ffffffff8110463c do_select ([kernel.kallsyms])
    > 07:24:37.527728 1 sshd 819 ffffffff811047f4 core_sys_select
    > ([kernel.kallsyms])
    > 07:24:37.527728 1 sshd 819 ffffffff81104929 sys_select
    > ([kernel.kallsyms])
    > 07:24:37.527728 1 sshd 819 ffffffff81002bc2 system_call
    > ([kernel.kallsyms])
    > 07:24:37.527728 1 sshd 819 7f56d4814e93 __GI_select
    > (/lib64/libc-2.12.90.so)
    > 07:24:37.527728 1 sshd 819 40560b run_builtin
    > (/tmp/build-perf/perf)
    > 07:24:37.527728 1 sshd 819 40580d handle_internal_command
    > (/tmp/build-perf/perf)
    > 07:24:37.527728 1 sshd 819 405959 run_argv
    > (/tmp/build-perf/perf)
    > 07:24:37.527728 1 sshd 819 405b63 main (/tmp/build-perf/perf)
    > 07:24:37.527728 1 sshd 819 7fa49de9fe7d __libc_start_main
    > (/lib64/libc-2.12.90.so)
    >
    >
    > This format has allowed us to do an in-depth analysis of scheduling
    > (record -e cs -c 1): we can see when was process running, for how long
    > it ran, why it was kicked off the processor, how long was it off the
    > processor, what ran in between schedulings, etc. If a log file shows a
    > process missing a heartbeat you can look at the perf data in the time
    > range and see if it had a chance to run. If not where was it blocked.

    Oh, in this case I strongly suggest you to use the tracepoint events.

    Look at the output of "perf list" and seek the events which name
    start with "sched:"

    sched:sched_kthread_stop [Tracepoint event]
    sched:sched_kthread_stop_ret [Tracepoint event]
    sched:sched_wait_task [Tracepoint event]
    sched:sched_wakeup [Tracepoint event]
    sched:sched_wakeup_new [Tracepoint event]
    sched:sched_switch [Tracepoint event]
    sched:sched_migrate_task [Tracepoint event]
    sched:sched_process_free [Tracepoint event]
    sched:sched_process_exit [Tracepoint event]
    sched:sched_process_wait [Tracepoint event]
    sched:sched_process_fork [Tracepoint event]
    sched:sched_stat_wait [Tracepoint event]
    sched:sched_stat_sleep [Tracepoint event]
    sched:sched_stat_iowait [Tracepoint event]
    sched:sched_stat_runtime [Tracepoint event]


    You have the sched:sched_switch event and many others.

    Just try:

    perf record -a -e sched:*
    perf script

    perf-4128 [000] 19242.870025: sched_stat_runtime: comm=perf pid=4128 runtime=7430405 [ns] vruntime=3530192223488
    perf-4128 [000] 19242.870042: sched_stat_runtime: comm=perf pid=4128 runtime=23142 [ns] vruntime=3530192246630 [n
    perf-4128 [000] 19242.870045: sched_stat_sleep: comm=kondemand/0 pid=59 delay=9979163 [ns]
    perf-4128 [000] 19242.870048: sched_wakeup: comm=kondemand/0 pid=59 prio=120 success=1 target_cpu=000
    perf-4128 [000] 19242.870063: sched_stat_runtime: comm=perf pid=4128 runtime=21581 [ns] vruntime=3530192268211 [n
    perf-4128 [000] 19242.870066: sched_stat_wait: comm=kondemand/0 pid=59 delay=21581 [ns]
    perf-4128 [000] 19242.870069: sched_switch: prev_comm=perf prev_pid=4128 prev_prio=120 prev_state=R ==> next_comm
    kondemand/0-59 [000] 19242.870091: sched_stat_runtime: comm=kondemand/0 pid=59 runtime=27362 [ns] vruntime=35301862739
    kondemand/0-59 [000] 19242.870094: sched_stat_wait: comm=perf pid=4128 delay=27362 [ns]
    kondemand/0-59 [000] 19242.870095: sched_switch: prev_comm=kondemand/0 prev_pid=59 prev_prio=120 prev_state=S ==> next

    And you can run your own script on these events:

    $ sudo ./perf script -g python
    generated Python script: perf-script.py

    Edit perf-script.py and then run it:

    $ perf script -s ./perf-script.py

    That also works for perl.

    The timestamps will be the cpu time and not the walltime, but at least that seems
    to be partly what you seek?


    \
     
     \ /
      Last update: 2011-02-18 19:01    [from the cache]
    ©2003-2014 Jasper Spaans. hosted at Digital Ocean