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

[fche@redhat.com (Frank Ch. Eigler)]

Hi -


xieliang007 wrote:

> Probably it's a newbie question, to be honest, i am new to SystemTap,
> currently i want to capture the kernel stack trace if "sys_write" runs
> too long, if that i could know where it sucks.

OK.


> [...] probe kernel.function("sys_write").return [...]
>    print_backtrace();

> Returning from:  0xffffffff81176f90 : sys_write+0x0/0x90 [kernel]
> Returning to  :  0xffffffff8100b0f2 : system_call_fastpath+0x16/0x1b [kernel]
>
> It doesn't show my "expected" kernel stack trace,e.g. file system or
> block layer related stack trace. 

The expectation is mistaken.  By the time that sys_write returns, all
that kernel activity is in the past, and will have left no trace on
the stack.

> How to archive that? Any pointers will be highly appreciated!

Not easy.  

One way could be to sample the kernel backtrace (from probe
timer.profile) while a sys_write is in effect.  Attributing the
backtraces to the particular thread suffering from a slow sys_write is
going to be tricky, but maybe this could work:

      global backtraces%
      global active
      probe syscall.write { 
            active[tid()]=1 
      }
      probe timer.profile {
            if (! (tid() in active)) next;
            backtraces[tid(), backtrace()] <<< 1
      }
      probe syscall.write.return { 
            delete active[tid()]
            elapsed = gettimeofday_ms() - @entry(gettimeofday_ms())
            if (elapsed <= 4)
                next; // oops, leaves behind backtraces[] records
            printf("%s[%d] sleepy for %d ms:\n", execname(), tid(), elapsed)
            foreach ([t,bt] in backtraces- limit /* top */ 10)
                    if (t == tid()) {
                       printf("\n%d hits:\n", @count(backtraces[t,bt]))
                       print_stack(bt) 
                       }
      }

      # stap --all-modules FOO.stp


- FChE