Re: [PATCH] initcall_debug: add deferred probe times

[Todd Poynor]

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

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