[PATCH RFC 0/1] s390dbf logging for vfio-ccw

[PATCH RFC 0/1] s390dbf logging for vfio-ccw

[Cornelia Huck]

The current discussions around uuids and mdev devices got me thinking,
and I realized that the uuid is an interesting information for
debugging devices.

Currently, vfio-ccw does not really log any debug data (there's just
a lone trace event). The common I/O layer has logged interesting
information into the s390dbf for a long time; this has been very
useful in the past, as the logged information can be accessed in a
crash dump (e.g. by the crash tool). We cannot log directly into
the common I/O layer debug features, though, as vfio-ccw may be a
module.

Another limitation is that for the sprintf-type debug feature, any
string logged via '%s' must outlive the debug feature (as it is not
copied for performance reasons). That means that logging the device
name is right out, as devices may go away (the current common I/O
layer code logs the numerical values of ssid/subchannel number instead);
logging the uuid of an mdev device via %pU just works fine, though.

My patch just logs some basics right now, we can certainly add more
events. We should also think about adding more trace events: they
may serve a similar purpose, especially if we should enhance the vfio
code with trace events in the future (so that we can correlate those
trace events with the vfio-ccw trace events, just as we can correlate
the s390dbf events with the common I/O layer dbf events to get a more
complete picture.)

Cornelia Huck (1):
  vfio-ccw: add some logging

 drivers/s390/cio/vfio_ccw_drv.c     | 50 ++++++++++++++++++++++++++--
 drivers/s390/cio/vfio_ccw_fsm.c     | 51 ++++++++++++++++++++++++++++-
 drivers/s390/cio/vfio_ccw_ops.c     | 10 ++++++
 drivers/s390/cio/vfio_ccw_private.h | 17 ++++++++++
 4 files changed, 124 insertions(+), 4 deletions(-)

-- 
2.20.1

[PATCH RFC 1/1] vfio-ccw: add some logging

[Cornelia Huck]

Usually, the common I/O layer logs various things into the s390
cio debug feature, which has been very helpful in the past when
looking at crash dumps. As vfio-ccw devices unbind from the
standard I/O subchannel driver, we lose some information there.

Let's introduce some vfio-ccw debug features and log some things
there. (Unfortunately we cannot reuse the cio debug feature from
a module.)

Signed-off-by: Cornelia Huck <cohuck@redhat.com>
---
 drivers/s390/cio/vfio_ccw_drv.c     | 50 ++++++++++++++++++++++++++--
 drivers/s390/cio/vfio_ccw_fsm.c     | 51 ++++++++++++++++++++++++++++-
 drivers/s390/cio/vfio_ccw_ops.c     | 10 ++++++
 drivers/s390/cio/vfio_ccw_private.h | 17 ++++++++++
 4 files changed, 124 insertions(+), 4 deletions(-)

diff --git a/drivers/s390/cio/vfio_ccw_drv.c b/drivers/s390/cio/vfio_ccw_drv.c
index 9208c0e56c33..45e792f6afd0 100644
--- a/drivers/s390/cio/vfio_ccw_drv.c
+++ b/drivers/s390/cio/vfio_ccw_drv.c
@@ -27,6 +27,9 @@ struct workqueue_struct *vfio_ccw_work_q;
 static struct kmem_cache *vfio_ccw_io_region;
 static struct kmem_cache *vfio_ccw_cmd_region;
 
+debug_info_t *vfio_ccw_debug_msg_id;
+debug_info_t *vfio_ccw_debug_trace_id;
+
 /*
  * Helpers
  */
@@ -164,6 +167,9 @@ static int vfio_ccw_sch_probe(struct subchannel *sch)
 	if (ret)
 		goto out_disable;
 
+	VFIO_CCW_MSG_EVENT(4, "bound to subchannel %x.%x.%04x\n",
+			   sch->schid.cssid, sch->schid.ssid,
+			   sch->schid.sch_no);
 	return 0;
 
 out_disable:
@@ -194,6 +200,9 @@ static int vfio_ccw_sch_remove(struct subchannel *sch)
 	kfree(private->cp.guest_cp);
 	kfree(private);
 
+	VFIO_CCW_MSG_EVENT(4, "unbound from subchannel %x.%x.%04x\n",
+			   sch->schid.cssid, sch->schid.ssid,
+			   sch->schid.sch_no);
 	return 0;
 }
 
