Re: [PATCH] initcall_debug: add deferred probe times

[Greg Kroah-Hartman]

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@xxxxxxxxxx>
> ---
>  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