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@xxxxxxxxxxxxxxx>
> ---
> 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@xxxxxxxxxxxxxxxxxxxxx
> https://lists.freedesktop.org/mailman/listinfo/intel-gfx
_______________________________________________
Intel-gfx mailing list
Intel-gfx@xxxxxxxxxxxxxxxxxxxxx
https://lists.freedesktop.org/mailman/listinfo/intel-gfx
