Re: [PATCH] initcall_debug: add deferred probe times

From: Greg Kroah-Hartman
Date: Tue Jul 25 2017 - 19:40:55 EST


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