* [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 related [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, other threads:[~2019-08-23 11:48 UTC | newest] 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
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).