Re: How to get the detailed kernel stack trace if specified fuction takes too long to finish?

[Josh Stone <jistone at redhat dot com>]

On 04/02/2014 07:47 PM, liang xie wrote:
> Yeh, systemtap-1.8 works for me, thanks! now i can get strace trace
> like this with the above scheduler script:
> long sys_write in tid 11892
>  0xffffffff814ed0a8 : thread_return+0x6d6/0x77e [kernel] (inexact)
>  0xffffffff812c4a41 : intel_idle+0xc1/0x170 [kernel] (inexact)
>  0xffffffff81097c6d : sched_clock_cpu+0xcd/0x110 [kernel] (inexact)
>  0xffffffff81009e3e : cpu_idle+0xee/0x110 [kernel] (inexact)
>  0xffffffff814e5f23 : start_secondary+0x202/0x245 [kernel] (inexact)
[...]
> But still no interesting filesystem related stack trace be found

Oh, I see, I made a mistake here:

> probe kernel.trace("sched_switch") {
>   t = task_tid($next)

The tracepoint will run when we are *about* to switch to $next, but
haven't yet, so the backtrace is for the previous task.  That appears to
be the idle task, so at least it seems clear you're not cpu-bound.

We have a 'scheduler.cpu_on' tapset which may work better.  That puts a
kprobe on "finish_task_switch", so it should be the right context for a
backtrace.  Like:

global start_time
probe syscall.write { start_time[tid()] = gettimeofday_us() }
probe syscall.write.return { delete start_time[tid()] }
probe scheduler.cpu_on {
  t = tid()
  if (t in start_time && gettimeofday_us() - start_time[t] > 100000)
  {
    printf("long sys_write in tid %d\n", t)
    print_backtrace()
    delete start_time[t]
  }
}