@@ -263,13 +272,46 @@ static struct css_driver vfio_ccw_sch_driver = {
 	.sch_event = vfio_ccw_sch_event,
 };
 
+static int __init vfio_ccw_debug_init(void)
+{
+	vfio_ccw_debug_msg_id = debug_register("vfio_ccw_msg", 16, 1,
+					       11 * sizeof(long));
+	if (!vfio_ccw_debug_msg_id)
+		goto out_unregister;
+	debug_register_view(vfio_ccw_debug_msg_id, &debug_sprintf_view);
+	debug_set_level(vfio_ccw_debug_msg_id, 2);
+	vfio_ccw_debug_trace_id = debug_register("vfio_ccw_trace", 16, 1, 16);
+	if (!vfio_ccw_debug_trace_id)
+		goto out_unregister;
+	debug_register_view(vfio_ccw_debug_trace_id, &debug_hex_ascii_view);
+	debug_set_level(vfio_ccw_debug_trace_id, 2);
+	return 0;
+
+out_unregister:
+	debug_unregister(vfio_ccw_debug_msg_id);
+	debug_unregister(vfio_ccw_debug_trace_id);
+	return -1;
+}
+
+static void vfio_ccw_debug_exit(void)
+{
+	debug_unregister(vfio_ccw_debug_msg_id);
+	debug_unregister(vfio_ccw_debug_trace_id);
+}
+
 static int __init vfio_ccw_sch_init(void)
 {
-	int ret = -ENOMEM;
+	int ret;
+
+	ret = vfio_ccw_debug_init();
+	if (ret)
+		return ret;
 
 	vfio_ccw_work_q = create_singlethread_workqueue("vfio-ccw");
-	if (!vfio_ccw_work_q)
-		return -ENOMEM;
+	if (!vfio_ccw_work_q) {
+		ret = -ENOMEM;
+		goto out_err;
+	}
 
 	vfio_ccw_io_region = kmem_cache_create_usercopy("vfio_ccw_io_region",
 					sizeof(struct ccw_io_region), 0,
@@ -298,6 +340,7 @@ static int __init vfio_ccw_sch_init(void)
 	kmem_cache_destroy(vfio_ccw_cmd_region);
 	kmem_cache_destroy(vfio_ccw_io_region);
 	destroy_workqueue(vfio_ccw_work_q);
+	vfio_ccw_debug_exit();
 	return ret;
 }
 
@@ -308,6 +351,7 @@ static void __exit vfio_ccw_sch_exit(void)
 	kmem_cache_destroy(vfio_ccw_io_region);
 	kmem_cache_destroy(vfio_ccw_cmd_region);
 	destroy_workqueue(vfio_ccw_work_q);
+	vfio_ccw_debug_exit();
 }
 module_init(vfio_ccw_sch_init);
 module_exit(vfio_ccw_sch_exit);
diff --git a/drivers/s390/cio/vfio_ccw_fsm.c b/drivers/s390/cio/vfio_ccw_fsm.c
index 49d9d3da0282..4a1e727c62d9 100644
--- a/drivers/s390/cio/vfio_ccw_fsm.c
+++ b/drivers/s390/cio/vfio_ccw_fsm.c
@@ -37,9 +37,14 @@ static int fsm_io_helper(struct vfio_ccw_private *private)
 		goto out;
 	}
 
+	VFIO_CCW_TRACE_EVENT(5, "stIO");
+	VFIO_CCW_TRACE_EVENT(5, dev_name(&sch->dev));
+
 	/* Issue "Start Subchannel" */
 	ccode = ssch(sch->schid, orb);
 
