From mboxrd@z Thu Jan  1 00:00:00 1970
Return-Path: <linux-kernel-owner@vger.kernel.org>
Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand
        id S1751673AbdGYXkv (ORCPT <rfc822;w@1wt.eu>);
        Tue, 25 Jul 2017 19:40:51 -0400
Received: from mail.linuxfoundation.org ([140.211.169.12]:35464 "EHLO
        mail.linuxfoundation.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org
        with ESMTP id S1750886AbdGYXku (ORCPT
        <rfc822;linux-kernel@vger.kernel.org>);
        Tue, 25 Jul 2017 19:40:50 -0400
Date: Tue, 25 Jul 2017 16:40:42 -0700
From: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
To: Todd Poynor <toddpoynor@google.com>
Cc: linux-kernel@vger.kernel.org, android-kernel@google.com
Subject: Re: [PATCH] initcall_debug: add deferred probe times
Message-ID: <20170725234042.GA3256@kroah.com>
References: <20170725233159.89543-1-toddpoynor@google.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <20170725233159.89543-1-toddpoynor@google.com>
User-Agent: Mutt/1.8.3 (2017-05-23)
Sender: linux-kernel-owner@vger.kernel.org
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org

On Tue, Jul 25, 2017 at 04:31:59PM -0700, Todd Poynor wrote:
> initcall_debug attributes all deferred device probe retries for the
> late_initcall level to function deferred_probe_initcall.  Add logs of
> the individual device probe routines called, to identify which drivers
> are executing for how long during the initcall path.  Deferred probes
> that occur after initcall processing are not shown.
> 
> Example log messages added:
> 
> [    0.505119] deferred probe my-sound-device @ 6
> [    0.517656] deferred probe my-sound-device returned after 1227 usecs

Can't you subtract the timestamp number right there?

And doesn't the tools/power/pm-graph/ scripts do this type of thing
automatically for you to give you pretty graphs you can use to drill
down on what is taking how long and such?

> Signed-off-by: Todd Poynor <toddpoynor@google.com>
> ---
>  drivers/base/dd.c | 28 +++++++++++++++++++++++++++-
>  1 file changed, 27 insertions(+), 1 deletion(-)
> 
> diff --git a/drivers/base/dd.c b/drivers/base/dd.c
> index 4882f06d12df..6831cb48e9dd 100644
> --- a/drivers/base/dd.c
> +++ b/drivers/base/dd.c
> @@ -20,6 +20,7 @@
>  #include <linux/device.h>
>  #include <linux/delay.h>
>  #include <linux/dma-mapping.h>
> +#include <linux/init.h>
>  #include <linux/module.h>
>  #include <linux/kthread.h>
>  #include <linux/wait.h>
> @@ -53,6 +54,7 @@ static DEFINE_MUTEX(deferred_probe_mutex);
>  static LIST_HEAD(deferred_probe_pending_list);
>  static LIST_HEAD(deferred_probe_active_list);
>  static atomic_t deferred_trigger_count = ATOMIC_INIT(0);
> +static bool initcalls_done;
>  
>  /*
>   * In some cases, like suspend to RAM or hibernation, It might be reasonable
> @@ -61,6 +63,26 @@ static atomic_t deferred_trigger_count = ATOMIC_INIT(0);
>   */
>  static bool defer_all_probes;
>  
> +/*
> + * For initcall_debug, show the deferred probes executed in late_initcall
> + * processing.
> + */
> +static void deferred_probe_debug(struct device *dev)
> +{
> +	ktime_t calltime, delta, rettime;
> +	unsigned long long duration;
> +
> +	printk(KERN_DEBUG "deferred probe %s @ %i\n", dev_name(dev),
> +	       task_pid_nr(current));

_if_ I were to take something like this, it would be best to use
dev_info(), right?

But look at the analyze_boot.py script, I think it does all of this for
you automagically...

thanks,

greg k-h