cat <debugfs_dir>/tracing/trace
you can get these at the end of the outputs:
1) | nameidata_to_filp() {
1) | __dentry_open() {
1) | file_move() {
1) 0.834 us | _raw_spin_lock();
1) 0.926 us | _raw_spin_unlock();
1) 4.768 us | }
!!!! file_move() is really called by __dentry_open()
1) | kmem_cache_alloc_notrace() {
1) 5.879 us | memset();
1) + 12.390 us | }
1) 1.025 us | mutex_lock();
1) | kmem_cache_alloc_notrace() {
1) 0.929 us | memset();
1) 3.329 us | }
1) 1.195 us | memcpy();
1) 1.026 us | __mutex_init();
!!!! the above are actually called by __tracing_open() which called by __dentry_open()
(But at the first I was confused, I wondered why __dentry_open() calls them.)
1) | kmem_cache_alloc_notrace() {
1) 0.978 us | memset();
1) 2.745 us | }
1) | __alloc_percpu() {
1) | pcpu_alloc() {
1) 1.053 us | mutex_lock();
1) 1.282 us | _raw_spin_lock_irqsave();
1) | pcpu_size_to_slot() {
1) 0.819 us | __pcpu_size_to_slot();
1) 5.455 us | }
1) 1.135 us | pcpu_need_to_extend();
1) | pcpu_alloc_area() {
1) | pcpu_chunk_slot() {
1) | pcpu_size_to_slot() {
1) 0.813 us | __pcpu_size_to_slot();
1) 2.535 us | }
1) 8.349 us | }
1) 1.160 us | memmove();
1) | pcpu_chunk_relocate() {
1) | pcpu_chunk_slot() {
1) | pcpu_size_to_slot() {
1) 0.803 us | __pcpu_size_to_slot();
1) 2.478 us | }
1) 4.129 us | }
1) 8.583 us | }
1) + 29.665 us | }
1) 1.038 us | _raw_spin_unlock_irqrestore();
1) 1.178 us | pcpu_next_pop();
1) 1.087 us | pcpu_chunk_addr();
1) 0.975 us | memset();
1) 0.821 us | pcpu_chunk_addr();
1) 0.943 us | memset();
1) 0.896 us | mutex_unlock();
1) + 75.625 us | }
1) + 77.453 us | }
!!!! the above are actually called by graph_trace_open() which called by __tracing_open()
== real graph ==:
father_fun()
child_fun()
notrace_child_fun()
grandchild_fun1()
grandchild_fun2()
===function_graph shows===>
father_fun()
child_fun()
grandchild_fun1()
grandchild_fun2()
When the notrace function calls traceable function, function_graph will
get wrong depth of functions, and show wrong graph.
Is there any method to fix it?
Lai
On Wed, Jan 06, 2010 at 06:44:02PM +0800, Lai Jiangshan wrote:
> cat <debugfs_dir>/tracing/trace
> you can get these at the end of the outputs:
>
> 1) | nameidata_to_filp() {
> 1) | __dentry_open() {
> 1) | file_move() {
> 1) 0.834 us | _raw_spin_lock();
> 1) 0.926 us | _raw_spin_unlock();
> 1) 4.768 us | }
>
> !!!! file_move() is really called by __dentry_open()
>
> 1) | kmem_cache_alloc_notrace() {
> 1) 5.879 us | memset();
> 1) + 12.390 us | }
> 1) 1.025 us | mutex_lock();
> 1) | kmem_cache_alloc_notrace() {
> 1) 0.929 us | memset();
> 1) 3.329 us | }
> 1) 1.195 us | memcpy();
> 1) 1.026 us | __mutex_init();
>
> !!!! the above are actually called by __tracing_open() which called by __dentry_open()
> (But at the first I was confused, I wondered why __dentry_open() calls them.)
>
> 1) | kmem_cache_alloc_notrace() {
> 1) 0.978 us | memset();
> 1) 2.745 us | }
> 1) | __alloc_percpu() {
> 1) | pcpu_alloc() {
> 1) 1.053 us | mutex_lock();
> 1) 1.282 us | _raw_spin_lock_irqsave();
> 1) | pcpu_size_to_slot() {
> 1) 0.819 us | __pcpu_size_to_slot();
> 1) 5.455 us | }
> 1) 1.135 us | pcpu_need_to_extend();
> 1) | pcpu_alloc_area() {
> 1) | pcpu_chunk_slot() {
> 1) | pcpu_size_to_slot() {
> 1) 0.813 us | __pcpu_size_to_slot();
> 1) 2.535 us | }
> 1) 8.349 us | }
> 1) 1.160 us | memmove();
> 1) | pcpu_chunk_relocate() {
> 1) | pcpu_chunk_slot() {
> 1) | pcpu_size_to_slot() {
> 1) 0.803 us | __pcpu_size_to_slot();
> 1) 2.478 us | }
> 1) 4.129 us | }
> 1) 8.583 us | }
> 1) + 29.665 us | }
> 1) 1.038 us | _raw_spin_unlock_irqrestore();
> 1) 1.178 us | pcpu_next_pop();
> 1) 1.087 us | pcpu_chunk_addr();
> 1) 0.975 us | memset();
> 1) 0.821 us | pcpu_chunk_addr();
> 1) 0.943 us | memset();
> 1) 0.896 us | mutex_unlock();
> 1) + 75.625 us | }
> 1) + 77.453 us | }
>
> !!!! the above are actually called by graph_trace_open() which called by __tracing_open()
>
> == real graph ==:
>
> father_fun()
> child_fun()
> notrace_child_fun()
> grandchild_fun1()
> grandchild_fun2()
>
> ===function_graph shows===>
>
> father_fun()
> child_fun()
> grandchild_fun1()
> grandchild_fun2()
>
> When the notrace function calls traceable function, function_graph will
> get wrong depth of functions, and show wrong graph.
>
> Is there any method to fix it?
I dont think so..
AFAIK the depth computation is based on the traced functions, and there's
no other 'depth related' input apart from them.
jirka
>
> Lai
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at http://www.tux.org/lkml/
On Wed, 2010-01-06 at 14:08 +0100, Jiri Olsa wrote:
> On Wed, Jan 06, 2010 at 06:44:02PM +0800, Lai Jiangshan wrote:
> > cat <debugfs_dir>/tracing/trace
> > you can get these at the end of the outputs:
> >
> > 1) | nameidata_to_filp() {
> > 1) | __dentry_open() {
> > 1) | file_move() {
> > 1) 0.834 us | _raw_spin_lock();
> > 1) 0.926 us | _raw_spin_unlock();
> > 1) 4.768 us | }
> >
> > !!!! file_move() is really called by __dentry_open()
?? And that is exactly what the above shows.
> >
> > 1) | kmem_cache_alloc_notrace() {
> > 1) 5.879 us | memset();
> > 1) + 12.390 us | }
> > 1) 1.025 us | mutex_lock();
> > 1) | kmem_cache_alloc_notrace() {
> > 1) 0.929 us | memset();
> > 1) 3.329 us | }
> > 1) 1.195 us | memcpy();
> > 1) 1.026 us | __mutex_init();
> >
> > !!!! the above are actually called by __tracing_open() which called by __dentry_open()
> > (But at the first I was confused, I wondered why __dentry_open() calls them.)
> >
> > 1) | kmem_cache_alloc_notrace() {
> > 1) 0.978 us | memset();
> > 1) 2.745 us | }
> > 1) | __alloc_percpu() {
> > 1) | pcpu_alloc() {
> > 1) 1.053 us | mutex_lock();
> > 1) 1.282 us | _raw_spin_lock_irqsave();
> > 1) | pcpu_size_to_slot() {
> > 1) 0.819 us | __pcpu_size_to_slot();
> > 1) 5.455 us | }
> > 1) 1.135 us | pcpu_need_to_extend();
> > 1) | pcpu_alloc_area() {
> > 1) | pcpu_chunk_slot() {
> > 1) | pcpu_size_to_slot() {
> > 1) 0.813 us | __pcpu_size_to_slot();
> > 1) 2.535 us | }
> > 1) 8.349 us | }
> > 1) 1.160 us | memmove();
> > 1) | pcpu_chunk_relocate() {
> > 1) | pcpu_chunk_slot() {
> > 1) | pcpu_size_to_slot() {
> > 1) 0.803 us | __pcpu_size_to_slot();
> > 1) 2.478 us | }
> > 1) 4.129 us | }
> > 1) 8.583 us | }
> > 1) + 29.665 us | }
> > 1) 1.038 us | _raw_spin_unlock_irqrestore();
> > 1) 1.178 us | pcpu_next_pop();
> > 1) 1.087 us | pcpu_chunk_addr();
> > 1) 0.975 us | memset();
> > 1) 0.821 us | pcpu_chunk_addr();
> > 1) 0.943 us | memset();
> > 1) 0.896 us | mutex_unlock();
> > 1) + 75.625 us | }
> > 1) + 77.453 us | }
> >
> > !!!! the above are actually called by graph_trace_open() which called by __tracing_open()
> >
> > == real graph ==:
> >
> > father_fun()
> > child_fun()
> > notrace_child_fun()
> > grandchild_fun1()
> > grandchild_fun2()
> >
> > ===function_graph shows===>
> >
> > father_fun()
> > child_fun()
> > grandchild_fun1()
> > grandchild_fun2()
> >
> > When the notrace function calls traceable function, function_graph will
> > get wrong depth of functions, and show wrong graph.
> >
> > Is there any method to fix it?
> I dont think so..
>
> AFAIK the depth computation is based on the traced functions, and there's
> no other 'depth related' input apart from them.
Right.
Honestly, if you think about it, the "father_fun()" does call those
grandchild_fun() functions. Just indirectly. I don't find anything wrong
with this.
You get the same issue if gcc decides to inline a function, since those
inlined functions don't get traced either.
-- Steve
>Steven Rostedt wrote:
>>On Wed, 2010-01-06 at 14:08 +0100, Jiri Olsa wrote:
>>> On Wed, Jan 06, 2010 at 06:44:02PM +0800, Lai Jiangshan wrote:
>>> == real graph ==:
>>>
>>> father_fun()
>>> child_fun()
>>> notrace_child_fun()
>>> grandchild_fun1()
>>> grandchild_fun2()
>>>
>>> ===function_graph shows===>
>>>
>>> father_fun()
>>> child_fun()
>>> grandchild_fun1()
>>> grandchild_fun2()
>>>
>>> When the notrace function calls traceable function, function_graph will
>>> get wrong depth of functions, and show wrong graph.
>>>
>>> Is there any method to fix it?
>> I dont think so..
>>
>> AFAIK the depth computation is based on the traced functions, and there's
>> no other 'depth related' input apart from them.
>
> Right.
>
>
> Honestly, if you think about it, the "father_fun()" does call those
> grandchild_fun() functions. Just indirectly. I don't find anything wrong
> with this.
>
> You get the same issue if gcc decides to inline a function, since those
> inlined functions don't get traced either.
Well, there is at least one thing different that could be used to indicate
that we're "down" farther in the call nesting, and that is stack depth.
In the example above, grandchild_fun1() is going to have a lower stack position
than child_fun(). So you might be able to use 'sp' to distinguish between
children and lower descendents.
You could potentially use this as an indicator for increased
indentation, but I'm not sure how accurate it is.
This might be different from the inline case, where the compiler usually
does not build a stack frame for the "called" code. But you also might
get false positives from variables declared inside in-function blocks
(or from other compiler oddities).
I would lean towards Steve's answer, that it doesn't matter too much.
Invisibility in the trace log, and the possible confusion it creates,
is the price you pay for 'notrace'.
Just my 2 cents.
-- Tim
=============================
Tim Bird
Architecture Group Chair, CE Linux Forum
Senior Staff Engineer, Sony Corporation of America
=============================