[PATCH] drivers: base: initcall_debug logs for driver probe times

[PATCH] drivers: base: initcall_debug logs for driver probe times

[Todd Poynor]

From: Todd Poynor <toddpoynor@google.com>

Add initcall_debug logs for each driver device probe call, for example:

   probe of a3800000.ramoops returned after 3007 usecs

This replaces the previous code added to report times for deferred
probes.  It also reports OF platform bus device creates that were
formerly lumped together in a single entry for function
of_platform_default_populate_init, as well as helping to annotate other
initcalls that involve device probing.

Signed-off-by: Todd Poynor <toddpoynor@google.com>
---
 drivers/base/dd.c | 50 +++++++++++++++++++++++------------------------
 1 file changed, 24 insertions(+), 26 deletions(-)

diff --git a/drivers/base/dd.c b/drivers/base/dd.c
index 1435d7281c66..56db446a467a 100644
--- a/drivers/base/dd.c
+++ b/drivers/base/dd.c
@@ -62,26 +62,6 @@ static bool initcalls_done;
  */
 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));
-	calltime = ktime_get();
-	bus_probe_device(dev);
-	rettime = ktime_get();
-	delta = ktime_sub(rettime, calltime);
-	duration = (unsigned long long) ktime_to_ns(delta) >> 10;
-	printk(KERN_DEBUG "deferred probe %s returned after %lld usecs\n",
-	       dev_name(dev), duration);
-}
-
 /*
  * deferred_probe_work_func() - Retry probing devices in the active list.
  */
@@ -125,11 +105,7 @@ static void deferred_probe_work_func(struct work_struct *work)
 		device_pm_move_to_tail(dev);
 
 		dev_dbg(dev, "Retrying from deferred list\n");
-		if (initcall_debug && !initcalls_done)
-			deferred_probe_debug(dev);
-		else
-			bus_probe_device(dev);
-
+		bus_probe_device(dev);
 		mutex_lock(&deferred_probe_mutex);
 
 		put_device(dev);
@@ -527,6 +503,25 @@ static int really_probe(struct device *dev, struct device_driver *drv)
 	return ret;
 }
 
