Frédéric Weisbecker, on 12/14/2008 03:35 AM wrote:
2008/12/13 Vladislav Bolkhovitin <vst@xxxxxxxx>:
Also (maybe I simply miss something) looks like ftrace doesn't trace exit
from functions, only entrance to them. Is it true? Is it possibly to log
exit from functions as well?
That's true with 2.6.28, the function tracer traces on function entries only.
But there is an add-on on ftrace which let one to trace on entry and
on return, the function
graph tracer. This tracer uses this facility to output a graph of
function calls and measure
the time elapsed during each function call.
You can also register two custom handlers to do some things you need
on entry and on return.
Word "graph" is quite confusing. We don't need any graphs, we need a
plain execution path tracing as in the attached example (this is what's
currently done).
All the above functionality is almost what we need. The only thing left,
which I forgot to mention, is possibility to log also functions return value
on exit. This is what TRACE_EXIT_RES() in SCST does. Is it possible to add
those?
I want to add that on the function graph tracer. That can be done
pretty easily. The only
problem comes with the type of the return value. Would this tracer be
supposed to always
return a 64 bits value regardless of the real typ of the value? There
would be some pointless bytes
on most return values. I don't know how to proceed for this problem.
I think if tracer always returns machine word, as Ingo suggested, as
"%d(%x)" it would be more then sufficient. In the rest of 0.01% of cases
it wouldn't be hard to print a non-standard return value using
ftrace_printk() just before returning it.
And one more question. Is it possible to redirect ftrace tracing to serial
console or any other console (netconsole?)? It can be helpful to investigate
hard lockups in IRQ or with IRQs disabled.
Thanks!
Vlad
I would find it useful too. I thought about something like using
early_printk or something like
that...I don't know. That would be good to redirect the output to the
tty device of the user choice.
That would make ftrace a complete debug logging subsystem.
Dec 15 17:09:48 linux-c07e kernel: [ 738.535571] [2519]: ENTRY dev_user_ioctl
Dec 15 17:09:48 linux-c07e kernel: [ 738.535582] [2519]: dev_user_ioctl:1735:REGISTER_DEVICE
Dec 15 17:09:48 linux-c07e kernel: [ 738.535589] [2519]: ENTRY dev_user_register_dev
Dec 15 17:09:48 linux-c07e kernel: [ 738.535601] [2519]: ENTRY sgv_pool_create
Dec 15 17:09:48 linux-c07e kernel: [ 738.535610] [2519]: ENTRY sgv_pool_init
Dec 15 17:09:48 linux-c07e kernel: [ 738.535616] [2519]: sgv_pool_init:997:name dev0, sizeof(*obj)=52, clustering_type=0
Dec 15 17:09:48 linux-c07e kernel: [ 738.535626] [2519]: sgv_pool_init:1026:pages=1, size=76
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: sgv_pool_init:1026:pages=2, size=100
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: sgv_pool_init:1026:pages=4, size=148
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: sgv_pool_init:1026:pages=8, size=244
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: sgv_pool_init:1026:pages=16, size=436
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: sgv_pool_init:1026:pages=32, size=820
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: sgv_pool_init:1026:pages=64, size=1588
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: sgv_pool_init:1026:pages=128, size=3124
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: sgv_pool_init:1026:pages=256, size=52
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: sgv_pool_init:1026:pages=512, size=52
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: sgv_pool_init:1026:pages=1024, size=52
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: EXIT sgv_pool_init: 0
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: EXIT sgv_pool_create: 1
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: ENTRY sgv_pool_create
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: ENTRY sgv_pool_init
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: sgv_pool_init:997:name dev0-clust, sizeof(*obj)=52, clustering_type=1
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: sgv_pool_init:1026:pages=1, size=80
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: sgv_pool_init:1026:pages=2, size=108
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: sgv_pool_init:1026:pages=4, size=164
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: sgv_pool_init:1026:pages=8, size=276
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: sgv_pool_init:1026:pages=16, size=500
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: sgv_pool_init:1026:pages=32, size=948
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: sgv_pool_init:1026:pages=64, size=1844
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: sgv_pool_init:1026:pages=128, size=3636
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: sgv_pool_init:1026:pages=256, size=1076
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: sgv_pool_init:1026:pages=512, size=2100
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: sgv_pool_init:1026:pages=1024, size=52
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: EXIT sgv_pool_init: 0
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: EXIT sgv_pool_create: 1
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: ENTRY __dev_user_set_opt
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: __dev_user_set_opt:2580:dev dev0, parse_type 0, on_free_cmd_type 1, memory_reuse_type 1, partial_transfers_type 0, partial_len 0
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: ENTRY dev_user_setup_functions
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: EXIT dev_user_setup_functions
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: EXIT __dev_user_set_opt: 0
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: dev_user_register_dev:2499:dev b7bffad0, name dev0
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: ENTRY __scst_register_virtual_dev_driver
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: EXIT scst_dev_handler_check: 0
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: scst: __scst_register_virtual_dev_driver:1036:Virtual device handler dh-dev0 for type 1 registered successfully
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: EXIT __scst_register_virtual_dev_driver: 0
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: ENTRY scst_register_virtual_device
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: EXIT scst_dev_handler_check: 0
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: ENTRY scst_suspend_activity
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: scst_suspend_activity:484:suspend_count 0
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: ENTRY scst_susp_wait
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: scst_susp_wait:463:wait_event() returned 0
Dec 15 17:09:48 linux-c07e kernel: [ 738.538862] [2519]: EXIT scst_susp_wait: 0
