Re: [RFC PATCH] boot-time: instrument probes more

[Francesco Valla <francesco@valla.it>]

Hello,

On Monday, 9 December 2024 at 04:10:04 Bird, Tim <Tim.Bird@sony.com> wrote:
> ----
> Below is the patch that adds the extra instrumentation.  My quick question is, does this look useful?
> Can it be used to find the more problematic (ie long-duration) probe functions or drivers initializations?
> 

Yes, it looks useful to me. While an experienced developer _might_ be able to match
device names and drivers at a quick glance, that's not the case for everyone, in
particular on certain SoCs which are modelled at devicetree level with an exceptionally
high number of "generic" device nodes.

> ----
> diff --git a/drivers/base/dd.c b/drivers/base/dd.c
> index 0c3725c3eefa..5e19079b0a2b 100644
> --- a/drivers/base/dd.c
> +++ b/drivers/base/dd.c
> @@ -28,6 +28,7 @@
>  #include <linux/pm_runtime.h>
>  #include <linux/pinctrl/devinfo.h>
>  #include <linux/slab.h>
> +#include <linux/kallsyms.h>
>  
>  #include "base.h"
>  #include "power/power.h"
> @@ -732,8 +733,16 @@ static int really_probe(struct device *dev, struct device_driver *drv)
>  static int really_probe_debug(struct device *dev, struct device_driver *drv)
>  {
>  	ktime_t calltime, rettime;
> +	char fn_name[KSYM_SYMBOL_LEN];
> +	unsigned long addr = 0;
>  	int ret;
>  
> +	if (dev->bus->probe)
> +		addr = (unsigned long)dev->bus->probe;
> +	else if (drv->probe)
> +		addr = (unsigned long)drv->probe;
> +	sprint_symbol_no_offset(fn_name, addr);
> +
>  	calltime = ktime_get();
>  	ret = really_probe(dev, drv);
>  	rettime = ktime_get();
> @@ -742,8 +751,8 @@ static int really_probe_debug(struct device *dev, struct device_driver *drv)
>  	 * CONFIG_DYNAMIC_DEBUG and we want a simple 'initcall_debug' on the
>  	 * kernel commandline to print this all the time at the debug level.
>  	 */
> -	printk(KERN_DEBUG "probe of %s returned %d after %lld usecs\n",
> -		 dev_name(dev), ret, ktime_us_delta(rettime, calltime));
> +	printk(KERN_DEBUG "probe %s in driver %s for device %s returned %d after %lld usecs\n",
> +		 fn_name, drv->name, dev_name(dev), ret, ktime_us_delta(rettime, calltime));
>  	return ret;
>  }
>  
> diff --git a/drivers/base/platform.c b/drivers/base/platform.c
> index 76bfcba25003..ae15969c483a 100644
> --- a/drivers/base/platform.c
> +++ b/drivers/base/platform.c
> @@ -32,6 +32,7 @@
>  #include <linux/types.h>
>  #include <linux/iommu.h>
>  #include <linux/dma-map-ops.h>
> +#include <linux/kallsyms.h>
>  
>  #include "base.h"
>  #include "power/power.h"
> @@ -1381,6 +1382,9 @@ static int platform_probe(struct device *_dev)
>  	struct platform_driver *drv = to_platform_driver(_dev->driver);
>  	struct platform_device *dev = to_platform_device(_dev);
>  	int ret;
> +	char fn_name[KSYM_SYMBOL_LEN];
> +	unsigned long addr = 0;
> +
>  
>  	/*
>  	 * A driver registered using platform_driver_probe() cannot be bound
> @@ -1401,6 +1405,13 @@ static int platform_probe(struct device *_dev)
>  		goto out;
>  
>  	if (drv->probe) {
> +		if (initcall_debug) {
> +			addr = (unsigned long)drv->probe;
> +			sprint_symbol_no_offset(fn_name, addr);
> +
> +			printk(KERN_DEBUG "platform probe %s is being called\n", fn_name);
> +		}
> +
>  		ret = drv->probe(dev);
>  		if (ret)
>  			dev_pm_domain_detach(_dev, true);

Does this really belong here? Why not add a print inside really_probe_debug(), just
before the call to really_probe()? That approach would catch all probe types (not just
platform_probe) while containing the initcall_debug instrumentation inside dd.c

Regards,
Francesco