Hello Tim,
On Saturday, 21 December 2024 15:47:54 CET you wrote:
> Hello,
>
> On Monday, 9 December 2024 at 04:10:04 Bird, Tim <Tim.Bird@xxxxxxxx> 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
>
I had some spare time and I tried to write a patch that maintains the format
of the "return" message (because of backward compatibility) while adding the
details you inserted just before the probe in dd.c.
I then used it on the Beagleplay and I can confirm this helps a lot.
Thank you!
Regards,
Francesco
---
drivers/base/dd.c | 21 +++++++++++++++++----
1 file changed, 17 insertions(+), 4 deletions(-)
diff --git a/drivers/base/dd.c b/drivers/base/dd.c
index f0e4b4aba885..e33ae82064ed 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,16 +733,28 @@ static int really_probe(struct device *dev, const struct device_driver *drv)
static int really_probe_debug(struct device *dev, const struct device_driver *drv)
{
ktime_t calltime, rettime;
+ char fn_name[KSYM_SYMBOL_LEN];
+ unsigned long addr = 0;
int ret;
- calltime = ktime_get();
- ret = really_probe(dev, drv);
- rettime = ktime_get();
+ 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);
+
/*
- * Don't change this to pr_debug() because that requires
+ * Don't change this or the one below to pr_debug() because that requires
* 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 "calling probe %s in driver %s for device %s\n",
+ fn_name, drv->name, dev_name(dev));
+
+ calltime = ktime_get();
+ ret = really_probe(dev, drv);
+ rettime = ktime_get();
+
printk(KERN_DEBUG "probe of %s returned %d after %lld usecs\n",
dev_name(dev), ret, ktime_us_delta(rettime, calltime));
return ret;
--
2.47.1
