lkml.org 
[lkml]   [2008]   [Dec]   [20]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    Date
    From
    SubjectRe: [PATCH][RFC 2/23]: SCST core
    Hi Vladislav,

    2008/12/18 Vladislav Bolkhovitin <vst@vlnb.net>:
    > Frédéric Weisbecker, on 12/14/2008 03:35 AM wrote:
    >>
    >> 2008/12/13 Vladislav Bolkhovitin <vst@vlnb.net>:
    >>>
    >>> 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@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

    \
     
     \ /
      Last update: 2008-12-20 14:09    [W:0.040 / U:1.776 seconds]
    ©2003-2016 Jasper Spaans. hosted at Digital OceanAdvertise on this site