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

[Janusz Krzysztofik <janusz.krzysztofik@linux.intel.com>]

Hi Michał,

Thanks for review.

On Thu, 2020-06-25 at 17:27 +0200, Michał Winiarski wrote:
> 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, 

The idea was to simply log IGT actions, not to log kernel reactions on
them which already happens.  Doing that from the kernel would probably
require modifications to PCI sysfs handling or to sysfs in general.

If you see no benefits from that, let's drop this patch.

Thanks,
Janusz 
 
> but let's go over this case-by-case.
> 
> > v2: rebase on upstream
> > 
> > Signed-off-by: Janusz Krzysztofik <janusz.krzysztofik@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@lists.freedesktop.org
> > https://lists.freedesktop.org/mailman/listinfo/intel-gfx

_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev