Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1696660 > unrolled thread

[PATCH] initcall_debug: add deferred probe times

Back to article view | Back to linux.kernel

Contents

  [PATCH] initcall_debug: add deferred probe times Todd Poynor <toddpoynor@google.com> - 2017-07-26 01:40 +0200
    Re: [PATCH] initcall_debug: add deferred probe times Greg Kroah-Hartman <gregkh@linuxfoundation.org> - 2017-07-26 01:50 +0200
      Re: [PATCH] initcall_debug: add deferred probe times Todd Poynor <toddpoynor@google.com> - 2017-07-26 05:10 +0200

#1696660 — [PATCH] initcall_debug: add deferred probe times

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

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));
+	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.
  */
@@ -106,7 +128,10 @@ static void deferred_probe_work_func(struct work_struct *work)
 		device_pm_unlock();
 
 		dev_dbg(dev, "Retrying from deferred list\n");
-		bus_probe_device(dev);
+		if (initcall_debug && !initcalls_done)
+			deferred_probe_debug(dev);
+		else
+			bus_probe_device(dev);
 
 		mutex_lock(&deferred_probe_mutex);
 
@@ -215,6 +240,7 @@ static int deferred_probe_initcall(void)
 	driver_deferred_probe_trigger();
 	/* Sort as many dependencies as possible before exiting initcalls */
 	flush_work(&deferred_probe_work);
+	initcalls_done = true;
 	return 0;
 }
 late_initcall(deferred_probe_initcall);
-- 
2.14.0.rc0.400.g1c36432dff-goog

[toc] | [next] | [standalone]

#1696665

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

[toc] | [prev] | [next] | [standalone]

#1696750

On Tue, Jul 25, 2017 at 4:40 PM, Greg Kroah-Hartman
<gregkh@linuxfoundation.org> wrote:
> 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?

This patch extends the existing initcall_debug functionality; I've
copied the methods used by do_one_initcall_debug() to compute and
report timing info in a compatible format.  If it's better to change
the way this is reported, I can also suggest changes to the existing
initcall_debug code.  cc'ed the maintainers (I should have in the
first place).

> 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?

analyze_boot.py parses the dmesg output printed by initcall_debug to
produce those graphs (and can also produce ftrace-based function
callgraphs).  The initcall_debug output printed (and graphed) for
deferred probe calls are lumped into a single entry
"deferred_probe_initcall".  This patch logs the times of the
individual deferred probe calls by device name, to better help
developers understand where the time is spent.  If this feature finds
favor, it may also be deemed useful to update analyze_boot.py to graph
this information.

>> 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?

dev_info() is fine by me, if the initcall_debug command line parameter
is specified I would think it shouldn't be required to use the debug
loglevel.  But we may want to change the existing initcall_debug
messages to use info loglevel as well.

> But look at the analyze_boot.py script, I think it does all of this for
> you automagically...
>
> thanks,
>
> greg k-h

Thanks -- Todd

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web