Re: [PATCH][RFC 2/23]: SCST core

From: Frédéric Weisbecker
Date: Sat Dec 20 2008 - 08:07:13 EST

Hi Vladislav,

2008/12/18 Vladislav Bolkhovitin <vst@xxxxxxxx>:
> 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).


The word graph is actually here to explain here that we not only trace
each function call
but we can actually retrieve all of the call path of a function and
then draw it as if it was
C code:

0) ! 108.528 us | }
0) | irq_exit() {
0) | do_softirq() {
0) | __do_softirq() {
0) 0.895 us | __local_bh_disable();
0) | run_timer_softirq() {
0) 0.827 us | hrtimer_run_pending();
0) 1.226 us | _spin_lock_irq();
0) | _spin_unlock_irq() {
0) 6.550 us | }
0) 0.924 us | _local_bh_enable();
0) + 12.129 us | }
0) + 13.911 us | }
0) 0.707 us | idle_cpu();
0) + 17.009 us | }
0) ! 137.419 us | }
0) <========== |
0) 1.045 us | }
0) ! 148.908 us | }
0) ! 151.022 us | }
0) ! 153.022 us | }
0) 0.963 us | journal_mark_dirty();
0) 0.925 us | __brelse();


>>> 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.
>

Yeah, I will do some tests to see if I can have a relevant result....


>>> 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.


ditto, I will try to do something to early_printk() a trace instead of
inserting into the ring buffer.
That could be a trace_option as an example.


> 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
>
>
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/