+/*
+ * For initcall_debug, show the driver probe time.
+ */
+static int really_probe_debug(struct device *dev, struct device_driver *drv)
+{
+	ktime_t calltime, delta, rettime;
+	unsigned long long duration;
+	int ret;
+
+	calltime = ktime_get();
+	ret = really_probe(dev, drv);
+	rettime = ktime_get();
+	delta = ktime_sub(rettime, calltime);
+	duration = (unsigned long long) ktime_to_ns(delta) >> 10;
+	printk(KERN_DEBUG "probe of %s returned after %lld usecs\n",
+	       dev_name(dev), duration);
+	return ret;
+}
+
 /**
  * driver_probe_done
  * Determine if the probe sequence is finished or not.
@@ -585,7 +580,10 @@ int driver_probe_device(struct device_driver *drv, struct device *dev)
 		pm_runtime_get_sync(dev->parent);
 
 	pm_runtime_barrier(dev);
-	ret = really_probe(dev, drv);
+	if (initcall_debug && !initcalls_done)
+		ret = really_probe_debug(dev, drv);
+	else
+		ret = really_probe(dev, drv);
 	pm_request_idle(dev);
 
 	if (dev->parent)
-- 
2.18.0.rc1.244.gcf134e6275-goog

Re: [PATCH] drivers: base: initcall_debug logs for driver probe times

[Greg Kroah-Hartman]

On Tue, Jun 19, 2018 at 07:39:03PM -0700, Todd Poynor wrote:
> From: Todd Poynor <toddpoynor@google.com>
> 
> Add initcall_debug logs for each driver device probe call, for example:
> 
>    probe of a3800000.ramoops returned after 3007 usecs
> 
> This replaces the previous code added to report times for deferred
> probes.  It also reports OF platform bus device creates that were
> formerly lumped together in a single entry for function
> of_platform_default_populate_init, as well as helping to annotate other
> initcalls that involve device probing.
> 
> Signed-off-by: Todd Poynor <toddpoynor@google.com>
> ---
>  drivers/base/dd.c | 50 +++++++++++++++++++++++------------------------
>  1 file changed, 24 insertions(+), 26 deletions(-)

New features with less lines of code, nice!

I'll queue this up soon, very good work.

greg k-h

Re: [PATCH] drivers: base: initcall_debug logs for driver probe times

[Todd Poynor]

[-- Attachment #1: Type: text/plain, Size: 378 bytes --]

On Tue, Jun 19, 2018 at 7:42 PM, Greg Kroah-Hartman <
gregkh@linuxfoundation.org> wrote:

> New features with less lines of code, nice!
>
> I'll queue this up soon, very good work.
>

Thanks, it was on a great suggestion from Rob Herring.  Previously I was
afraid to pollute or duplicate the existing initcall_debug logs, but this
complements the existing output nicely.


Todd

[-- Attachment #2: Type: text/html, Size: 853 bytes --]

Re: [PATCH] drivers: base: initcall_debug logs for driver probe times

[Rob Herring]

On Tue, Jun 19, 2018 at 8:39 PM, Todd Poynor <toddpoynor@gmail.com> wrote:
> From: Todd Poynor <toddpoynor@google.com>
>
> Add initcall_debug logs for each driver device probe call, for example:
>
>    probe of a3800000.ramoops returned after 3007 usecs
>
> This replaces the previous code added to report times for deferred
> probes.  It also reports OF platform bus device creates that were
> formerly lumped together in a single entry for function
> of_platform_default_populate_init, as well as helping to annotate other
> initcalls that involve device probing.
>
> Signed-off-by: Todd Poynor <toddpoynor@google.com>
> ---
>  drivers/base/dd.c | 50 +++++++++++++++++++++++------------------------
>  1 file changed, 24 insertions(+), 26 deletions(-)
>
> diff --git a/drivers/base/dd.c b/drivers/base/dd.c
> index 1435d7281c66..56db446a467a 100644
> --- a/drivers/base/dd.c
> +++ b/drivers/base/dd.c
> @@ -62,26 +62,6 @@ static bool initcalls_done;
>   */
>  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));
> -       calltime = ktime_get();
> -       bus_probe_device(dev);
> -       rettime = ktime_get();
> -       delta = ktime_sub(rettime, calltime);
> -       duration = (unsigned long long) ktime_to_ns(delta) >> 10;
> -       printk(KERN_DEBUG "deferred probe %s returned after %lld usecs\n",
> -              dev_name(dev), duration);
> -}
> -
>  /*
>   * deferred_probe_work_func() - Retry probing devices in the active list.
>   */
> @@ -125,11 +105,7 @@ static void deferred_probe_work_func(struct work_struct *work)
>                 device_pm_move_to_tail(dev);
>
>                 dev_dbg(dev, "Retrying from deferred list\n");
> -               if (initcall_debug && !initcalls_done)
> -                       deferred_probe_debug(dev);
> -               else
> -                       bus_probe_device(dev);
> -
> +               bus_probe_device(dev);
>                 mutex_lock(&deferred_probe_mutex);
>
>                 put_device(dev);
> @@ -527,6 +503,25 @@ static int really_probe(struct device *dev, struct device_driver *drv)
>         return ret;
>  }
>
> +/*
> + * For initcall_debug, show the driver probe time.
> + */
> +static int really_probe_debug(struct device *dev, struct device_driver *drv)
> +{
> +       ktime_t calltime, delta, rettime;
> +       unsigned long long duration;

Probably should be s64.

> +       int ret;
> +
> +       calltime = ktime_get();
> +       ret = really_probe(dev, drv);
> +       rettime = ktime_get();
> +       delta = ktime_sub(rettime, calltime);
> +       duration = (unsigned long long) ktime_to_ns(delta) >> 10;

Is avoiding a divide really worth optimizing here compared to the
flood of messages typically on the serial port? Just use ktime_to_us.
Perhaps just get rid of duration and do the conversion in the printk
arg.

> +       printk(KERN_DEBUG "probe of %s returned after %lld usecs\n",
> +              dev_name(dev), duration);

Including the return code here too would be good.

> +       return ret;
> +}
> +
>  /**
>   * driver_probe_done
>   * Determine if the probe sequence is finished or not.
> @@ -585,7 +580,10 @@ int driver_probe_device(struct device_driver *drv, struct device *dev)
>                 pm_runtime_get_sync(dev->parent);
>
>         pm_runtime_barrier(dev);
> -       ret = really_probe(dev, drv);
> +       if (initcall_debug && !initcalls_done)
> +               ret = really_probe_debug(dev, drv);
> +       else
> +               ret = really_probe(dev, drv);
>         pm_request_idle(dev);
>
>         if (dev->parent)
> --
> 2.18.0.rc1.244.gcf134e6275-goog
>

Re: [PATCH] drivers: base: initcall_debug logs for driver probe times

[Todd Poynor]

[-- Attachment #1: Type: text/plain, Size: 1602 bytes --]

On Wed, Jun 20, 2018 at 7:28 AM, Rob Herring <robh+dt@kernel.org> wrote:

> On Tue, Jun 19, 2018 at 8:39 PM, Todd Poynor <toddpoynor@gmail.com> wrote:
> ...
> > +static int really_probe_debug(struct device *dev, struct device_driver
> *drv)
> > +{
> > +       ktime_t calltime, delta, rettime;
> > +       unsigned long long duration;
>
> Probably should be s64.
>
> > +       int ret;
> > +
> > +       calltime = ktime_get();
> > +       ret = really_probe(dev, drv);
> > +       rettime = ktime_get();
> > +       delta = ktime_sub(rettime, calltime);
> > +       duration = (unsigned long long) ktime_to_ns(delta) >> 10;
>
> Is avoiding a divide really worth optimizing here compared to the
> flood of messages typically on the serial port? Just use ktime_to_us.
> Perhaps just get rid of duration and do the conversion in the printk
> arg.
>

Sure, the above is based on the existing code in init/main.c, I can send a
small update to that code separately.

> +       printk(KERN_DEBUG "probe of %s returned after %lld usecs\n",
> > +              dev_name(dev), duration);
>
> Including the return code here too would be good.
>

Will do.

While we're at it, I see newer runtime PM, etc. code now prints via
pr_info() level when initcall_debug is enabled, but I'll leave this at
debug level unless anybody feels both this and the existing code should
switch to info level.

And since the above is printed after initcall levels are complete, I'll
drop the code I added previously to ensure deferred probe calls, module
probes, etc. are no longer printed after that point.


> ...
>

Thanks -- Todd

[-- Attachment #2: Type: text/html, Size: 2787 bytes --]

Re: [PATCH] drivers: base: initcall_debug logs for driver probe times

[Todd Poynor]

[-- Attachment #1: Type: text/plain, Size: 747 bytes --]

On Wed, Jun 20, 2018 at 7:28 AM, Rob Herring <robh+dt@kernel.org> wrote:

> On Tue, Jun 19, 2018 at 8:39 PM, Todd Poynor <toddpoynor@gmail.com> wrote:
> ...
> > +       calltime = ktime_get();
> > +       ret = really_probe(dev, drv);
> > +       rettime = ktime_get();
> > +       delta = ktime_sub(rettime, calltime);
> > +       duration = (unsigned long long) ktime_to_ns(delta) >> 10;
>
> Is avoiding a divide really worth optimizing here compared to the
> flood of messages typically on the serial port? Just use ktime_to_us.
>

I also meant to mention that serial console output is typically disabled in
a boot time analysis run since it drastically affects the timing, but
still, not trying to optimize this sequence to that degree.

Todd

[-- Attachment #2: Type: text/html, Size: 1375 bytes --]