+	VFIO_CCW_HEX_EVENT(5, &ccode, sizeof(ccode));
+
 	switch (ccode) {
 	case 0:
 		/*
@@ -86,9 +91,14 @@ static int fsm_do_halt(struct vfio_ccw_private *private)
 
 	spin_lock_irqsave(sch->lock, flags);
 
+	VFIO_CCW_TRACE_EVENT(2, "haltIO");
+	VFIO_CCW_TRACE_EVENT(2, dev_name(&sch->dev));
+
 	/* Issue "Halt Subchannel" */
 	ccode = hsch(sch->schid);
 
+	VFIO_CCW_HEX_EVENT(2, &ccode, sizeof(ccode));
+
 	switch (ccode) {
 	case 0:
 		/*
@@ -122,9 +132,14 @@ static int fsm_do_clear(struct vfio_ccw_private *private)
 
 	spin_lock_irqsave(sch->lock, flags);
 
+	VFIO_CCW_TRACE_EVENT(2, "clearIO");
+	VFIO_CCW_TRACE_EVENT(2, dev_name(&sch->dev));
+
 	/* Issue "Clear Subchannel" */
 	ccode = csch(sch->schid);
 
+	VFIO_CCW_HEX_EVENT(2, &ccode, sizeof(ccode));
+
 	switch (ccode) {
 	case 0:
 		/*
@@ -149,6 +164,9 @@ static void fsm_notoper(struct vfio_ccw_private *private,
 {
 	struct subchannel *sch = private->sch;
 
+	VFIO_CCW_TRACE_EVENT(2, "notoper");
+	VFIO_CCW_TRACE_EVENT(2, dev_name(&sch->dev));
+
 	/*
 	 * TODO:
 	 * Probably we should send the machine check to the guest.
@@ -229,6 +247,7 @@ static void fsm_io_request(struct vfio_ccw_private *private,
 	struct ccw_io_region *io_region = private->io_region;
 	struct mdev_device *mdev = private->mdev;
 	char *errstr = "request";
+	struct subchannel_id schid = get_schid(private);
 
 	private->state = VFIO_CCW_STATE_CP_PROCESSING;
 	memcpy(scsw, io_region->scsw_area, sizeof(*scsw));
@@ -239,18 +258,32 @@ static void fsm_io_request(struct vfio_ccw_private *private,
 		/* Don't try to build a cp if transport mode is specified. */
 		if (orb->tm.b) {
 			io_region->ret_code = -EOPNOTSUPP;
+			VFIO_CCW_MSG_EVENT(2,
+					   "%pUl (%x.%x.%04x): transport mode\n",
+					   mdev_uuid(mdev), schid.cssid,
+					   schid.ssid, schid.sch_no);
 			errstr = "transport mode";
 			goto err_out;
 		}
 		io_region->ret_code = cp_init(&private->cp, mdev_dev(mdev),
 					      orb);
 		if (io_region->ret_code) {
+			VFIO_CCW_MSG_EVENT(2,
+					   "%pUl (%x.%x.%04x): cp_init=%d\n",
+					   mdev_uuid(mdev), schid.cssid,
+					   schid.ssid, schid.sch_no,
+					   io_region->ret_code);
 			errstr = "cp init";
 			goto err_out;
 		}
 
 		io_region->ret_code = cp_prefetch(&private->cp);
 		if (io_region->ret_code) {
+			VFIO_CCW_MSG_EVENT(2,
+					   "%pUl (%x.%x.%04x): cp_prefetch=%d\n",
+					   mdev_uuid(mdev), schid.cssid,
+					   schid.ssid, schid.sch_no,
+					   io_region->ret_code);
 			errstr = "cp prefetch";
 			cp_free(&private->cp);
 			goto err_out;
@@ -259,23 +292,36 @@ static void fsm_io_request(struct vfio_ccw_private *private,
 		/* Start channel program and wait for I/O interrupt. */
 		io_region->ret_code = fsm_io_helper(private);
 		if (io_region->ret_code) {
+			VFIO_CCW_MSG_EVENT(2,
+					   "%pUl (%x.%x.%04x): fsm_io_helper=%d\n",
+					   mdev_uuid(mdev), schid.cssid,
+					   schid.ssid, schid.sch_no,
+					   io_region->ret_code);
 			errstr = "cp fsm_io_helper";
 			cp_free(&private->cp);
 			goto err_out;
 		}
 		return;
 	} else if (scsw->cmd.fctl & SCSW_FCTL_HALT_FUNC) {
+		VFIO_CCW_MSG_EVENT(2,
+				   "%pUl (%x.%x.%04x): halt on io_region\n",
+				   mdev_uuid(mdev), schid.cssid,
+				   schid.ssid, schid.sch_no);
 		/* halt is handled via the async cmd region */
 		io_region->ret_code = -EOPNOTSUPP;
 		goto err_out;
 	} else if (scsw->cmd.fctl & SCSW_FCTL_CLEAR_FUNC) {
+		VFIO_CCW_MSG_EVENT(2,
+				   "%pUl (%x.%x.%04x): clear on io_region\n",
+				   mdev_uuid(mdev), schid.cssid,
+				   schid.ssid, schid.sch_no);
 		/* clear is handled via the async cmd region */
 		io_region->ret_code = -EOPNOTSUPP;
 		goto err_out;
 	}
 
 err_out:
-	trace_vfio_ccw_io_fctl(scsw->cmd.fctl, get_schid(private),
+	trace_vfio_ccw_io_fctl(scsw->cmd.fctl, schid,
 			       io_region->ret_code, errstr);
 }
 
@@ -308,6 +354,9 @@ static void fsm_irq(struct vfio_ccw_private *private,
 {
 	struct irb *irb = this_cpu_ptr(&cio_irb);
 
+	VFIO_CCW_TRACE_EVENT(6, "IRQ");
+	VFIO_CCW_TRACE_EVENT(6, dev_name(&private->sch->dev));
+
 	memcpy(&private->irb, irb, sizeof(*irb));
 
 	queue_work(vfio_ccw_work_q, &private->io_work);
diff --git a/drivers/s390/cio/vfio_ccw_ops.c b/drivers/s390/cio/vfio_ccw_ops.c
index 5eb61116ca6f..f0d71ab77c50 100644
--- a/drivers/s390/cio/vfio_ccw_ops.c
+++ b/drivers/s390/cio/vfio_ccw_ops.c
@@ -124,6 +124,11 @@ static int vfio_ccw_mdev_create(struct kobject *kobj, struct mdev_device *mdev)
 	private->mdev = mdev;
 	private->state = VFIO_CCW_STATE_IDLE;
 
+	VFIO_CCW_MSG_EVENT(2, "mdev %pUl, sch %x.%x.%04x: create\n",
+			   mdev_uuid(mdev), private->sch->schid.cssid,
+			   private->sch->schid.ssid,
+			   private->sch->schid.sch_no);
+
 	return 0;
 }
 
@@ -132,6 +137,11 @@ static int vfio_ccw_mdev_remove(struct mdev_device *mdev)
 	struct vfio_ccw_private *private =
 		dev_get_drvdata(mdev_parent_dev(mdev));
 
+	VFIO_CCW_MSG_EVENT(2, "mdev %pUl, sch %x.%x.%04x: remove\n",
+			   mdev_uuid(mdev), private->sch->schid.cssid,
+			   private->sch->schid.ssid,
+			   private->sch->schid.sch_no);
+
 	if ((private->state != VFIO_CCW_STATE_NOT_OPER) &&
 	    (private->state != VFIO_CCW_STATE_STANDBY)) {
 		if (!vfio_ccw_sch_quiesce(private->sch))
diff --git a/drivers/s390/cio/vfio_ccw_private.h b/drivers/s390/cio/vfio_ccw_private.h
index f1092c3dc1b1..bbe9babf767b 100644
--- a/drivers/s390/cio/vfio_ccw_private.h
+++ b/drivers/s390/cio/vfio_ccw_private.h
@@ -17,6 +17,7 @@
 #include <linux/eventfd.h>
 #include <linux/workqueue.h>
 #include <linux/vfio_ccw.h>
+#include <asm/debug.h>
 
 #include "css.h"
 #include "vfio_ccw_cp.h"
@@ -139,4 +140,20 @@ static inline void vfio_ccw_fsm_event(struct vfio_ccw_private *private,
 
 extern struct workqueue_struct *vfio_ccw_work_q;
 
+
+/* s390 debug feature, similar to base cio */
+extern debug_info_t *vfio_ccw_debug_msg_id;
+extern debug_info_t *vfio_ccw_debug_trace_id;
+
+#define VFIO_CCW_TRACE_EVENT(imp, txt) \
+		debug_text_event(vfio_ccw_debug_trace_id, imp, txt)
+
+#define VFIO_CCW_MSG_EVENT(imp, args...) \
+		debug_sprintf_event(vfio_ccw_debug_msg_id, imp, ##args)
+
+static inline void VFIO_CCW_HEX_EVENT(int level, void *data, int length)
+{
+	debug_event(vfio_ccw_debug_trace_id, level, data, length);
+}
+
 #endif
-- 
2.20.1

Re: [PATCH RFC 1/1] vfio-ccw: add some logging

[Eric Farman]

On 8/16/19 11:15 AM, Cornelia Huck wrote:
> Usually, the common I/O layer logs various things into the s390
> cio debug feature, which has been very helpful in the past when
> looking at crash dumps. As vfio-ccw devices unbind from the
> standard I/O subchannel driver, we lose some information there.
> 
> Let's introduce some vfio-ccw debug features and log some things
> there. (Unfortunately we cannot reuse the cio debug feature from
> a module.)

Boo :(

> 
> Signed-off-by: Cornelia Huck <cohuck@redhat.com>
> ---
>  drivers/s390/cio/vfio_ccw_drv.c     | 50 ++++++++++++++++++++++++++--
>  drivers/s390/cio/vfio_ccw_fsm.c     | 51 ++++++++++++++++++++++++++++-
>  drivers/s390/cio/vfio_ccw_ops.c     | 10 ++++++
>  drivers/s390/cio/vfio_ccw_private.h | 17 ++++++++++
>  4 files changed, 124 insertions(+), 4 deletions(-)
> 

...snip...

> diff --git a/drivers/s390/cio/vfio_ccw_fsm.c b/drivers/s390/cio/vfio_ccw_fsm.c
> index 49d9d3da0282..4a1e727c62d9 100644
> --- a/drivers/s390/cio/vfio_ccw_fsm.c
> +++ b/drivers/s390/cio/vfio_ccw_fsm.c

...snip...

> @@ -239,18 +258,32 @@ static void fsm_io_request(struct vfio_ccw_private *private,
>  		/* Don't try to build a cp if transport mode is specified. */
>  		if (orb->tm.b) {
>  			io_region->ret_code = -EOPNOTSUPP;
> +			VFIO_CCW_MSG_EVENT(2,
> +					   "%pUl (%x.%x.%04x): transport mode\n",
> +					   mdev_uuid(mdev), schid.cssid,
> +					   schid.ssid, schid.sch_no);
>  			errstr = "transport mode";
>  			goto err_out;
>  		}
>  		io_region->ret_code = cp_init(&private->cp, mdev_dev(mdev),
>  					      orb);
>  		if (io_region->ret_code) {
> +			VFIO_CCW_MSG_EVENT(2,
> +					   "%pUl (%x.%x.%04x): cp_init=%d\n",
> +					   mdev_uuid(mdev), schid.cssid,
> +					   schid.ssid, schid.sch_no,
> +					   io_region->ret_code);
>  			errstr = "cp init";
>  			goto err_out;
>  		}
>  
>  		io_region->ret_code = cp_prefetch(&private->cp);
>  		if (io_region->ret_code) {
> +			VFIO_CCW_MSG_EVENT(2,
> +					   "%pUl (%x.%x.%04x): cp_prefetch=%d\n",
> +					   mdev_uuid(mdev), schid.cssid,
> +					   schid.ssid, schid.sch_no,
> +					   io_region->ret_code);
>  			errstr = "cp prefetch";
>  			cp_free(&private->cp);
>  			goto err_out;
> @@ -259,23 +292,36 @@ static void fsm_io_request(struct vfio_ccw_private *private,
>  		/* Start channel program and wait for I/O interrupt. */
>  		io_region->ret_code = fsm_io_helper(private);
>  		if (io_region->ret_code) {
> +			VFIO_CCW_MSG_EVENT(2,
> +					   "%pUl (%x.%x.%04x): fsm_io_helper=%d\n",
> +					   mdev_uuid(mdev), schid.cssid,
> +					   schid.ssid, schid.sch_no,
> +					   io_region->ret_code);

I suppose these ones could be squashed into err_out, and use errstr as
substitution for the message text.  But this is fine.

>  			errstr = "cp fsm_io_helper";
>  			cp_free(&private->cp);
>  			goto err_out;
>  		}
>  		return;
>  	} else if (scsw->cmd.fctl & SCSW_FCTL_HALT_FUNC) {
> +		VFIO_CCW_MSG_EVENT(2,
> +				   "%pUl (%x.%x.%04x): halt on io_region\n",
> +				   mdev_uuid(mdev), schid.cssid,
> +				   schid.ssid, schid.sch_no);
>  		/* halt is handled via the async cmd region */
>  		io_region->ret_code = -EOPNOTSUPP;
>  		goto err_out;
>  	} else if (scsw->cmd.fctl & SCSW_FCTL_CLEAR_FUNC) {
> +		VFIO_CCW_MSG_EVENT(2,
> +				   "%pUl (%x.%x.%04x): clear on io_region\n",
> +				   mdev_uuid(mdev), schid.cssid,
> +				   schid.ssid, schid.sch_no);

The above idea would need errstr to be set to something other than
"request" here, which maybe isn't a bad thing anyway.  :)

>  		/* clear is handled via the async cmd region */
>  		io_region->ret_code = -EOPNOTSUPP;
>  		goto err_out;
>  	}
>  
>  err_out:
> -	trace_vfio_ccw_io_fctl(scsw->cmd.fctl, get_schid(private),
> +	trace_vfio_ccw_io_fctl(scsw->cmd.fctl, schid,
>  			       io_region->ret_code, errstr);
>  }
>  
> @@ -308,6 +354,9 @@ static void fsm_irq(struct vfio_ccw_private *private,
>  {
>  	struct irb *irb = this_cpu_ptr(&cio_irb);
>  
> +	VFIO_CCW_TRACE_EVENT(6, "IRQ");
> +	VFIO_CCW_TRACE_EVENT(6, dev_name(&private->sch->dev));
> +
>  	memcpy(&private->irb, irb, sizeof(*irb));
>  
>  	queue_work(vfio_ccw_work_q, &private->io_work);
> diff --git a/drivers/s390/cio/vfio_ccw_ops.c b/drivers/s390/cio/vfio_ccw_ops.c
> index 5eb61116ca6f..f0d71ab77c50 100644
> --- a/drivers/s390/cio/vfio_ccw_ops.c
> +++ b/drivers/s390/cio/vfio_ccw_ops.c
> @@ -124,6 +124,11 @@ static int vfio_ccw_mdev_create(struct kobject *kobj, struct mdev_device *mdev)
>  	private->mdev = mdev;
>  	private->state = VFIO_CCW_STATE_IDLE;
>  
> +	VFIO_CCW_MSG_EVENT(2, "mdev %pUl, sch %x.%x.%04x: create\n",
> +			   mdev_uuid(mdev), private->sch->schid.cssid,
> +			   private->sch->schid.ssid,
> +			   private->sch->schid.sch_no);
> +
>  	return 0;
>  }
>  
> @@ -132,6 +137,11 @@ static int vfio_ccw_mdev_remove(struct mdev_device *mdev)
>  	struct vfio_ccw_private *private =
>  		dev_get_drvdata(mdev_parent_dev(mdev));
>  
> +	VFIO_CCW_MSG_EVENT(2, "mdev %pUl, sch %x.%x.%04x: remove\n",
> +			   mdev_uuid(mdev), private->sch->schid.cssid,
> +			   private->sch->schid.ssid,
> +			   private->sch->schid.sch_no);
> +
>  	if ((private->state != VFIO_CCW_STATE_NOT_OPER) &&
>  	    (private->state != VFIO_CCW_STATE_STANDBY)) {
>  		if (!vfio_ccw_sch_quiesce(private->sch))
> diff --git a/drivers/s390/cio/vfio_ccw_private.h b/drivers/s390/cio/vfio_ccw_private.h
> index f1092c3dc1b1..bbe9babf767b 100644
> --- a/drivers/s390/cio/vfio_ccw_private.h
> +++ b/drivers/s390/cio/vfio_ccw_private.h
> @@ -17,6 +17,7 @@
>  #include <linux/eventfd.h>
>  #include <linux/workqueue.h>
>  #include <linux/vfio_ccw.h>
> +#include <asm/debug.h>
>  
>  #include "css.h"
>  #include "vfio_ccw_cp.h"
> @@ -139,4 +140,20 @@ static inline void vfio_ccw_fsm_event(struct vfio_ccw_private *private,
>  
>  extern struct workqueue_struct *vfio_ccw_work_q;
>  
> +
> +/* s390 debug feature, similar to base cio */
> +extern debug_info_t *vfio_ccw_debug_msg_id;
> +extern debug_info_t *vfio_ccw_debug_trace_id;
> +
> +#define VFIO_CCW_TRACE_EVENT(imp, txt) \
> +		debug_text_event(vfio_ccw_debug_trace_id, imp, txt)
> +
> +#define VFIO_CCW_MSG_EVENT(imp, args...) \
> +		debug_sprintf_event(vfio_ccw_debug_msg_id, imp, ##args)
> +
> +static inline void VFIO_CCW_HEX_EVENT(int level, void *data, int length)
> +{
> +	debug_event(vfio_ccw_debug_trace_id, level, data, length);
> +}
> +
>  #endif
> 

This all looks pretty standard compared to the existing cio stuff, and
would be a good addition for vfio-ccw.

Reviewed-by: Eric Farman <farman@linux.ibm.com>

Re: [PATCH RFC 1/1] vfio-ccw: add some logging

[Cornelia Huck]

On Wed, 21 Aug 2019 11:54:26 -0400
Eric Farman <farman@linux.ibm.com> wrote:

> On 8/16/19 11:15 AM, Cornelia Huck wrote:
> > Usually, the common I/O layer logs various things into the s390
> > cio debug feature, which has been very helpful in the past when
> > looking at crash dumps. As vfio-ccw devices unbind from the
> > standard I/O subchannel driver, we lose some information there.
> > 
> > Let's introduce some vfio-ccw debug features and log some things
> > there. (Unfortunately we cannot reuse the cio debug feature from
> > a module.)  
> 
> Boo :(

Yeah, that would have been even more useful :(

> 
> > 
> > Signed-off-by: Cornelia Huck <cohuck@redhat.com>
> > ---
> >  drivers/s390/cio/vfio_ccw_drv.c     | 50 ++++++++++++++++++++++++++--
> >  drivers/s390/cio/vfio_ccw_fsm.c     | 51 ++++++++++++++++++++++++++++-
> >  drivers/s390/cio/vfio_ccw_ops.c     | 10 ++++++
> >  drivers/s390/cio/vfio_ccw_private.h | 17 ++++++++++
> >  4 files changed, 124 insertions(+), 4 deletions(-)
> >   
> 
> ...snip...
> 
> > diff --git a/drivers/s390/cio/vfio_ccw_fsm.c b/drivers/s390/cio/vfio_ccw_fsm.c
> > index 49d9d3da0282..4a1e727c62d9 100644
> > --- a/drivers/s390/cio/vfio_ccw_fsm.c
> > +++ b/drivers/s390/cio/vfio_ccw_fsm.c  
> 
> ...snip...
> 
> > @@ -239,18 +258,32 @@ static void fsm_io_request(struct vfio_ccw_private *private,
> >  		/* Don't try to build a cp if transport mode is specified. */
> >  		if (orb->tm.b) {
> >  			io_region->ret_code = -EOPNOTSUPP;
> > +			VFIO_CCW_MSG_EVENT(2,
> > +					   "%pUl (%x.%x.%04x): transport mode\n",
> > +					   mdev_uuid(mdev), schid.cssid,
> > +					   schid.ssid, schid.sch_no);
> >  			errstr = "transport mode";
> >  			goto err_out;
> >  		}
> >  		io_region->ret_code = cp_init(&private->cp, mdev_dev(mdev),
> >  					      orb);
> >  		if (io_region->ret_code) {
> > +			VFIO_CCW_MSG_EVENT(2,
> > +					   "%pUl (%x.%x.%04x): cp_init=%d\n",
> > +					   mdev_uuid(mdev), schid.cssid,
> > +					   schid.ssid, schid.sch_no,
> > +					   io_region->ret_code);
> >  			errstr = "cp init";
> >  			goto err_out;
> >  		}
> >  
> >  		io_region->ret_code = cp_prefetch(&private->cp);
> >  		if (io_region->ret_code) {
> > +			VFIO_CCW_MSG_EVENT(2,
> > +					   "%pUl (%x.%x.%04x): cp_prefetch=%d\n",
> > +					   mdev_uuid(mdev), schid.cssid,
> > +					   schid.ssid, schid.sch_no,
> > +					   io_region->ret_code);
> >  			errstr = "cp prefetch";
> >  			cp_free(&private->cp);
> >  			goto err_out;
> > @@ -259,23 +292,36 @@ static void fsm_io_request(struct vfio_ccw_private *private,
> >  		/* Start channel program and wait for I/O interrupt. */
> >  		io_region->ret_code = fsm_io_helper(private);
> >  		if (io_region->ret_code) {
> > +			VFIO_CCW_MSG_EVENT(2,
> > +					   "%pUl (%x.%x.%04x): fsm_io_helper=%d\n",
> > +					   mdev_uuid(mdev), schid.cssid,
> > +					   schid.ssid, schid.sch_no,
> > +					   io_region->ret_code);  
> 
> I suppose these ones could be squashed into err_out, and use errstr as
> substitution for the message text.  But this is fine.
> 
> >  			errstr = "cp fsm_io_helper";
> >  			cp_free(&private->cp);
> >  			goto err_out;
> >  		}
> >  		return;
> >  	} else if (scsw->cmd.fctl & SCSW_FCTL_HALT_FUNC) {
> > +		VFIO_CCW_MSG_EVENT(2,
> > +				   "%pUl (%x.%x.%04x): halt on io_region\n",
> > +				   mdev_uuid(mdev), schid.cssid,
> > +				   schid.ssid, schid.sch_no);
> >  		/* halt is handled via the async cmd region */
> >  		io_region->ret_code = -EOPNOTSUPP;
> >  		goto err_out;
> >  	} else if (scsw->cmd.fctl & SCSW_FCTL_CLEAR_FUNC) {
> > +		VFIO_CCW_MSG_EVENT(2,
> > +				   "%pUl (%x.%x.%04x): clear on io_region\n",
> > +				   mdev_uuid(mdev), schid.cssid,
> > +				   schid.ssid, schid.sch_no);  
> 
> The above idea would need errstr to be set to something other than
> "request" here, which maybe isn't a bad thing anyway.  :)

The trace event tries to cover all of the different error cases in one
go, so it is not quite optimal (but still useful). For the sprintf
event, I tried to include better error-specific information (also, I'm
probably a bit paranoid with regard to strings in the sprintf view :)

We could probably enhance the trace event here, and we should evaluate
adding more of them, as they and the dbf complement each other.

> 
> >  		/* clear is handled via the async cmd region */
> >  		io_region->ret_code = -EOPNOTSUPP;
> >  		goto err_out;
> >  	}
> >  
> >  err_out:
> > -	trace_vfio_ccw_io_fctl(scsw->cmd.fctl, get_schid(private),
> > +	trace_vfio_ccw_io_fctl(scsw->cmd.fctl, schid,
> >  			       io_region->ret_code, errstr);
> >  }
> >  

(...)

> This all looks pretty standard compared to the existing cio stuff, and
> would be a good addition for vfio-ccw.

I pretty much copied some of the basic stuff over. We can always add
more later :)

> 
> Reviewed-by: Eric Farman <farman@linux.ibm.com>
> 

Thanks!

I'll go ahead and queue this for the next release, unless someone
objects.

Re: [PATCH RFC 1/1] vfio-ccw: add some logging

[Cornelia Huck]

On Fri, 16 Aug 2019 17:15:05 +0200
Cornelia Huck <cohuck@redhat.com> wrote:

> Usually, the common I/O layer logs various things into the s390
> cio debug feature, which has been very helpful in the past when
> looking at crash dumps. As vfio-ccw devices unbind from the
> standard I/O subchannel driver, we lose some information there.
> 
> Let's introduce some vfio-ccw debug features and log some things
> there. (Unfortunately we cannot reuse the cio debug feature from
> a module.)
> 
> Signed-off-by: Cornelia Huck <cohuck@redhat.com>
> ---
>  drivers/s390/cio/vfio_ccw_drv.c     | 50 ++++++++++++++++++++++++++--
>  drivers/s390/cio/vfio_ccw_fsm.c     | 51 ++++++++++++++++++++++++++++-
>  drivers/s390/cio/vfio_ccw_ops.c     | 10 ++++++
>  drivers/s390/cio/vfio_ccw_private.h | 17 ++++++++++
>  4 files changed, 124 insertions(+), 4 deletions(-)

Queued.