[RFC] driver core: add a dbg printk for successful probes

Dan Carpenter posted 1 patch 1 month ago
[RFC] driver core: add a dbg printk for successful probes
Posted by Dan Carpenter 1 month ago
Hi Laura, and Nicolas,

I've been thinking about the driver probing talk you gave last year.  The
talk was about how tricky it is sometimes to determine which drivers have
probed successfully.  The drivers might be built into the kernel instead of
as a module, for example.  The idea was that we could make a list of
drivers we expected to probe successfully and find regressions in probe
that way.

Why couldn't we just add a printk in call_driver_probe() and then we could
pass

	dd.dyndbg="func call_driver_probe +p"

at the kernel command line.

On my qemu system the `dmesg | grep succeeded` looks like this:

[    0.135501] reg-dummy reg-dummy: probing reg-dummy succeeded
[    0.169490] psci-cpuidle-domain psci: probing psci-cpuidle-domain succeeded
[    0.188039] ctrl 9000000.pl011:0: probing ctrl succeeded
[    0.188598] port 9000000.pl011:0.0: probing port succeeded
[    0.206720] uart-pl011 9000000.pl011: probing uart-pl011 succeeded
[    1.071943] pl061_gpio 9030000.pl061: probing pl061_gpio succeeded
[    1.117740] pci-host-generic 4010000000.pcie: probing pci-host-generic succeeded
[    1.159963] virtio-mmio a003e00.virtio_mmio: probing virtio-mmio succeeded
[    1.166752] virtio-pci 0000:00:01.0: probing virtio-pci succeeded
[    1.168180] virtio-pci 0000:00:02.0: probing virtio-pci succeeded
[    1.173959] virtio-pci 0000:00:03.0: probing virtio-pci succeeded
[    1.178934] ctrl serial8250:0: probing ctrl succeeded
[    1.179059] port serial8250:0.0: probing port succeeded
[    1.182032] port serial8250:0.1: probing port succeeded
[    1.182490] port serial8250:0.2: probing port succeeded
[    1.182916] port serial8250:0.3: probing port succeeded
[    1.183309] port serial8250:0.4: probing port succeeded
[    1.183705] port serial8250:0.5: probing port succeeded
[    1.185558] port serial8250:0.6: probing port succeeded
[    1.185962] port serial8250:0.7: probing port succeeded
[    1.186352] port serial8250:0.8: probing port succeeded
[    1.189519] port serial8250:0.9: probing port succeeded
[    1.189972] port serial8250:0.10: probing port succeeded
[    1.190378] port serial8250:0.11: probing port succeeded
[    1.190791] port serial8250:0.12: probing port succeeded
[    1.191180] port serial8250:0.13: probing port succeeded
[    1.191595] port serial8250:0.14: probing port succeeded
[    1.192017] port serial8250:0.15: probing port succeeded
[    1.193533] port serial8250:0.16: probing port succeeded
[    1.193955] port serial8250:0.17: probing port succeeded
[    1.194360] port serial8250:0.18: probing port succeeded
[    1.197551] port serial8250:0.19: probing port succeeded
[    1.197965] port serial8250:0.20: probing port succeeded
[    1.198353] port serial8250:0.21: probing port succeeded
[    1.201960] port serial8250:0.22: probing port succeeded
[    1.202528] port serial8250:0.23: probing port succeeded
[    1.202997] port serial8250:0.24: probing port succeeded
[    1.203415] port serial8250:0.25: probing port succeeded
[    1.203819] port serial8250:0.26: probing port succeeded
[    1.204279] port serial8250:0.27: probing port succeeded
[    1.204669] port serial8250:0.28: probing port succeeded
[    1.205659] port serial8250:0.29: probing port succeeded
[    1.209673] port serial8250:0.30: probing port succeeded
[    1.210117] port serial8250:0.31: probing port succeeded
[    1.210643] serial8250 serial8250: probing serial8250 succeeded
[    1.212911] kgdboc kgdboc: probing kgdboc succeeded
[    1.291410] virtio_blk virtio0: probing virtio_blk succeeded
[    1.309485] virtio_blk virtio3: probing virtio_blk succeeded
[    1.331200] virtio_net virtio1: probing virtio_net succeeded
[    1.354786] fw_cfg 9020000.fw-cfg: probing fw_cfg succeeded
[    1.356688] scmi_virtio_transport firmware:scmi-vio-backend: probing scmi_virtio_transport succeeded
[    1.357830] scmi-virtio virtio2: probing scmi-virtio succeeded
[    1.394738] scmi-clocks scmi_dev.3: probing scmi-clocks succeeded
[    1.415087] arm-scmi arm-scmi.0.auto: probing arm-scmi succeeded
[    1.426512] armv8-pmu pmu: probing armv8-pmu succeeded

I kind of wish all the printks in that function started with __func__.  Would
this be useful for you?  Send me any feedback you have and I can resend this as
a proper patch.

diff --git a/drivers/base/dd.c b/drivers/base/dd.c
index 9b745ba54de1..e8cc710ead76 100644
--- a/drivers/base/dd.c
+++ b/drivers/base/dd.c
@@ -579,6 +579,7 @@ static int call_driver_probe(struct device *dev, const struct device_driver *drv
 
 	switch (ret) {
 	case 0:
+		dev_dbg(dev, "probing %s succeeded\n", drv->name);
 		break;
 	case -EPROBE_DEFER:
 		/* Driver requested deferred probing */
Re: [RFC] driver core: add a dbg printk for successful probes
Posted by Laura Nao 1 month ago
Hi Dan,

On 10/24/24 16:54, Dan Carpenter wrote:
> Hi Laura, and Nicolas,
> 
> I've been thinking about the driver probing talk you gave last year.  The
> talk was about how tricky it is sometimes to determine which drivers have
> probed successfully.  The drivers might be built into the kernel instead of
> as a module, for example.  The idea was that we could make a list of
> drivers we expected to probe successfully and find regressions in probe
> that way.
> 
> Why couldn't we just add a printk in call_driver_probe() and then we could
> pass
> 
> 	dd.dyndbg="func call_driver_probe +p"
> 
> at the kernel command line.
>

Thanks for highlighting this.

This could be useful for debugging by making sysfs information more
accessible and easier to parse, though it may not add significant value for
automated testing.

The main challenge with these tests is building a list of devices expected
to be probed on a given platform, rather than knowing if a certain driver
was probed. From our experience with KernelCI and bootrr[1], manually
creating and maintaining such lists can become a high-maintenance task.
Relying on kernel output with the suggested debug prints as a reference
file would still require significant upkeep - generating, storing, and
updating the reference for each platform over time. Additionally, there's a
risk that some failures could go undetected, if for example a driver is
missing from the kernel config at the time the reference is created or
updated.

Our approach with the DT[2] and ACPI[3] kselftests has been to avoid using
external reference files where possible and instead rely on stable
information already within the kernel. We use the device tree or ACPI
tables as sources to identify which devices are present, then scrape sysfs
to verify whether they’ve been successfully probed. Of course, this
approach isn’t always feasible - some information isn’t exposed by the
kernel, such as devices on discoverable buses, and reference files may be
necessary to cover these cases.

I think debug prints could improve readability but won’t fundamentally
simplify automated testing. What would truly make a difference is if the
kernel could expose expected devices and their corresponding drivers in a
standardized, stable way - ideally in a dedicated place in sysfs (as
suggested in the RFCv1 of the ACPI kselftest). This would make automated
testing easier by reducing the need to parse scattered directories in sysfs
and avoid workarounds to handle exceptions, like skipping devices that
don't have drivers or managing devices represented in sysfs through
multiple directories. For example, in the ACPI kselftest, the main
challenge was determining which devices should have a driver folder in
sysfs and which shouldn’t. So far, I haven’t found a straightforward way to
expose this information in a structured format in sysfs though.

Any thoughts or ideas on this are welcome!

Best,

Laura

[1] https://github.com/kernelci/bootrr
[2] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/tools/testing/selftests/dt
[3] https://lore.kernel.org/all/20240308144933.337107-1-laura.nao@collabora.com/
 
> On my qemu system the `dmesg | grep succeeded` looks like this:
> 
> [    0.135501] reg-dummy reg-dummy: probing reg-dummy succeeded
> [    0.169490] psci-cpuidle-domain psci: probing psci-cpuidle-domain succeeded
> [    0.188039] ctrl 9000000.pl011:0: probing ctrl succeeded
> [    0.188598] port 9000000.pl011:0.0: probing port succeeded
> [    0.206720] uart-pl011 9000000.pl011: probing uart-pl011 succeeded
> [    1.071943] pl061_gpio 9030000.pl061: probing pl061_gpio succeeded
> [    1.117740] pci-host-generic 4010000000.pcie: probing pci-host-generic succeeded
> [    1.159963] virtio-mmio a003e00.virtio_mmio: probing virtio-mmio succeeded
> [    1.166752] virtio-pci 0000:00:01.0: probing virtio-pci succeeded
> [    1.168180] virtio-pci 0000:00:02.0: probing virtio-pci succeeded
> [    1.173959] virtio-pci 0000:00:03.0: probing virtio-pci succeeded
> [    1.178934] ctrl serial8250:0: probing ctrl succeeded
> [    1.179059] port serial8250:0.0: probing port succeeded
> [    1.182032] port serial8250:0.1: probing port succeeded
> [    1.182490] port serial8250:0.2: probing port succeeded
> [    1.182916] port serial8250:0.3: probing port succeeded
> [    1.183309] port serial8250:0.4: probing port succeeded
> [    1.183705] port serial8250:0.5: probing port succeeded
> [    1.185558] port serial8250:0.6: probing port succeeded
> [    1.185962] port serial8250:0.7: probing port succeeded
> [    1.186352] port serial8250:0.8: probing port succeeded
> [    1.189519] port serial8250:0.9: probing port succeeded
> [    1.189972] port serial8250:0.10: probing port succeeded
> [    1.190378] port serial8250:0.11: probing port succeeded
> [    1.190791] port serial8250:0.12: probing port succeeded
> [    1.191180] port serial8250:0.13: probing port succeeded
> [    1.191595] port serial8250:0.14: probing port succeeded
> [    1.192017] port serial8250:0.15: probing port succeeded
> [    1.193533] port serial8250:0.16: probing port succeeded
> [    1.193955] port serial8250:0.17: probing port succeeded
> [    1.194360] port serial8250:0.18: probing port succeeded
> [    1.197551] port serial8250:0.19: probing port succeeded
> [    1.197965] port serial8250:0.20: probing port succeeded
> [    1.198353] port serial8250:0.21: probing port succeeded
> [    1.201960] port serial8250:0.22: probing port succeeded
> [    1.202528] port serial8250:0.23: probing port succeeded
> [    1.202997] port serial8250:0.24: probing port succeeded
> [    1.203415] port serial8250:0.25: probing port succeeded
> [    1.203819] port serial8250:0.26: probing port succeeded
> [    1.204279] port serial8250:0.27: probing port succeeded
> [    1.204669] port serial8250:0.28: probing port succeeded
> [    1.205659] port serial8250:0.29: probing port succeeded
> [    1.209673] port serial8250:0.30: probing port succeeded
> [    1.210117] port serial8250:0.31: probing port succeeded
> [    1.210643] serial8250 serial8250: probing serial8250 succeeded
> [    1.212911] kgdboc kgdboc: probing kgdboc succeeded
> [    1.291410] virtio_blk virtio0: probing virtio_blk succeeded
> [    1.309485] virtio_blk virtio3: probing virtio_blk succeeded
> [    1.331200] virtio_net virtio1: probing virtio_net succeeded
> [    1.354786] fw_cfg 9020000.fw-cfg: probing fw_cfg succeeded
> [    1.356688] scmi_virtio_transport firmware:scmi-vio-backend: probing scmi_virtio_transport succeeded
> [    1.357830] scmi-virtio virtio2: probing scmi-virtio succeeded
> [    1.394738] scmi-clocks scmi_dev.3: probing scmi-clocks succeeded
> [    1.415087] arm-scmi arm-scmi.0.auto: probing arm-scmi succeeded
> [    1.426512] armv8-pmu pmu: probing armv8-pmu succeeded
> 
> I kind of wish all the printks in that function started with __func__.  Would
> this be useful for you?  Send me any feedback you have and I can resend this as
> a proper patch.
> 
> diff --git a/drivers/base/dd.c b/drivers/base/dd.c
> index 9b745ba54de1..e8cc710ead76 100644
> --- a/drivers/base/dd.c
> +++ b/drivers/base/dd.c
> @@ -579,6 +579,7 @@ static int call_driver_probe(struct device *dev, const struct device_driver *drv
>   
>   	switch (ret) {
>   	case 0:
> +		dev_dbg(dev, "probing %s succeeded\n", drv->name);
>   		break;
>   	case -EPROBE_DEFER:
>   		/* Driver requested deferred probing */
> 

Re: [RFC] driver core: add a dbg printk for successful probes
Posted by Laura Nao 3 weeks, 5 days ago
Hi all,

On 10/25/24 14:58, Laura Nao wrote:
> The main challenge with these tests is building a list of devices expected
> to be probed on a given platform, rather than knowing if a certain driver
> was probed. From our experience with KernelCI and bootrr[1], manually
> creating and maintaining such lists can become a high-maintenance task.
> Relying on kernel output with the suggested debug prints as a reference
> file would still require significant upkeep - generating, storing, and
> updating the reference for each platform over time. Additionally, there's a
> risk that some failures could go undetected, if for example a driver is
> missing from the kernel config at the time the reference is created or
> updated.
> 

Building on this, what do you think about adding a sysfs attribute to
identify devices that aren’t meant to be probed by a driver?
I can think of a few cases, like class devices or devices not assigned to a
subsystem, but there are likely many more.

A recent example I encountered is with I2C adapters: while the device for 
the I2C controller itself is expected to bind to a driver, the devices 
created for each I2C bus segment are managed by the same driver but 
don’t have a driver symlink in sysfs. From userspace, looking at all 
devices in sysfs, it’s difficult to tell which ones represent actual 
hardware and which are software abstractions managed by the same driver 
but not directly probed. Having a specific sysfs attribute for these 
cases would make it much easier to tell them apart.  

Any thoughts on this?

Best,

Laura

Re: [RFC] driver core: add a dbg printk for successful probes
Posted by Nícolas F. R. A. Prado 1 month ago
On Fri, Oct 25, 2024 at 02:58:34PM +0200, Laura Nao wrote:
> Hi Dan,
> 
> On 10/24/24 16:54, Dan Carpenter wrote:
> > Hi Laura, and Nicolas,
> > 
> > I've been thinking about the driver probing talk you gave last year.  The
> > talk was about how tricky it is sometimes to determine which drivers have
> > probed successfully.  The drivers might be built into the kernel instead of
> > as a module, for example.  The idea was that we could make a list of
> > drivers we expected to probe successfully and find regressions in probe
> > that way.
> > 
> > Why couldn't we just add a printk in call_driver_probe() and then we could
> > pass
> > 
> > 	dd.dyndbg="func call_driver_probe +p"
> > 
> > at the kernel command line.
> >
> 
> Thanks for highlighting this.
> 
> This could be useful for debugging by making sysfs information more
> accessible and easier to parse, though it may not add significant value for
> automated testing.
> 
> The main challenge with these tests is building a list of devices expected
> to be probed on a given platform, rather than knowing if a certain driver
> was probed. From our experience with KernelCI and bootrr[1], manually
> creating and maintaining such lists can become a high-maintenance task.
> Relying on kernel output with the suggested debug prints as a reference
> file would still require significant upkeep - generating, storing, and
> updating the reference for each platform over time. Additionally, there's a
> risk that some failures could go undetected, if for example a driver is
> missing from the kernel config at the time the reference is created or
> updated.
> 
> Our approach with the DT[2] and ACPI[3] kselftests has been to avoid using
> external reference files where possible and instead rely on stable
> information already within the kernel. We use the device tree or ACPI
> tables as sources to identify which devices are present, then scrape sysfs
> to verify whether they’ve been successfully probed. Of course, this
> approach isn’t always feasible - some information isn’t exposed by the
> kernel, such as devices on discoverable buses, and reference files may be
> necessary to cover these cases.

And just to give more information on this note, to test the devices that aren't
covered by DT or ACPI:
* We've introduced the Discoverable Devices[4] kselftest, which targets devices
  on USB and PCI buses and requires describing those devices in a reference file
  beforehand;
* And more recently we've been proposing the Device Existence[5] kselftest that
  just needs to be run once to generate a reference automatically and has the
  broadest coverage, detecting all devices on the system, although in its
  current state it does not check for driver probe, only device presence.

We've also added a short documentation page[6] comparing those tests and a
couple others.

Since for these devices the need for a reference is unavoidable, the aim of the
tests is to try to encode the system information in the most stable way possible
to reduce maintenance and false-positives.

Thanks,
Nícolas

[4] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/tools/testing/selftests/devices/probe
[5] https://lore.kernel.org/all/20240928-kselftest-dev-exist-v2-1-fab07de6b80b@collabora.com/
[6] https://lore.kernel.org/all/20241001-kselftest-device-docs-v1-1-be28b70dd855@collabora.com