[Intel-gfx] [RFC PATCH i-g-t v2 1/8] tests/core_hotunplug: Duplicate debug messages in dmesg

Michał Winiarski michal at hardline.pl
Thu Jun 25 15:27:56 UTC 2020


Quoting Janusz Krzysztofik (2020-06-22 18:44:08)
> The purpose of debug messages displayed by the test is to make
> identification of a subtest phase that fails more easy.  Since issues
> exhibited by the test are mostly reported to dmesg, print those debug
> messages to /dev/kmsg as well.

I'm not a fan of spamming dmesg from IGT and I'd prefer if you add this logging
to the kernel, but let's go over this case-by-case.

> v2: rebase on upstream
> 
> Signed-off-by: Janusz Krzysztofik <janusz.krzysztofik at linux.intel.com>
> ---
>  tests/core_hotunplug.c | 38 ++++++++++++++++++++++----------------
>  1 file changed, 22 insertions(+), 16 deletions(-)
> 
> diff --git a/tests/core_hotunplug.c b/tests/core_hotunplug.c
> index e03f3b945..826645b1f 100644
> --- a/tests/core_hotunplug.c
> +++ b/tests/core_hotunplug.c
> @@ -49,6 +49,12 @@ struct hotunplug {
>  
>  /* Helpers */
>  
> +#define local_debug(msg...)                                                 \
> +({                                                                          \
> +       igt_debug("%s: %s\n", __func__, msg);                                \
> +       igt_kmsg(KMSG_DEBUG "%s: %s: %s\n", igt_test_name(), __func__, msg); \
> +})
> +
>  static void prepare_for_unbind(struct hotunplug *priv, char *buf, int buflen)
>  {
>         int len;
> @@ -68,9 +74,9 @@ static void prepare_for_unbind(struct hotunplug *priv, char *buf, int buflen)
>         close(priv->fd.sysfs_dev);
>  }
>  
> -static void prepare(struct hotunplug *priv, char *buf, int buflen)
> +static inline void prepare(struct hotunplug *priv, char *buf, int buflen)
>  {
> -       igt_debug("opening device\n");
> +       local_debug("opening device");

[  220.458370] [drm:drm_open] pid = 194, minor = 128
[  220.460062] [drm:i915_gem_open [i915]]

>         priv->fd.drm = __drm_open_driver(DRIVER_ANY);
>         igt_assert(priv->fd.drm >= 0);
>  
> @@ -137,14 +143,14 @@ static void bus_rescan(int fd_sysfs_bus)
>         close(fd_sysfs_bus);
>  }
>  
> -static void healthcheck(void)
> +static inline void healthcheck(void)
>  {
>         int fd_drm;
>  
>         /* device name may have changed, rebuild IGT device list */
>         igt_devices_scan(true);
>  
> -       igt_debug("reopening the device\n");
> +       local_debug("reopening the device");

Well, this is going to look the same as open, except closing it won't print
drm_lastclose.

[  293.957567] [drm:drm_release] open_count = 2
[  293.958805] [drm:drm_file_free.part.0] pid = 194, device = 0xe280, open_count = 2

>         fd_drm = __drm_open_driver(DRIVER_ANY);
>         igt_abort_on_f(fd_drm < 0, "Device reopen failure");
>  
> @@ -181,13 +187,13 @@ static void unbind_rebind(void)
>  
>         prepare(&priv, buf, sizeof(buf));
>  
> -       igt_debug("closing the device\n");
> +       local_debug("closing the device");

[  250.157568] [drm:drm_release] open_count = 1
[  250.158807] [drm:drm_file_free.part.0] pid = 194, device = 0xe280, open_count = 1
[  250.161183] [drm:drm_lastclose]
[  250.162312] [drm:drm_lastclose] driver lastclose completed

>         close(priv.fd.drm);
>  
> -       igt_debug("unbinding the driver from the device\n");
> +       local_debug("unbinding the driver from the device");
>         driver_unbind(priv.fd.sysfs_drv, priv.dev_bus_addr);

[ 1553.868235] bus: 'event_source': remove device i915_0000_00_02.0

>  
> -       igt_debug("rebinding the driver to the device\n");
> +       local_debug("rebinding the driver to the device");
>         driver_bind(priv.fd.sysfs_drv, priv.dev_bus_addr);

[ 1592.758219] bus: 'pci': driver_probe_device: matched device 0000:00:02.0 with driver i915
[ 1592.760543] bus: 'pci': really_probe: probing driver i915 with device 0000:00:02.0
(...bunch of i915 logs...)
[  203.961656] driver: 'i915': driver_bound: bound to device '0000:00:02.0'
[  203.966421] bus: 'pci': really_probe: bound device 0000:00:02.0 to driver i915

>  
>         healthcheck();
> @@ -199,13 +205,13 @@ static void unplug_rescan(void)
>  
>         prepare(&priv, NULL, 0);
>  
> -       igt_debug("closing the device\n");
> +       local_debug("closing the device");
>         close(priv.fd.drm);
>  
> -       igt_debug("unplugging the device\n");
> +       local_debug("unplugging the device");
>         device_unplug(priv.fd.sysfs_dev);

[   60.664163] bus: 'pci': remove device 0000:00:02.0

> -       igt_debug("recovering the device\n");
> +       local_debug("recovering the device");
>         bus_rescan(priv.fd.sysfs_bus);

[   97.384479] bus: 'pci': add device 0000:00:02.0

>  
>         healthcheck();
> @@ -218,13 +224,13 @@ static void hotunbind_lateclose(void)
>  
>         prepare(&priv, buf, sizeof(buf));
>  
> -       igt_debug("hot unbinding the driver from the device\n");
> +       local_debug("hot unbinding the driver from the device");
>         driver_unbind(priv.fd.sysfs_drv, priv.dev_bus_addr);
>  
> -       igt_debug("rebinding the driver to the device\n");
> +       local_debug("rebinding the driver to the device");
>         driver_bind(priv.fd.sysfs_drv, priv.dev_bus_addr);
>  
> -       igt_debug("late closing the unbound device instance\n");
> +       local_debug("late closing the unbound device instance");
>         close(priv.fd.drm);

Would it be possible to add extra logging allowing us to distinguish this from
regular unbind on i915 side?

>  
>         healthcheck();
> @@ -236,13 +242,13 @@ static void hotunplug_lateclose(void)
>  
>         prepare(&priv, NULL, 0);
>  
> -       igt_debug("hot unplugging the device\n");
> +       local_debug("hot unplugging the device");
>         device_unplug(priv.fd.sysfs_dev);
>  
> -       igt_debug("recovering the device\n");
> +       local_debug("recovering the device");
>         bus_rescan(priv.fd.sysfs_bus);
>  
> -       igt_debug("late closing the removed device instance\n");
> +       local_debug("late closing the removed device instance");
>         close(priv.fd.drm);

Same thing here.

So, not including the hot unplug/unbind, I think the logging is already there.

Also - note, the "driver core" logs are probably disabled on CI, but I still
think that figuring out how to enable those from IGT (and letting the kernel
just do its regular logging) rather than adding kmsg prints from userspace is a
better approach.

-Michał

>  
>         healthcheck();
> -- 
> 2.21.1
> 
> _______________________________________________
> Intel-gfx mailing list
> Intel-gfx at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/intel-gfx


More information about the Intel-gfx mailing list