lists.openwall.net   lists  /  announce  owl-users  owl-dev  john-users  john-dev  passwdqc-users  yescrypt  popa3d-users  /  oss-security  kernel-hardening  musl  sabotage  tlsify  passwords  /  crypt-dev  xvendor  /  Bugtraq  Full-Disclosure  linux-kernel  linux-netdev  linux-ext4  linux-hardening  linux-cve-announce  PHC 
Open Source and information security mailing list archives
 
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Date:	Sat, 20 Dec 2008 14:06:53 +0100
From:	"Frédéric Weisbecker" <fweisbec@...il.com>
To:	"Vladislav Bolkhovitin" <vst@...b.net>
Cc:	"Steven Rostedt" <srostedt@...hat.com>,
	"Sam Ravnborg" <sam@...nborg.org>, linux-scsi@...r.kernel.org,
	"James Bottomley" <James.Bottomley@...senpartnership.com>,
	"Andrew Morton" <akpm@...ux-foundation.org>,
	"FUJITA Tomonori" <fujita.tomonori@....ntt.co.jp>,
	"Mike Christie" <michaelc@...wisc.edu>,
	"Jeff Garzik" <jeff@...zik.org>,
	"Boaz Harrosh" <bharrosh@...asas.com>,
	"Linus Torvalds" <torvalds@...ux-foundation.org>,
	linux-kernel@...r.kernel.org, scst-devel@...ts.sourceforge.net,
	"Bart Van Assche" <bart.vanassche@...il.com>,
	"Nicholas A. Bellinger" <nab@...ux-iscsi.org>,
	"Ingo Molnar" <mingo@...e.hu>
Subject: Re: [PATCH][RFC 2/23]: SCST core

Hi Vladislav,

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

Powered by blists - more mailing lists