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

[liang xie]

Hi Josh,

Just report back, the last one is pretty helpful and works for my
situation, coooool:)  Thanks a lot!

On Fri, Apr 4, 2014 at 12:24 AM, Josh Stone <jistone@redhat.com> wrote:
> 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]
>   }
> }