[RFC PATCH 0/4] vfio-ccw: A couple trace changes

[RFC PATCH 0/4] vfio-ccw: A couple trace changes

[Eric Farman]

Hi Conny,

I mentioned these to you a while ago; just been caught up in other
things. These aren't really pre-reqs for anything in our pipe, but
they've been beneficial to me on their own, and simplify debugging
of future work (such as the FSM needs brought up by Halil).

While the first patch refactors the trace so new ones can be added
outside the FSM, none of the other patches in this series really do.
I imagine that would be beneficial in the future, so I think it
would be good to do that rework before we get too far along.

Eric Farman (4):
  vfio-ccw: Refactor how the traces are built
  vfio-ccw: Trace the FSM jumptable
  vfio-ccw: Add a trace for asynchronous requests
  vfio-ccw: Rename the io_fctl trace

 drivers/s390/cio/Makefile           |  4 +--
 drivers/s390/cio/vfio_ccw_cp.h      |  1 +
 drivers/s390/cio/vfio_ccw_fsm.c     | 11 +++---
 drivers/s390/cio/vfio_ccw_private.h |  1 +
 drivers/s390/cio/vfio_ccw_trace.c   | 14 ++++++++
 drivers/s390/cio/vfio_ccw_trace.h   | 56 ++++++++++++++++++++++++++++-
 6 files changed, 79 insertions(+), 8 deletions(-)
 create mode 100644 drivers/s390/cio/vfio_ccw_trace.c

-- 
2.17.1

[RFC PATCH 1/4] vfio-ccw: Refactor how the traces are built

[Eric Farman]

