dynamic function tracing

dynamic function tracing

[Arjan van de Ven]

Hi,

I like the new function trace format with the {}'s a lot.. but I would
like to use it in a way I don't think would work with dynamic tracing.

What I would like to do (read: usecase) is mark a function as
interesting (because it has some performance issue or whatever),
and then I want to get all functions it calls (recursive) traced
automatically for the duration of that function.

This might be implementable by, on hitting the function to trace,
patching all trace points with a function that checks if it's this
thread (eg this "current"), and if so, traces the call. 
I realize it's not going to be super cheap, so it needs to be one-shot,
but it'll form a really strong usecase in practice...


-- 
Arjan van de Ven 	Intel Open Source Technology Centre
For development, discussion and tips for power savings, 
visit http://www.lesswatts.org

Re: dynamic function tracing

[Frank Ch. Eigler]

arjan wrote:

> [...]  What I would like to do (read: usecase) is mark a function as
> interesting (because it has some performance issue or whatever), and
> then I want to get all functions it calls (recursive) traced
> automatically for the duration of that function. [...]

FWIW, the systemtap expression for this is:

# stap para-callgraph.stp 'kernel.function("FOO")' 'kernel.function("BAR")'

where "FOO" is a pattern matching all the interesting functions that
BAR might indirectly call, and BAR is a pattern matching the trigger
function(s), whose call lifetime the thread's FOO calls should be
included.  Some latent problems are still preventing kprobes-based
probes from working quite everywhere in the kernel, so FOO/BAR can't
yet be something quite as broad as kernel.function("*").  But
restricted to individual drivers or source subtrees, it tends to work.

On utrace-patched kernels and current systemtap, and dwarf debug info
all around, those patterns can also refer to user-space functions:

# stap para-callgraph.stp 'module("ext3").function("*")' 'process("ls").function("main")' -c ls

     0 ls(13543):->ext3_permission inode=0xffff88032e1b0190 mask=0x1 
     8 ls(13543): ->ext3_check_acl inode=0xffff88032e1b0190 mask=0x1 
    12 ls(13543):  ->ext3_get_acl inode=0xffff88032e1b0190 type=0x8000 
    16 ls(13543):   ->ext3_iget_acl inode=0xffff88032e1b0190 i_acl=0xffff88032e1b00d8 
    20 ls(13543):   <-ext3_iget_acl return=0x0 
    23 ls(13543):  <-ext3_get_acl return=0x0 
    26 ls(13543): <-ext3_check_acl return=0xfffffffffffffff5 
    29 ls(13543):<-ext3_permission return=0x0 
     0 ls(13543):->ext3_permission inode=0xffff88032e057b70 mask=0x1 
     4 ls(13543): ->ext3_check_acl inode=0xffff88032e057b70 mask=0x1 
     7 ls(13543):  ->ext3_get_acl inode=0xffff88032e057b70 type=0x8000 
    11 ls(13543):   ->ext3_iget_acl inode=0xffff88032e057b70 i_acl=0xffff88032e057ab8 
[...]
  6390 ls(13543):   ->ext3_check_dir_entry function=0xffffffffa00461a9 dir=0xffff88031b49b250 de=0xffff88031581fc58 bh=0xffff88031b46d580 offset=0x1c58 
  6393 ls(13543):   <-ext3_check_dir_entry return=0x1 
  6397 ls(13543):   ->ext3fs_dirhash name=0xffff88031581fc60 len=0xc hinfo=0xffff8802ea881d98 
  6401 ls(13543):    ->str2hashbuf msg=0xffff88031581fc60 len=0xc buf=0xffff8802ea881c68 num=0x4 
  6404 ls(13543):    <-str2hashbuf 
  6407 ls(13543):   <-ext3fs_dirhash return=0x0 
  6412 ls(13543):   ->ext3_htree_store_dirent dir_file=0xffff8801005bc480 hash=0x188f0bd6 minor_hash=0x4497695a dirent=0xffff88031581fc58 
  6416 ls(13543):    ->kzalloc size=0x3d flags=0xd0 
  6420 ls(13543):    <-kzalloc return=0xffff880172712770 
  6423 ls(13543):   <-ext3_htree_store_dirent return=0x0 
  6428 ls(13543):   ->ext3_check_dir_entry function=0xffffffffa00461a9 dir=0xffff88031b49b250 de=0xffff88031581fc6c bh=0xffff88031b46d580 offset=0x1c6c 
  6432 ls(13543):   <-ext3_check_dir_entry return=0x1 
[...]
   254 ls(13543):       <-ext3_get_group_desc return=0xffff880326e493e0 
   258 ls(13543):       ->constant_test_bit nr=0x0 addr=0xffff88029092a000 
   262 ls(13543):       <-constant_test_bit return=0x1 
   265 ls(13543):      <-__ext3_get_inode_loc return=0x0 
   268 ls(13543):     <-ext3_get_inode_loc return=0x0 
   273 ls(13543):     ->__ext3_journal_get_write_access where=0xffffffffa0044410 handle=0xffff88032508c000 bh=0xffff88029092a000 
   277 ls(13543):     <-__ext3_journal_get_write_access return=0x0 
   281 ls(13543):    <-ext3_reserve_inode_write return=0x0 
   286 ls(13543):    ->ext3_mark_iloc_dirty handle=0xffff88032508c000 inode=0xffff880162d62008 iloc=0xffff8802ea8818a8 
   290 ls(13543):     ->ext3_get_inode_flags ei=0xffff880162d61e78 
   293 ls(13543):     <-ext3_get_inode_flags 
   298 ls(13543):     ->__ext3_journal_dirty_metadata where=0xffffffffa0044430 handle=0xffff88032508c000 bh=0xffff88029092a000 
   302 ls(13543):     <-__ext3_journal_dirty_metadata return=0x0 
   306 ls(13543):     ->brelse bh=0xffff88029092a000 
   309 ls(13543):     <-brelse 
   312 ls(13543):    <-ext3_mark_iloc_dirty return=0x0 
   315 ls(13543):   <-ext3_mark_inode_dirty return=0x0 
   319 ls(13543):   ->__ext3_journal_stop where=0xffffffffa00443f0 handle=0xffff88032508c000 
   322 ls(13543):   <-__ext3_journal_stop return=0x0 
   325 ls(13543):  <-ext3_dirty_inode 
   329 ls(13543):  ->__ext3_journal_stop where=0xffffffffa0044780 handle=0xffff88032508c000 
   334 ls(13543):  <-__ext3_journal_stop return=0x0 
   337 ls(13543): <-ext3_ordered_write_end return=0x40 
   342 ls(13543):<-ext3_file_write return=0x40 

- FChE

Re: dynamic function tracing

[Steven Rostedt]

On Fri, 2008-11-28 at 10:19 -0800, Arjan van de Ven wrote:
> Hi,
> 
> I like the new function trace format with the {}'s a lot.. but I would
> like to use it in a way I don't think would work with dynamic tracing.
> 
> What I would like to do (read: usecase) is mark a function as
> interesting (because it has some performance issue or whatever),
> and then I want to get all functions it calls (recursive) traced
> automatically for the duration of that function.
> 
> This might be implementable by, on hitting the function to trace,
> patching all trace points with a function that checks if it's this
> thread (eg this "current"), and if so, traces the call. 
> I realize it's not going to be super cheap, so it needs to be one-shot,
> but it'll form a really strong usecase in practice...

It would not be wise to enable the function pointer at that moment. But
what we could do is have a function trace enabled that will flag when a
function is hit. Then it could start tracing all functions until it
returns. This would be possible.

What we need is a better way to attach the function tracer with the
function graph.

-- Steve