Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752671AbYLTNHM (ORCPT ); Sat, 20 Dec 2008 08:07:12 -0500 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1751431AbYLTNG4 (ORCPT ); Sat, 20 Dec 2008 08:06:56 -0500 Received: from qw-out-2122.google.com ([74.125.92.26]:40055 "EHLO qw-out-2122.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751409AbYLTNGz convert rfc822-to-8bit (ORCPT ); Sat, 20 Dec 2008 08:06:55 -0500 DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=gamma; h=message-id:date:from:to:subject:cc:in-reply-to:mime-version :content-type:content-transfer-encoding:content-disposition :references; b=fZDafFfTuYEV/8INhNzAKABXR3AywPXkCcqE4ybEjtx0Idyhh30MkCNOd8GyaDsAoY RhK5HViEv8y6nDxAqNc8yPXtPWZOaakhm64h2cEEpGnPYvG7mDYS5AtR+3JmPiMeijXB +zK6y9OYj5huU7cRrjKokzWNcgNMGZW2zN1dQ= Message-ID: Date: Sat, 20 Dec 2008 14:06:53 +0100 From: "=?ISO-8859-1?Q?Fr=E9d=E9ric_Weisbecker?=" To: "Vladislav Bolkhovitin" Subject: Re: [PATCH][RFC 2/23]: SCST core Cc: "Steven Rostedt" , "Sam Ravnborg" , linux-scsi@vger.kernel.org, "James Bottomley" , "Andrew Morton" , "FUJITA Tomonori" , "Mike Christie" , "Jeff Garzik" , "Boaz Harrosh" , "Linus Torvalds" , linux-kernel@vger.kernel.org, scst-devel@lists.sourceforge.net, "Bart Van Assche" , "Nicholas A. Bellinger" , "Ingo Molnar" In-Reply-To: <494A37E9.5000009@vlnb.net> MIME-Version: 1.0 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 8BIT Content-Disposition: inline References: <494009D7.4020602@vlnb.net> <49400ACD.3070502@vlnb.net> <20081210191213.GA15273@uranus.ravnborg.org> <49414DBE.6070801@vlnb.net> <20081211210917.GB27010@uranus.ravnborg.org> <4942BA85.3070408@vlnb.net> <1229118607.24995.18.camel@localhost.localdomain> <4943CAAB.4050008@vlnb.net> <494A37E9.5000009@vlnb.net> Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 9204 Lines: 217 Hi Vladislav, 2008/12/18 Vladislav Bolkhovitin : > Fr?d?ric Weisbecker, on 12/14/2008 03:35 AM wrote: >> >> 2008/12/13 Vladislav Bolkhovitin : >>> >>> 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/