KVM Archive on lore.kernel.org
 help / color / Atom feed
* [PATCH RFC 0/1] s390dbf logging for vfio-ccw
@ 2019-08-16 15:15 Cornelia Huck
  2019-08-16 15:15 ` [PATCH RFC 1/1] vfio-ccw: add some logging Cornelia Huck
  0 siblings, 1 reply; 5+ messages in thread
From: Cornelia Huck @ 2019-08-16 15:15 UTC (permalink / raw)
  To: Eric Farman, Halil Pasic; +Cc: linux-s390, kvm, 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


^ permalink raw reply	[flat|nested] 5+ messages in thread

* [PATCH RFC 1/1] vfio-ccw: add some logging
  2019-08-16 15:15 [PATCH RFC 0/1] s390dbf logging for vfio-ccw Cornelia Huck
@ 2019-08-16 15:15 ` Cornelia Huck
  2019-08-21 15:54   ` Eric Farman
  2019-08-23 11:48   ` Cornelia Huck
  0 siblings, 2 replies; 5+ messages in thread
From: Cornelia Huck @ 2019-08-16 15:15 UTC (permalink / raw)
  To: Eric Farman, Halil Pasic; +Cc: linux-s390, kvm, 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


^ permalink raw reply	[flat|nested] 5+ messages in thread

* Re: [PATCH RFC 1/1] vfio-ccw: add some logging
  2019-08-16 15:15 ` [PATCH RFC 1/1] vfio-ccw: add some logging Cornelia Huck
@ 2019-08-21 15:54   ` Eric Farman
  2019-08-23 10:44     ` Cornelia Huck
  2019-08-23 11:48   ` Cornelia Huck
  1 sibling, 1 reply; 5+ messages in thread
From: Eric Farman @ 2019-08-21 15:54 UTC (permalink / raw)
  To: Cornelia Huck, Halil Pasic; +Cc: linux-s390, kvm



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>


^ permalink raw reply	[flat|nested] 5+ messages in thread

* Re: [PATCH RFC 1/1] vfio-ccw: add some logging
  2019-08-21 15:54   ` Eric Farman
@ 2019-08-23 10:44     ` Cornelia Huck
  0 siblings, 0 replies; 5+ messages in thread
From: Cornelia Huck @ 2019-08-23 10:44 UTC (permalink / raw)
  To: Eric Farman; +Cc: Halil Pasic, linux-s390, kvm

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.

^ permalink raw reply	[flat|nested] 5+ messages in thread

* Re: [PATCH RFC 1/1] vfio-ccw: add some logging
  2019-08-16 15:15 ` [PATCH RFC 1/1] vfio-ccw: add some logging Cornelia Huck
  2019-08-21 15:54   ` Eric Farman
@ 2019-08-23 11:48   ` Cornelia Huck
  1 sibling, 0 replies; 5+ messages in thread
From: Cornelia Huck @ 2019-08-23 11:48 UTC (permalink / raw)
  To: Eric Farman, Halil Pasic; +Cc: linux-s390, kvm

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.

^ permalink raw reply	[flat|nested] 5+ messages in thread

end of thread, back to index

Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-08-16 15:15 [PATCH RFC 0/1] s390dbf logging for vfio-ccw Cornelia Huck
2019-08-16 15:15 ` [PATCH RFC 1/1] vfio-ccw: add some logging Cornelia Huck
2019-08-21 15:54   ` Eric Farman
2019-08-23 10:44     ` Cornelia Huck
2019-08-23 11:48   ` Cornelia Huck

KVM Archive on lore.kernel.org

Archives are clonable:
	git clone --mirror https://lore.kernel.org/kvm/0 kvm/git/0.git

	# If you have public-inbox 1.1+ installed, you may
	# initialize and index your mirror using the following commands:
	public-inbox-init -V2 kvm kvm/ https://lore.kernel.org/kvm \
		kvm@vger.kernel.org kvm@archiver.kernel.org
	public-inbox-index kvm


Newsgroup available over NNTP:
	nntp://nntp.lore.kernel.org/org.kernel.vger.kvm


AGPL code for this site: git clone https://public-inbox.org/ public-inbox