[RFC] [PATCH 0/5] Teach perf tool to profile sleep times (V4)

* [RFC] [PATCH 0/5] Teach perf tool to profile sleep times (V4)
@ 2012-06-04  8:09 Andrew Vagin
  2012-06-04  8:09 ` [PATCH 1/5] sched: event: add trace events when a task starts executing on a cpu Andrew Vagin
                   ` (6 more replies)
  0 siblings, 7 replies; 15+ messages in thread
From: Andrew Vagin @ 2012-06-04  8:09 UTC (permalink / raw)
  Cc: Arun Sharma, Oleg Strikov, Steven Rostedt, Frederic Weisbecker,
	Ingo Molnar, Peter Zijlstra, linux-kernel

Do you want to know where your code waits locks for a long time?
Yes! It's for you. This feature helps you to find bottlenecks.

It's not artificial task. Once one of my colleague was investigating a
scalability problem. He pressed sysrq-t some times and tried to merge
call-chains by hand. But perf can do that better.

Here is fourth attempt to add this functionality in the kernel.

Previous attempts:
* [PATCH 0/4] trace: add ability to collect call chains of non-current task.

* [PATCH rh6 0/7] Teach perf tool to collect D-state statistics
This version doesn't work for non-root users.

* "sched/tracing: Add a new tracepoint for sleeptime" by Arun Sharma
It has been committed, but then reverted due to performance reason.

This series resolves a problem with events filtering and non-root users.
Before I tried to use sched_stat* events, but it occurs in a context of
another task. For this case logic of perf_event_context* doesn't work.

This series adds one more event sched:sched_switch_finish, it's sent
when a task starts executing on a cpu. When a task goes out from cpu,
sched:sched_switch is sent.

The time difference between sched_switch and sched_switch_finish is a time
when a task wasn't being executed on a cpu.

For profiling sleep time, events of both types should be collected and
filtered by a defined state (interruptible of uninterruptible sleep).

Then events should be post-processed with help "perf inject". It saves the time
of sched_switch event for each process and when it meets stat_switch_finish,
it sets time difference in sample->period and saves this new sample
in the new perf.data.

./perf record -e sched:sched_switch -g --filter 'prev_state == 1' \
	-e sched:sched_switch_finish --filter 'state == 1' -P  ~/foo

./perf inject -i ~/perf.data -o perf.data.new -s

A test program:
#include<unistd.h>
#include<time.h>
#include<sys/select.h>

int main()
{
          struct timespec ts1;
          struct timeval tv1;
          int i;
        long s;

          for (i = 0; i<  2; i++) {
                  ts1.tv_sec = 0;
                  ts1.tv_nsec = 10000000;
                  nanosleep(&ts1, NULL);

                  tv1.tv_sec = 0;
                  tv1.tv_usec = 40000;
                  select(0, NULL, NULL, NULL,&tv1);
                if (i % 100 == 0) {
                        s = time(NULL);
                        while (time(NULL) - s < 4);
                }
          }
        return 1;
}

Profiling results:
# Overhead  Command      Shared Object                  Symbol
# ........  .......  .................  ......................
#
   100.00%      foo  [kernel.kallsyms]  [k] finish_task_switch
                |
                --- finish_task_switch
                    __schedule
                    schedule
                   |          
                   |--79.85%-- schedule_hrtimeout_range_clock
                   |          schedule_hrtimeout_range
                   |          poll_schedule_timeout
                   |          do_select
                   |          core_sys_select
                   |          sys_select
                   |          system_call
                   |          __select
                   |          __libc_start_main
                   |          
                    --20.15%-- do_nanosleep
                              hrtimer_nanosleep
                              sys_nanosleep
                              system_call
                              __GI___libc_nanosleep
                              __libc_start_main

Andrew Vagin (5):
  event: add an event sched_switch_finish
  sched: send the event sched_switch before perf_event_task_sched_out
  sched: save a previous state on task_struct
  perf: teach "perf inject" to work with files
  perf: teach perf inject to merge sched_switch* events

 include/linux/sched.h        |    3 +
 include/trace/events/sched.h |   29 ++++++++++
 kernel/sched/core.c          |    3 +-
 tools/perf/builtin-inject.c  |  119 +++++++++++++++++++++++++++++++++++++++---
 4 files changed, 146 insertions(+), 8 deletions(-)

^ permalink raw reply	[flat|nested] 15+ messages in thread