Commit 3cd90214b70f ("vfio: ccw: add tracepoints for interesting error
paths") added a quick trace point to determine where a channel program
failed while being processed.  It's a great addition, but adding more
traces to vfio-ccw is more cumbersome than it needs to be.

Let's refactor how this is done, so that additional traces are easier
to add and can exist outside of the FSM if we ever desire.

Signed-off-by: Eric Farman <farman@linux.ibm.com>
---
 drivers/s390/cio/Makefile         |  4 ++--
 drivers/s390/cio/vfio_ccw_cp.h    |  1 +
 drivers/s390/cio/vfio_ccw_fsm.c   |  3 ---
 drivers/s390/cio/vfio_ccw_trace.c | 12 ++++++++++++
 drivers/s390/cio/vfio_ccw_trace.h |  2 ++
 5 files changed, 17 insertions(+), 5 deletions(-)
 create mode 100644 drivers/s390/cio/vfio_ccw_trace.c

diff --git a/drivers/s390/cio/Makefile b/drivers/s390/cio/Makefile
index f6a8db04177c..23eae4188876 100644
--- a/drivers/s390/cio/Makefile
+++ b/drivers/s390/cio/Makefile
@@ -5,7 +5,7 @@
 
 # The following is required for define_trace.h to find ./trace.h
 CFLAGS_trace.o := -I$(src)
-CFLAGS_vfio_ccw_fsm.o := -I$(src)
+CFLAGS_vfio_ccw_trace.o := -I$(src)
 
 obj-y += airq.o blacklist.o chsc.o cio.o css.o chp.o idset.o isc.o \
 	fcx.o itcw.o crw.o ccwreq.o trace.o ioasm.o
@@ -21,5 +21,5 @@ qdio-objs := qdio_main.o qdio_thinint.o qdio_debug.o qdio_setup.o
 obj-$(CONFIG_QDIO) += qdio.o
 
 vfio_ccw-objs += vfio_ccw_drv.o vfio_ccw_cp.o vfio_ccw_ops.o vfio_ccw_fsm.o \
-	vfio_ccw_async.o
+	vfio_ccw_async.o vfio_ccw_trace.o
 obj-$(CONFIG_VFIO_CCW) += vfio_ccw.o
diff --git a/drivers/s390/cio/vfio_ccw_cp.h b/drivers/s390/cio/vfio_ccw_cp.h
index 7cdc38049033..ba31240ce965 100644
--- a/drivers/s390/cio/vfio_ccw_cp.h
+++ b/drivers/s390/cio/vfio_ccw_cp.h
@@ -15,6 +15,7 @@
 #include <asm/scsw.h>
 
 #include "orb.h"
+#include "vfio_ccw_trace.h"
 
 /*
  * Max length for ccw chain.
diff --git a/drivers/s390/cio/vfio_ccw_fsm.c b/drivers/s390/cio/vfio_ccw_fsm.c
index 4a1e727c62d9..d4119e4c4a8c 100644
--- a/drivers/s390/cio/vfio_ccw_fsm.c
+++ b/drivers/s390/cio/vfio_ccw_fsm.c
@@ -15,9 +15,6 @@
 #include "ioasm.h"
 #include "vfio_ccw_private.h"
 
-#define CREATE_TRACE_POINTS
-#include "vfio_ccw_trace.h"
-
 static int fsm_io_helper(struct vfio_ccw_private *private)
 {
 	struct subchannel *sch;
diff --git a/drivers/s390/cio/vfio_ccw_trace.c b/drivers/s390/cio/vfio_ccw_trace.c
new file mode 100644
index 000000000000..d5cc943c6864
--- /dev/null
+++ b/drivers/s390/cio/vfio_ccw_trace.c
@@ -0,0 +1,12 @@
+// SPDX-License-Identifier: GPL-2.0
+/*
+ * Tracepoint definitions for vfio_ccw
+ *
+ * Copyright IBM Corp. 2019
+ * Author(s): Eric Farman <farman@linux.ibm.com>
+ */
+
+#define CREATE_TRACE_POINTS
+#include "vfio_ccw_trace.h"
+
+EXPORT_TRACEPOINT_SYMBOL(vfio_ccw_io_fctl);
diff --git a/drivers/s390/cio/vfio_ccw_trace.h b/drivers/s390/cio/vfio_ccw_trace.h
index b1da53ddec1f..2a2937a40124 100644
--- a/drivers/s390/cio/vfio_ccw_trace.h
+++ b/drivers/s390/cio/vfio_ccw_trace.h
@@ -7,6 +7,8 @@
  *            Halil Pasic <pasic@linux.vnet.ibm.com>
  */
 
+#include "cio.h"
+
 #undef TRACE_SYSTEM
 #define TRACE_SYSTEM vfio_ccw
 
-- 
2.17.1

[RFC PATCH 2/4] vfio-ccw: Trace the FSM jumptable

[Eric Farman]

It would be nice if we could track the sequence of events within
vfio-ccw, based on the state of the device/FSM and our calling
sequence within it.  So let's add a simple trace here so we can
watch the states change as things go, and allow it to be folded
into the rest of the other cio traces.

Signed-off-by: Eric Farman <farman@linux.ibm.com>
---
 drivers/s390/cio/vfio_ccw_private.h |  1 +
 drivers/s390/cio/vfio_ccw_trace.c   |  1 +
 drivers/s390/cio/vfio_ccw_trace.h   | 26 ++++++++++++++++++++++++++
 3 files changed, 28 insertions(+)

diff --git a/drivers/s390/cio/vfio_ccw_private.h b/drivers/s390/cio/vfio_ccw_private.h
index bbe9babf767b..9b9bb4982972 100644
--- a/drivers/s390/cio/vfio_ccw_private.h
+++ b/drivers/s390/cio/vfio_ccw_private.h
@@ -135,6 +135,7 @@ extern fsm_func_t *vfio_ccw_jumptable[NR_VFIO_CCW_STATES][NR_VFIO_CCW_EVENTS];
 static inline void vfio_ccw_fsm_event(struct vfio_ccw_private *private,
 				     int event)
 {
+	trace_vfio_ccw_fsm_event(private->sch->schid, private->state, event);
 	vfio_ccw_jumptable[private->state][event](private, event);
 }
 
diff --git a/drivers/s390/cio/vfio_ccw_trace.c b/drivers/s390/cio/vfio_ccw_trace.c
index d5cc943c6864..b37bc68e7f18 100644
--- a/drivers/s390/cio/vfio_ccw_trace.c
+++ b/drivers/s390/cio/vfio_ccw_trace.c
@@ -9,4 +9,5 @@
 #define CREATE_TRACE_POINTS
 #include "vfio_ccw_trace.h"
 
+EXPORT_TRACEPOINT_SYMBOL(vfio_ccw_fsm_event);
 EXPORT_TRACEPOINT_SYMBOL(vfio_ccw_io_fctl);
diff --git a/drivers/s390/cio/vfio_ccw_trace.h b/drivers/s390/cio/vfio_ccw_trace.h
index 2a2937a40124..24a8152acfdf 100644
--- a/drivers/s390/cio/vfio_ccw_trace.h
+++ b/drivers/s390/cio/vfio_ccw_trace.h
@@ -17,6 +17,32 @@
 
 #include <linux/tracepoint.h>
 
+TRACE_EVENT(vfio_ccw_fsm_event,
+	TP_PROTO(struct subchannel_id schid, int state, int event),
+	TP_ARGS(schid, state, event),
+
+	TP_STRUCT__entry(
+		__field(u8, cssid)
+		__field(u8, ssid)
+		__field(u16, schno)
+		__field(int, state)
+		__field(int, event)
+	),
+
+	TP_fast_assign(
+		__entry->cssid = schid.cssid;
+		__entry->ssid = schid.ssid;
+		__entry->schno = schid.sch_no;
+		__entry->state = state;
+		__entry->event = event;
+	),
+
+	TP_printk("schid=%x.%x.%04x state=%x event=%x",
+		__entry->cssid, __entry->ssid, __entry->schno,
+		__entry->state,
+		__entry->event)
+);
+
 TRACE_EVENT(vfio_ccw_io_fctl,
 	TP_PROTO(int fctl, struct subchannel_id schid, int errno, char *errstr),
 	TP_ARGS(fctl, schid, errno, errstr),
-- 
2.17.1

[RFC PATCH 3/4] vfio-ccw: Add a trace for asynchronous requests

[Eric Farman]

Since the asynchronous requests are typically associated with
error recovery, let's add a simple trace when one of those is
issued to a device.

Signed-off-by: Eric Farman <farman@linux.ibm.com>
---
 drivers/s390/cio/vfio_ccw_fsm.c   |  4 ++++
 drivers/s390/cio/vfio_ccw_trace.c |  1 +
 drivers/s390/cio/vfio_ccw_trace.h | 26 ++++++++++++++++++++++++++
 3 files changed, 31 insertions(+)

diff --git a/drivers/s390/cio/vfio_ccw_fsm.c b/drivers/s390/cio/vfio_ccw_fsm.c
index d4119e4c4a8c..23648a9aa721 100644
--- a/drivers/s390/cio/vfio_ccw_fsm.c
+++ b/drivers/s390/cio/vfio_ccw_fsm.c
@@ -341,6 +341,10 @@ static void fsm_async_request(struct vfio_ccw_private *private,
 		/* should not happen? */
 		cmd_region->ret_code = -EINVAL;
 	}
+
+	trace_vfio_ccw_fsm_async_request(get_schid(private),
+					 cmd_region->command,
+					 cmd_region->ret_code);
 }
 
 /*
diff --git a/drivers/s390/cio/vfio_ccw_trace.c b/drivers/s390/cio/vfio_ccw_trace.c
index b37bc68e7f18..37ecbf8be805 100644
--- a/drivers/s390/cio/vfio_ccw_trace.c
+++ b/drivers/s390/cio/vfio_ccw_trace.c
@@ -9,5 +9,6 @@
 #define CREATE_TRACE_POINTS
 #include "vfio_ccw_trace.h"
 
+EXPORT_TRACEPOINT_SYMBOL(vfio_ccw_fsm_async_request);
 EXPORT_TRACEPOINT_SYMBOL(vfio_ccw_fsm_event);
 EXPORT_TRACEPOINT_SYMBOL(vfio_ccw_io_fctl);
diff --git a/drivers/s390/cio/vfio_ccw_trace.h b/drivers/s390/cio/vfio_ccw_trace.h
index 24a8152acfdf..4be2e36242e6 100644
--- a/drivers/s390/cio/vfio_ccw_trace.h
+++ b/drivers/s390/cio/vfio_ccw_trace.h
@@ -17,6 +17,32 @@
 
 #include <linux/tracepoint.h>
 
+TRACE_EVENT(vfio_ccw_fsm_async_request,
+	TP_PROTO(struct subchannel_id schid,
+		 int command,
+		 int errno),
+	TP_ARGS(schid, command, errno),
+
+	TP_STRUCT__entry(
+		__field_struct(struct subchannel_id, schid)
+		__field(int, command)
+		__field(int, errno)
+	),
+
+	TP_fast_assign(
+		__entry->schid = schid;
+		__entry->command = command;
+		__entry->errno = errno;
+	),
+
+	TP_printk("schid=%x.%x.%04x command=%d errno=%d",
+		  __entry->schid.cssid,
+		  __entry->schid.ssid,
+		  __entry->schid.sch_no,
+		  __entry->command,
+		  __entry->errno)
+);
+
 TRACE_EVENT(vfio_ccw_fsm_event,
 	TP_PROTO(struct subchannel_id schid, int state, int event),
 	TP_ARGS(schid, state, event),
-- 
2.17.1

[RFC PATCH 4/4] vfio-ccw: Rename the io_fctl trace

[Eric Farman]

Rename this trace to the function name, so we remember what is being
traced instead of an abstract reference to the function control bit
of the SCSW (since that exists in the IRB, but not the ORB).

Signed-off-by: Eric Farman <farman@linux.ibm.com>
---
 drivers/s390/cio/vfio_ccw_fsm.c   | 4 ++--
 drivers/s390/cio/vfio_ccw_trace.c | 2 +-
 drivers/s390/cio/vfio_ccw_trace.h | 2 +-
 3 files changed, 4 insertions(+), 4 deletions(-)

diff --git a/drivers/s390/cio/vfio_ccw_fsm.c b/drivers/s390/cio/vfio_ccw_fsm.c
index 23648a9aa721..23e61aa638e4 100644
--- a/drivers/s390/cio/vfio_ccw_fsm.c
+++ b/drivers/s390/cio/vfio_ccw_fsm.c
@@ -318,8 +318,8 @@ static void fsm_io_request(struct vfio_ccw_private *private,
 	}
 
 err_out:
-	trace_vfio_ccw_io_fctl(scsw->cmd.fctl, schid,
-			       io_region->ret_code, errstr);
+	trace_vfio_ccw_fsm_io_request(scsw->cmd.fctl, schid,
+				      io_region->ret_code, errstr);
 }
 
 /*
diff --git a/drivers/s390/cio/vfio_ccw_trace.c b/drivers/s390/cio/vfio_ccw_trace.c
index 37ecbf8be805..8c671d2519f6 100644
--- a/drivers/s390/cio/vfio_ccw_trace.c
+++ b/drivers/s390/cio/vfio_ccw_trace.c
@@ -11,4 +11,4 @@
 
 EXPORT_TRACEPOINT_SYMBOL(vfio_ccw_fsm_async_request);
 EXPORT_TRACEPOINT_SYMBOL(vfio_ccw_fsm_event);
-EXPORT_TRACEPOINT_SYMBOL(vfio_ccw_io_fctl);
+EXPORT_TRACEPOINT_SYMBOL(vfio_ccw_fsm_io_request);
diff --git a/drivers/s390/cio/vfio_ccw_trace.h b/drivers/s390/cio/vfio_ccw_trace.h
index 4be2e36242e6..415aa23658ad 100644
--- a/drivers/s390/cio/vfio_ccw_trace.h
+++ b/drivers/s390/cio/vfio_ccw_trace.h
@@ -69,7 +69,7 @@ TRACE_EVENT(vfio_ccw_fsm_event,
 		__entry->event)
 );
 
-TRACE_EVENT(vfio_ccw_io_fctl,
+TRACE_EVENT(vfio_ccw_fsm_io_request,
 	TP_PROTO(int fctl, struct subchannel_id schid, int errno, char *errstr),
 	TP_ARGS(fctl, schid, errno, errstr),
 
-- 
2.17.1

Re: [RFC PATCH 3/4] vfio-ccw: Add a trace for asynchronous requests

[Steffen Maier]

On 10/14/19 8:08 PM, Eric Farman wrote:
> Since the asynchronous requests are typically associated with
> error recovery, let's add a simple trace when one of those is
> issued to a device.
> 
> Signed-off-by: Eric Farman <farman@linux.ibm.com>
> ---
>   drivers/s390/cio/vfio_ccw_fsm.c   |  4 ++++
>   drivers/s390/cio/vfio_ccw_trace.c |  1 +
>   drivers/s390/cio/vfio_ccw_trace.h | 26 ++++++++++++++++++++++++++
>   3 files changed, 31 insertions(+)
> 
> diff --git a/drivers/s390/cio/vfio_ccw_fsm.c b/drivers/s390/cio/vfio_ccw_fsm.c
> index d4119e4c4a8c..23648a9aa721 100644
> --- a/drivers/s390/cio/vfio_ccw_fsm.c
> +++ b/drivers/s390/cio/vfio_ccw_fsm.c
> @@ -341,6 +341,10 @@ static void fsm_async_request(struct vfio_ccw_private *private,
>   		/* should not happen? */
>   		cmd_region->ret_code = -EINVAL;
>   	}
> +
> +	trace_vfio_ccw_fsm_async_request(get_schid(private),
> +					 cmd_region->command,
> +					 cmd_region->ret_code);
>   }
> 
>   /*
> diff --git a/drivers/s390/cio/vfio_ccw_trace.c b/drivers/s390/cio/vfio_ccw_trace.c
> index b37bc68e7f18..37ecbf8be805 100644
> --- a/drivers/s390/cio/vfio_ccw_trace.c
> +++ b/drivers/s390/cio/vfio_ccw_trace.c
> @@ -9,5 +9,6 @@
>   #define CREATE_TRACE_POINTS
>   #include "vfio_ccw_trace.h"
> 
> +EXPORT_TRACEPOINT_SYMBOL(vfio_ccw_fsm_async_request);
>   EXPORT_TRACEPOINT_SYMBOL(vfio_ccw_fsm_event);
>   EXPORT_TRACEPOINT_SYMBOL(vfio_ccw_io_fctl);
> diff --git a/drivers/s390/cio/vfio_ccw_trace.h b/drivers/s390/cio/vfio_ccw_trace.h
> index 24a8152acfdf..4be2e36242e6 100644
> --- a/drivers/s390/cio/vfio_ccw_trace.h
> +++ b/drivers/s390/cio/vfio_ccw_trace.h
> @@ -17,6 +17,32 @@
> 
>   #include <linux/tracepoint.h>
> 
> +TRACE_EVENT(vfio_ccw_fsm_async_request,
> +	TP_PROTO(struct subchannel_id schid,
> +		 int command,
> +		 int errno),
> +	TP_ARGS(schid, command, errno),
> +
> +	TP_STRUCT__entry(
> +		__field_struct(struct subchannel_id, schid)

Not sure: Does this allow the user to filter for fields of struct subchannel_id 
or can the user express a filter on the entire combined struct subchannel_id?
In the preceding patch you have the 3 parts of schid as explicit separate trace 
fields in the tracepoint.

> +		__field(int, command)
> +		__field(int, errno)
> +	),
> +
> +	TP_fast_assign(
> +		__entry->schid = schid;
> +		__entry->command = command;
> +		__entry->errno = errno;
> +	),
> +
> +	TP_printk("schid=%x.%x.%04x command=%d errno=%d",
> +		  __entry->schid.cssid,
> +		  __entry->schid.ssid,
> +		  __entry->schid.sch_no,
> +		  __entry->command,
> +		  __entry->errno)
> +);
> +
>   TRACE_EVENT(vfio_ccw_fsm_event,
>   	TP_PROTO(struct subchannel_id schid, int state, int event),
>   	TP_ARGS(schid, state, event),
> 


-- 
Mit freundlichen Gruessen / Kind regards
Steffen Maier

Linux on IBM Z Development

https://www.ibm.com/privacy/us/en/
IBM Deutschland Research & Development GmbH
Vorsitzender des Aufsichtsrats: Matthias Hartmann
Geschaeftsfuehrung: Dirk Wittkopp
Sitz der Gesellschaft: Boeblingen
Registergericht: Amtsgericht Stuttgart, HRB 243294

Re: [RFC PATCH 2/4] vfio-ccw: Trace the FSM jumptable

[Steffen Maier]

On 10/14/19 8:08 PM, Eric Farman wrote:
> It would be nice if we could track the sequence of events within
> vfio-ccw, based on the state of the device/FSM and our calling
> sequence within it.  So let's add a simple trace here so we can
> watch the states change as things go, and allow it to be folded
> into the rest of the other cio traces.
> 
> Signed-off-by: Eric Farman <farman@linux.ibm.com>
> ---
>   drivers/s390/cio/vfio_ccw_private.h |  1 +
>   drivers/s390/cio/vfio_ccw_trace.c   |  1 +
>   drivers/s390/cio/vfio_ccw_trace.h   | 26 ++++++++++++++++++++++++++
>   3 files changed, 28 insertions(+)
> 
> diff --git a/drivers/s390/cio/vfio_ccw_private.h b/drivers/s390/cio/vfio_ccw_private.h
> index bbe9babf767b..9b9bb4982972 100644
> --- a/drivers/s390/cio/vfio_ccw_private.h
> +++ b/drivers/s390/cio/vfio_ccw_private.h
> @@ -135,6 +135,7 @@ extern fsm_func_t *vfio_ccw_jumptable[NR_VFIO_CCW_STATES][NR_VFIO_CCW_EVENTS];
>   static inline void vfio_ccw_fsm_event(struct vfio_ccw_private *private,
>   				     int event)
>   {
> +	trace_vfio_ccw_fsm_event(private->sch->schid, private->state, event);
>   	vfio_ccw_jumptable[private->state][event](private, event);
>   }
> 
> diff --git a/drivers/s390/cio/vfio_ccw_trace.c b/drivers/s390/cio/vfio_ccw_trace.c
> index d5cc943c6864..b37bc68e7f18 100644
> --- a/drivers/s390/cio/vfio_ccw_trace.c
> +++ b/drivers/s390/cio/vfio_ccw_trace.c
> @@ -9,4 +9,5 @@
>   #define CREATE_TRACE_POINTS
>   #include "vfio_ccw_trace.h"
> 
> +EXPORT_TRACEPOINT_SYMBOL(vfio_ccw_fsm_event);
>   EXPORT_TRACEPOINT_SYMBOL(vfio_ccw_io_fctl);
> diff --git a/drivers/s390/cio/vfio_ccw_trace.h b/drivers/s390/cio/vfio_ccw_trace.h
> index 2a2937a40124..24a8152acfdf 100644
> --- a/drivers/s390/cio/vfio_ccw_trace.h
> +++ b/drivers/s390/cio/vfio_ccw_trace.h
> @@ -17,6 +17,32 @@
> 
>   #include <linux/tracepoint.h>
> 
> +TRACE_EVENT(vfio_ccw_fsm_event,
> +	TP_PROTO(struct subchannel_id schid, int state, int event),
> +	TP_ARGS(schid, state, event),
> +
> +	TP_STRUCT__entry(
> +		__field(u8, cssid)
> +		__field(u8, ssid)
> +		__field(u16, schno)
> +		__field(int, state)
> +		__field(int, event)
> +	),
> +
> +	TP_fast_assign(
> +		__entry->cssid = schid.cssid;
> +		__entry->ssid = schid.ssid;
> +		__entry->schno = schid.sch_no;
> +		__entry->state = state;
> +		__entry->event = event;
> +	),
> +
> +	TP_printk("schid=%x.%x.%04x state=%x event=%x",

/sys/kernel/debug/tracing/events](0)# grep -R '%[^%]*x'

Many existing TPs often seem to format hex output with a 0x prefix (either 
explicit with 0x%x or implicit with %#x). Since some of your other TPs also 
output decimal integer values, I wonder if a distinction would help 
unexperienced TP readers.

> +		__entry->cssid, __entry->ssid, __entry->schno,
> +		__entry->state,
> +		__entry->event)
> +);
> +
>   TRACE_EVENT(vfio_ccw_io_fctl,
>   	TP_PROTO(int fctl, struct subchannel_id schid, int errno, char *errstr),
>   	TP_ARGS(fctl, schid, errno, errstr),
> 


-- 
Mit freundlichen Gruessen / Kind regards
Steffen Maier

Linux on IBM Z Development

https://www.ibm.com/privacy/us/en/
IBM Deutschland Research & Development GmbH
Vorsitzender des Aufsichtsrats: Matthias Hartmann
Geschaeftsfuehrung: Dirk Wittkopp
Sitz der Gesellschaft: Boeblingen
Registergericht: Amtsgericht Stuttgart, HRB 243294

Re: [RFC PATCH 2/4] vfio-ccw: Trace the FSM jumptable

[Eric Farman]

On 10/15/19 6:01 AM, Steffen Maier wrote:
> On 10/14/19 8:08 PM, Eric Farman wrote:
>> It would be nice if we could track the sequence of events within
>> vfio-ccw, based on the state of the device/FSM and our calling
>> sequence within it.  So let's add a simple trace here so we can
>> watch the states change as things go, and allow it to be folded
>> into the rest of the other cio traces.
>>
>> Signed-off-by: Eric Farman <farman@linux.ibm.com>
>> ---
>>   drivers/s390/cio/vfio_ccw_private.h |  1 +
>>   drivers/s390/cio/vfio_ccw_trace.c   |  1 +
>>   drivers/s390/cio/vfio_ccw_trace.h   | 26 ++++++++++++++++++++++++++
>>   3 files changed, 28 insertions(+)
>>
>> diff --git a/drivers/s390/cio/vfio_ccw_private.h
>> b/drivers/s390/cio/vfio_ccw_private.h
>> index bbe9babf767b..9b9bb4982972 100644
>> --- a/drivers/s390/cio/vfio_ccw_private.h
>> +++ b/drivers/s390/cio/vfio_ccw_private.h
>> @@ -135,6 +135,7 @@ extern fsm_func_t
>> *vfio_ccw_jumptable[NR_VFIO_CCW_STATES][NR_VFIO_CCW_EVENTS];
>>   static inline void vfio_ccw_fsm_event(struct vfio_ccw_private *private,
>>                        int event)
>>   {
>> +    trace_vfio_ccw_fsm_event(private->sch->schid, private->state,
>> event);
>>       vfio_ccw_jumptable[private->state][event](private, event);
>>   }
>>
>> diff --git a/drivers/s390/cio/vfio_ccw_trace.c
>> b/drivers/s390/cio/vfio_ccw_trace.c
>> index d5cc943c6864..b37bc68e7f18 100644
>> --- a/drivers/s390/cio/vfio_ccw_trace.c
>> +++ b/drivers/s390/cio/vfio_ccw_trace.c
>> @@ -9,4 +9,5 @@
>>   #define CREATE_TRACE_POINTS
>>   #include "vfio_ccw_trace.h"
>>
>> +EXPORT_TRACEPOINT_SYMBOL(vfio_ccw_fsm_event);
>>   EXPORT_TRACEPOINT_SYMBOL(vfio_ccw_io_fctl);
>> diff --git a/drivers/s390/cio/vfio_ccw_trace.h
>> b/drivers/s390/cio/vfio_ccw_trace.h
>> index 2a2937a40124..24a8152acfdf 100644
>> --- a/drivers/s390/cio/vfio_ccw_trace.h
>> +++ b/drivers/s390/cio/vfio_ccw_trace.h
>> @@ -17,6 +17,32 @@
>>
>>   #include <linux/tracepoint.h>
>>
>> +TRACE_EVENT(vfio_ccw_fsm_event,
>> +    TP_PROTO(struct subchannel_id schid, int state, int event),
>> +    TP_ARGS(schid, state, event),
>> +
>> +    TP_STRUCT__entry(
>> +        __field(u8, cssid)
>> +        __field(u8, ssid)
>> +        __field(u16, schno)
>> +        __field(int, state)
>> +        __field(int, event)
>> +    ),
>> +
>> +    TP_fast_assign(
>> +        __entry->cssid = schid.cssid;
>> +        __entry->ssid = schid.ssid;
>> +        __entry->schno = schid.sch_no;
>> +        __entry->state = state;
>> +        __entry->event = event;
>> +    ),
>> +
>> +    TP_printk("schid=%x.%x.%04x state=%x event=%x",
> 
> /sys/kernel/debug/tracing/events](0)# grep -R '%[^%]*x'
> 
> Many existing TPs often seem to format hex output with a 0x prefix
> (either explicit with 0x%x or implicit with %#x). Since some of your
> other TPs also output decimal integer values, I wonder if a distinction
> would help unexperienced TP readers.

Fair enough.  Since they're just enumerated values, they are probably
better as %d; I don't have a good reason for picking %x (with or without
a preceding 0x).

> 
>> +        __entry->cssid, __entry->ssid, __entry->schno,
>> +        __entry->state,
>> +        __entry->event)
>> +);
>> +
>>   TRACE_EVENT(vfio_ccw_io_fctl,
>>       TP_PROTO(int fctl, struct subchannel_id schid, int errno, char
>> *errstr),
>>       TP_ARGS(fctl, schid, errno, errstr),
>>
> 
> 

Re: [RFC PATCH 1/4] vfio-ccw: Refactor how the traces are built

[Cornelia Huck]

On Mon, 14 Oct 2019 20:08:52 +0200
Eric Farman <farman@linux.ibm.com> wrote:

> Commit 3cd90214b70f ("vfio: ccw: add tracepoints for interesting error
> paths") added a quick trace point to determine where a channel program
> failed while being processed.  It's a great addition, but adding more
> traces to vfio-ccw is more cumbersome than it needs to be.
> 
> Let's refactor how this is done, so that additional traces are easier
> to add and can exist outside of the FSM if we ever desire.
> 
> Signed-off-by: Eric Farman <farman@linux.ibm.com>
> ---
>  drivers/s390/cio/Makefile         |  4 ++--
>  drivers/s390/cio/vfio_ccw_cp.h    |  1 +
>  drivers/s390/cio/vfio_ccw_fsm.c   |  3 ---
>  drivers/s390/cio/vfio_ccw_trace.c | 12 ++++++++++++
>  drivers/s390/cio/vfio_ccw_trace.h |  2 ++
>  5 files changed, 17 insertions(+), 5 deletions(-)
>  create mode 100644 drivers/s390/cio/vfio_ccw_trace.c

Looks good.

I'm wondering whether we could consolidate tracepoints and s390dbf
usage somehow. These two complement each other in a way (looking at a
live system vs. looking at a crash dump, integration with other parts
of the system), but they currently also cover at least partially
different code paths. Not sure how much sense it makes to have double
coverage at least for a subset of the functionality.

Re: [RFC PATCH 2/4] vfio-ccw: Trace the FSM jumptable

[Cornelia Huck]

On Tue, 15 Oct 2019 12:01:12 +0200
Steffen Maier <maier@linux.ibm.com> wrote:

> On 10/14/19 8:08 PM, Eric Farman wrote:
> > It would be nice if we could track the sequence of events within
> > vfio-ccw, based on the state of the device/FSM and our calling
> > sequence within it.  So let's add a simple trace here so we can
> > watch the states change as things go, and allow it to be folded
> > into the rest of the other cio traces.
> > 
> > Signed-off-by: Eric Farman <farman@linux.ibm.com>
> > ---
> >   drivers/s390/cio/vfio_ccw_private.h |  1 +
> >   drivers/s390/cio/vfio_ccw_trace.c   |  1 +
> >   drivers/s390/cio/vfio_ccw_trace.h   | 26 ++++++++++++++++++++++++++
> >   3 files changed, 28 insertions(+)

(...)

> > diff --git a/drivers/s390/cio/vfio_ccw_trace.h b/drivers/s390/cio/vfio_ccw_trace.h
> > index 2a2937a40124..24a8152acfdf 100644
> > --- a/drivers/s390/cio/vfio_ccw_trace.h
> > +++ b/drivers/s390/cio/vfio_ccw_trace.h
> > @@ -17,6 +17,32 @@
> > 
> >   #include <linux/tracepoint.h>
> > 
> > +TRACE_EVENT(vfio_ccw_fsm_event,
> > +	TP_PROTO(struct subchannel_id schid, int state, int event),
> > +	TP_ARGS(schid, state, event),
> > +
> > +	TP_STRUCT__entry(
> > +		__field(u8, cssid)
> > +		__field(u8, ssid)
> > +		__field(u16, schno)
> > +		__field(int, state)
> > +		__field(int, event)
> > +	),
> > +
> > +	TP_fast_assign(
> > +		__entry->cssid = schid.cssid;
> > +		__entry->ssid = schid.ssid;
> > +		__entry->schno = schid.sch_no;
> > +		__entry->state = state;
> > +		__entry->event = event;
> > +	),
> > +
> > +	TP_printk("schid=%x.%x.%04x state=%x event=%x",  
> 
> /sys/kernel/debug/tracing/events](0)# grep -R '%[^%]*x'
> 
> Many existing TPs often seem to format hex output with a 0x prefix (either 
> explicit with 0x%x or implicit with %#x). Since some of your other TPs also 
> output decimal integer values, I wonder if a distinction would help 
> unexperienced TP readers.

I generally agree. However, we explicitly don't want to do that for
schid formatting (as it should match the bus id). For event, it might
become relevant should we want to introduce a high number of new events
in the future (currently, there's a grand total of four events.)

> 
> > +		__entry->cssid, __entry->ssid, __entry->schno,
> > +		__entry->state,
> > +		__entry->event)
> > +);
> > +
> >   TRACE_EVENT(vfio_ccw_io_fctl,
> >   	TP_PROTO(int fctl, struct subchannel_id schid, int errno, char *errstr),
> >   	TP_ARGS(fctl, schid, errno, errstr),
> >   
> 
> 

Re: [RFC PATCH 4/4] vfio-ccw: Rename the io_fctl trace

[Cornelia Huck]

On Mon, 14 Oct 2019 20:08:55 +0200
Eric Farman <farman@linux.ibm.com> wrote:

> Rename this trace to the function name, so we remember what is being
> traced instead of an abstract reference to the function control bit
> of the SCSW (since that exists in the IRB, but not the ORB).
> 
> Signed-off-by: Eric Farman <farman@linux.ibm.com>
> ---
>  drivers/s390/cio/vfio_ccw_fsm.c   | 4 ++--
>  drivers/s390/cio/vfio_ccw_trace.c | 2 +-
>  drivers/s390/cio/vfio_ccw_trace.h | 2 +-
>  3 files changed, 4 insertions(+), 4 deletions(-)

That makes sense (I don't supposed this is used in any tooling, as it
is more of a low-level debug trace.)

Re: [RFC PATCH 2/4] vfio-ccw: Trace the FSM jumptable

[Steffen Maier]

On 10/15/19 3:53 PM, Cornelia Huck wrote:
> On Tue, 15 Oct 2019 12:01:12 +0200
> Steffen Maier <maier@linux.ibm.com> wrote:
> 
>> On 10/14/19 8:08 PM, Eric Farman wrote:
>>> It would be nice if we could track the sequence of events within
>>> vfio-ccw, based on the state of the device/FSM and our calling
>>> sequence within it.  So let's add a simple trace here so we can
>>> watch the states change as things go, and allow it to be folded
>>> into the rest of the other cio traces.
>>>
>>> Signed-off-by: Eric Farman <farman@linux.ibm.com>
>>> ---
>>>    drivers/s390/cio/vfio_ccw_private.h |  1 +
>>>    drivers/s390/cio/vfio_ccw_trace.c   |  1 +
>>>    drivers/s390/cio/vfio_ccw_trace.h   | 26 ++++++++++++++++++++++++++
>>>    3 files changed, 28 insertions(+)
> 
> (...)
> 
>>> diff --git a/drivers/s390/cio/vfio_ccw_trace.h b/drivers/s390/cio/vfio_ccw_trace.h
>>> index 2a2937a40124..24a8152acfdf 100644
>>> --- a/drivers/s390/cio/vfio_ccw_trace.h
>>> +++ b/drivers/s390/cio/vfio_ccw_trace.h
>>> @@ -17,6 +17,32 @@
>>>
>>>    #include <linux/tracepoint.h>
>>>
>>> +TRACE_EVENT(vfio_ccw_fsm_event,
>>> +	TP_PROTO(struct subchannel_id schid, int state, int event),
>>> +	TP_ARGS(schid, state, event),
>>> +
>>> +	TP_STRUCT__entry(
>>> +		__field(u8, cssid)
>>> +		__field(u8, ssid)
>>> +		__field(u16, schno)
>>> +		__field(int, state)
>>> +		__field(int, event)
>>> +	),
>>> +
>>> +	TP_fast_assign(
>>> +		__entry->cssid = schid.cssid;
>>> +		__entry->ssid = schid.ssid;
>>> +		__entry->schno = schid.sch_no;
>>> +		__entry->state = state;
>>> +		__entry->event = event;
>>> +	),
>>> +
>>> +	TP_printk("schid=%x.%x.%04x state=%x event=%x",
>>
>> /sys/kernel/debug/tracing/events](0)# grep -R '%[^%]*x'
>>
>> Many existing TPs often seem to format hex output with a 0x prefix (either
>> explicit with 0x%x or implicit with %#x). Since some of your other TPs also
>> output decimal integer values, I wonder if a distinction would help
>> unexperienced TP readers.
> 
> I generally agree. However, we explicitly don't want to do that for
> schid formatting (as it should match the bus id). For event, it might
> become relevant should we want to introduce a high number of new events
> in the future (currently, there's a grand total of four events.)

Yeah, thanks for clarifying. I meant just state and event, not schid.

> 
>>
>>> +		__entry->cssid, __entry->ssid, __entry->schno,
>>> +		__entry->state,
>>> +		__entry->event)
>>> +);
>>> +
>>>    TRACE_EVENT(vfio_ccw_io_fctl,
>>>    	TP_PROTO(int fctl, struct subchannel_id schid, int errno, char *errstr),
>>>    	TP_ARGS(fctl, schid, errno, errstr),
>>>    
>>
>>
> 


-- 
Mit freundlichen Gruessen / Kind regards
Steffen Maier

Linux on IBM Z Development

https://www.ibm.com/privacy/us/en/
IBM Deutschland Research & Development GmbH
Vorsitzender des Aufsichtsrats: Matthias Hartmann
Geschaeftsfuehrung: Dirk Wittkopp
Sitz der Gesellschaft: Boeblingen
Registergericht: Amtsgericht Stuttgart, HRB 243294

Re: [RFC PATCH 3/4] vfio-ccw: Add a trace for asynchronous requests

[Eric Farman]

On 10/15/19 5:54 AM, Steffen Maier wrote:
> On 10/14/19 8:08 PM, Eric Farman wrote:
>> Since the asynchronous requests are typically associated with
>> error recovery, let's add a simple trace when one of those is
>> issued to a device.
>>
>> Signed-off-by: Eric Farman <farman@linux.ibm.com>
>> ---
>>   drivers/s390/cio/vfio_ccw_fsm.c   |  4 ++++
>>   drivers/s390/cio/vfio_ccw_trace.c |  1 +
>>   drivers/s390/cio/vfio_ccw_trace.h | 26 ++++++++++++++++++++++++++
>>   3 files changed, 31 insertions(+)
>>
>> diff --git a/drivers/s390/cio/vfio_ccw_fsm.c
>> b/drivers/s390/cio/vfio_ccw_fsm.c
>> index d4119e4c4a8c..23648a9aa721 100644
>> --- a/drivers/s390/cio/vfio_ccw_fsm.c
>> +++ b/drivers/s390/cio/vfio_ccw_fsm.c
>> @@ -341,6 +341,10 @@ static void fsm_async_request(struct
>> vfio_ccw_private *private,
>>           /* should not happen? */
>>           cmd_region->ret_code = -EINVAL;
>>       }
>> +
>> +    trace_vfio_ccw_fsm_async_request(get_schid(private),
>> +                     cmd_region->command,
>> +                     cmd_region->ret_code);
>>   }
>>
>>   /*
>> diff --git a/drivers/s390/cio/vfio_ccw_trace.c
>> b/drivers/s390/cio/vfio_ccw_trace.c
>> index b37bc68e7f18..37ecbf8be805 100644
>> --- a/drivers/s390/cio/vfio_ccw_trace.c
>> +++ b/drivers/s390/cio/vfio_ccw_trace.c
>> @@ -9,5 +9,6 @@
>>   #define CREATE_TRACE_POINTS
>>   #include "vfio_ccw_trace.h"
>>
>> +EXPORT_TRACEPOINT_SYMBOL(vfio_ccw_fsm_async_request);
>>   EXPORT_TRACEPOINT_SYMBOL(vfio_ccw_fsm_event);
>>   EXPORT_TRACEPOINT_SYMBOL(vfio_ccw_io_fctl);
>> diff --git a/drivers/s390/cio/vfio_ccw_trace.h
>> b/drivers/s390/cio/vfio_ccw_trace.h
>> index 24a8152acfdf..4be2e36242e6 100644
>> --- a/drivers/s390/cio/vfio_ccw_trace.h
>> +++ b/drivers/s390/cio/vfio_ccw_trace.h
>> @@ -17,6 +17,32 @@
>>
>>   #include <linux/tracepoint.h>
>>
>> +TRACE_EVENT(vfio_ccw_fsm_async_request,
>> +    TP_PROTO(struct subchannel_id schid,
>> +         int command,
>> +         int errno),
>> +    TP_ARGS(schid, command, errno),
>> +
>> +    TP_STRUCT__entry(
>> +        __field_struct(struct subchannel_id, schid)
> 
> Not sure: Does this allow the user to filter for fields of struct
> subchannel_id or can the user express a filter on the entire combined
> struct subchannel_id?

Good question...  I tried playing around with this a little bit, and
while format says it's using "REC->schid.foo", trying any combination to
get an element within schid just fails, citing some form of invalid
argument (the exact reason depends on what I try).  Harrumph.

> In the preceding patch you have the 3 parts of schid as explicit
> separate trace fields in the tracepoint.

Yeah, I did.  Why didn't I do that here?  :)

Well it seems that the one trace that exists (vfio_ccw_fsm_io_request
(nee vfio_ccw_fsm_io_fctl)), uses this same field_struct, instead of the
three-piece schid.  So, I need to change this in both the I/O and
asynchronous traces.

Thanks for the suggestions!
 - Eric

> 
>> +        __field(int, command)
>> +        __field(int, errno)
>> +    ),
>> +
>> +    TP_fast_assign(
>> +        __entry->schid = schid;
>> +        __entry->command = command;
>> +        __entry->errno = errno;
>> +    ),
>> +
>> +    TP_printk("schid=%x.%x.%04x command=%d errno=%d",
>> +          __entry->schid.cssid,
>> +          __entry->schid.ssid,
>> +          __entry->schid.sch_no,
>> +          __entry->command,
>> +          __entry->errno)
>> +);
>> +
>>   TRACE_EVENT(vfio_ccw_fsm_event,
>>       TP_PROTO(struct subchannel_id schid, int state, int event),
>>       TP_ARGS(schid, state, event),
>>
> 
> 

Re: [RFC PATCH 1/4] vfio-ccw: Refactor how the traces are built

[Eric Farman]

On 10/15/19 9:46 AM, Cornelia Huck wrote:
> On Mon, 14 Oct 2019 20:08:52 +0200
> Eric Farman <farman@linux.ibm.com> wrote:
> 
>> Commit 3cd90214b70f ("vfio: ccw: add tracepoints for interesting error
>> paths") added a quick trace point to determine where a channel program
>> failed while being processed.  It's a great addition, but adding more
>> traces to vfio-ccw is more cumbersome than it needs to be.
>>
>> Let's refactor how this is done, so that additional traces are easier
>> to add and can exist outside of the FSM if we ever desire.
>>
>> Signed-off-by: Eric Farman <farman@linux.ibm.com>
>> ---
>>  drivers/s390/cio/Makefile         |  4 ++--
>>  drivers/s390/cio/vfio_ccw_cp.h    |  1 +
>>  drivers/s390/cio/vfio_ccw_fsm.c   |  3 ---
>>  drivers/s390/cio/vfio_ccw_trace.c | 12 ++++++++++++
>>  drivers/s390/cio/vfio_ccw_trace.h |  2 ++
>>  5 files changed, 17 insertions(+), 5 deletions(-)
>>  create mode 100644 drivers/s390/cio/vfio_ccw_trace.c
> 
> Looks good.
> 
> I'm wondering whether we could consolidate tracepoints and s390dbf
> usage somehow. These two complement each other in a way (looking at a
> live system vs. looking at a crash dump, integration with other parts
> of the system), but they currently also cover at least partially
> different code paths. Not sure how much sense it makes to have double
> coverage at least for a subset of the functionality.
> 

Yeah, there's gaps that could/should be closed, and maybe this patch
makes it easier to add traces to paths that s390dbf currently cover and
could benefit from having both.  Some more consideration of what is
covered and where, and what is missing, is certainliy needed.

 - Eric