[PATCH] i2c: Add message transfer tracepoints for I2C and SMBUS

[PATCH] i2c: Add message transfer tracepoints for I2C and SMBUS

[David Howells]

Add tracepoints into the I2C and SMBUS message transfer functions to retrieve
the message sent or received.  The following config options must be turned on
to make use of the facility:

	CONFIG_FTRACE
	CONFIG_ENABLE_DEFAULT_TRACERS

The I2C tracepoint can be enabled thusly:

	echo 1 >/sys/kernel/debug/tracing/events/i2c/i2c_transfer/enable

and will dump messages that can be viewed in /sys/kernel/debug/tracing/trace
that look like:

        ... i2c_transfer: i2c-5 f=00 a=44 l=6 ret=1 [021433000000]

formatted as:

	i2c-<adapter-nr>
	f=<flags>
	a=<addr>
	l=<datalen>
	ret=<result>
	[<data>]

(Bit 0 of the flags is set if this was a read and clear if it was a write).


The SMBUS tracepoint can be enabled thusly:

	echo 1 >/sys/kernel/debug/tracing/events/i2c/smbus_transfer/enable

and will dump messages that can be viewed in /sys/kernel/debug/tracing/trace
that look like:

	... smbus_transfer: i2c-0 f=00 a=51 r=1 c=0 p=2 res=0 [80ff0100000000000000800c693d0088ffffb83aee3b0088ffff0100000000000000]

formatted as:

	i2c-<adapter-nr>
	f=<flags>
	a=<addr>
	r=<read_write>
	c=<command>
	p=<protocol>
	res=<result>
	[<data-block>]


In both cases, the adapters to be traced can be selected by something like:

	echo adapter_nr==1 >/sys/kernel/debug/tracing/events/i2c/{i2c,smbus}_transfer/filter

Signed-off-by: David Howells <dhowells@redhat.com>
Reviewed-by: Steven Rostedt <rostedt@goodmis.org>
---

 drivers/i2c/i2c-core.c     |   38 ++++++++++++++++--
 include/trace/events/i2c.h |   95 ++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 130 insertions(+), 3 deletions(-)
 create mode 100644 include/trace/events/i2c.h

diff --git a/drivers/i2c/i2c-core.c b/drivers/i2c/i2c-core.c
index d74c0b34248e..2128e106ca97 100644
--- a/drivers/i2c/i2c-core.c
+++ b/drivers/i2c/i2c-core.c
@@ -48,10 +48,13 @@
 #include <linux/rwsem.h>
 #include <linux/pm_runtime.h>
 #include <linux/acpi.h>
+#include <linux/jump_label.h>
 #include <asm/uaccess.h>
 
 #include "i2c-core.h"
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/i2c.h>
 
 /* core_lock protects i2c_adapter_idr, and guarantees
    that device detection, deletion of detected devices, and attach_adapter
@@ -62,6 +65,18 @@ static DEFINE_IDR(i2c_adapter_idr);
 static struct device_type i2c_client_type;
 static int i2c_detect(struct i2c_adapter *adapter, struct i2c_driver *driver);
 
+static struct static_key i2c_trace_msg = STATIC_KEY_INIT_FALSE;
+
+void i2c_transfer_trace_reg(void)
+{
+	static_key_slow_inc(&i2c_trace_msg);
+}
+
+void i2c_transfer_trace_unreg(void)
+{
+	static_key_slow_dec(&i2c_trace_msg);
+}
+
 /* ------------------------------------------------------------------------- */
 
 static const struct i2c_device_id *i2c_match_id(const struct i2c_device_id *id,
@@ -1680,6 +1695,7 @@ static void __exit i2c_exit(void)
 	class_compat_unregister(i2c_adapter_compat_class);
 #endif
 	bus_unregister(&i2c_bus_type);
+	tracepoint_synchronize_unregister();
 }
 
 /* We must initialize early, because some subsystems register i2c drivers
@@ -1720,6 +1736,16 @@ int __i2c_transfer(struct i2c_adapter *adap, struct i2c_msg *msgs, int num)
 			break;
 	}
 
+	/* i2c_trace_msg gets enabled when tracepoint i2c_transfer gets
+	 * enabled.  This is an efficient way of keeping the for-loop from
+	 * being executed when not needed.
+	 */
+	if (static_key_false(&i2c_trace_msg)) {
+		int i;
+		for (i = 0; i < num; i++)
+			trace_i2c_transfer(adap, &msgs[i], ret);
+	}
+
 	return ret;
 }
 EXPORT_SYMBOL(__i2c_transfer);
@@ -2535,15 +2561,21 @@ s32 i2c_smbus_xfer(struct i2c_adapter *adapter, u16 addr, unsigned short flags,
 		i2c_unlock_adapter(adapter);
 
 		if (res != -EOPNOTSUPP || !adapter->algo->master_xfer)
-			return res;
+			goto trace;
 		/*
 		 * Fall back to i2c_smbus_xfer_emulated if the adapter doesn't
 		 * implement native support for the SMBus operation.
 		 */
 	}
 
-	return i2c_smbus_xfer_emulated(adapter, addr, flags, read_write,
-				       command, protocol, data);
+	res = i2c_smbus_xfer_emulated(adapter, addr, flags, read_write,
+				      command, protocol, data);
+
+trace:
+	trace_smbus_transfer(adapter, addr, flags, read_write,
+			     command, protocol, data, res);
+
+	return res;
 }
 EXPORT_SYMBOL(i2c_smbus_xfer);
 
diff --git a/include/trace/events/i2c.h b/include/trace/events/i2c.h
new file mode 100644
index 000000000000..ed366e145c8d
--- /dev/null
+++ b/include/trace/events/i2c.h
@@ -0,0 +1,95 @@
+/* I2C message transfer tracepoint
+ *
+ * Copyright (C) 2013 Red Hat, Inc. All Rights Reserved.
+ * Written by David Howells (dhowells@redhat.com)
+ *
+ * This program is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU General Public Licence
+ * as published by the Free Software Foundation; either version
+ * 2 of the Licence, or (at your option) any later version.
+ */
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM i2c
+
+#if !defined(_TRACE_I2C_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_I2C_H
+
+#include <linux/i2c.h>
+#include <linux/tracepoint.h>
+
+/*
+ * drivers/i2c/i2c-core.c
+ */
+extern void i2c_transfer_trace_reg(void);
+extern void i2c_transfer_trace_unreg(void);
+
+TRACE_EVENT_FN(i2c_transfer,
+	       TP_PROTO(const struct i2c_adapter *adap, const struct i2c_msg *msg,
+			int ret),
+	       TP_ARGS(adap, msg, ret),
+	       TP_STRUCT__entry(
+		       __field(	int,	adapter_nr		)
+		       __field(__u16,	addr			)
+		       __field(__u16,	flags			)
+		       __field(__u16,	len			)
+		       __field(__s16,	ret			)
+		       __dynamic_array(__u8, buf, msg->len)	),
+	       TP_fast_assign(
+		       __entry->adapter_nr = adap->nr;
+		       __entry->addr = msg->addr;
+		       __entry->flags = msg->flags;
+		       __entry->len = msg->len;
+		       __entry->ret = ret;
+		       memcpy(__get_dynamic_array(buf), msg->buf, msg->len);
+			      ),
+	       TP_printk("i2c-%d f=%02x a=%02x l=%u ret=%d [%*phN]",
+			 __entry->adapter_nr,
+			 __entry->flags,
+			 __entry->addr,
+			 __entry->len,
+			 __entry->ret,
+			 __entry->len, __get_dynamic_array(buf)
+			 ),
+	       i2c_transfer_trace_reg,
+	       i2c_transfer_trace_unreg);
+
+TRACE_EVENT(smbus_transfer,
+	    TP_PROTO(const struct i2c_adapter *adap,
+		     u16 addr, unsigned short flags,
+		     char read_write, u8 command, int protocol,
+		     const union i2c_smbus_data *data, int res),
+	    TP_ARGS(adap, addr, flags, read_write, command, protocol, data, res),
+	    TP_STRUCT__entry(
+		    __field(int,	adapter_nr		)
+		    __field(__u16,	addr			)
+		    __field(__u16,	flags			)
+		    __field(__u8,	read_write		)
+		    __field(__u8,	command			)
+		    __field(__s16,	res			)
+		    __field(__u32,	protocol		)
+		    __array(__u8, buf, I2C_SMBUS_BLOCK_MAX + 2)	),
+	    TP_fast_assign(
+		    __entry->adapter_nr = adap->nr;
+		    __entry->addr = addr;
+		    __entry->flags = flags;
+		    __entry->read_write = read_write;
+		    __entry->command = command;
+		    __entry->protocol = protocol;
+		    __entry->res = res;
+		    memcpy(__entry->buf, data->block, I2C_SMBUS_BLOCK_MAX + 2);
+			   ),
+	    TP_printk("i2c-%d f=%02x a=%02x r=%x c=%x p=%x res=%d [%*phN]",
+		      __entry->adapter_nr,
+		      __entry->flags,
+		      __entry->addr,
+		      __entry->read_write,
+		      __entry->command,
+		      __entry->protocol,
+		      __entry->res,
+		      I2C_SMBUS_BLOCK_MAX + 2, __entry->buf
+		      ));
+
+#endif /* _TRACE_I2C_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>

[PATCH] i2c: Add message transfer tracepoints for I2C and SMBUS

[David Howells]

Add tracepoints into the I2C and SMBUS message transfer functions to retrieve
the message sent or received.  The following config options must be turned on
to make use of the facility:

	CONFIG_FTRACE
	CONFIG_ENABLE_DEFAULT_TRACERS

The I2C tracepoint can be enabled thusly:

	echo 1 >/sys/kernel/debug/tracing/events/i2c/i2c_transfer/enable

and will dump messages that can be viewed in /sys/kernel/debug/tracing/trace
that look like:

        ... i2c_transfer: i2c-5 f=00 a=44 l=6 ret=1 [021433000000]

formatted as:

	i2c-<adapter-nr>
	f=<flags>
	a=<addr>
	l=<datalen>
	ret=<result>
	[<data>]

(Bit 0 of the flags is set if this was a read and clear if it was a write).


The SMBUS tracepoint can be enabled thusly:

	echo 1 >/sys/kernel/debug/tracing/events/i2c/smbus_transfer/enable

and will dump messages that can be viewed in /sys/kernel/debug/tracing/trace
that look like:

	... smbus_transfer: i2c-0 f=00 a=51 r=1 c=0 p=2 res=0 [80ff0100000000000000800c693d0088ffffb83aee3b0088ffff0100000000000000]

formatted as:

	i2c-<adapter-nr>
	f=<flags>
	a=<addr>
	r=<read_write>
	c=<command>
	p=<protocol>
	res=<result>
	[<data-block>]


In both cases, the adapters to be traced can be selected by something like:

	echo adapter_nr==1 >/sys/kernel/debug/tracing/events/i2c/{i2c,smbus}_transfer/filter

Signed-off-by: David Howells <dhowells-H+wXaHxf7aLQT0dZR+AlfA@public.gmane.org>
Reviewed-by: Steven Rostedt <rostedt-nx8X9YLhiw1AfugRpC6u6w@public.gmane.org>
---

 drivers/i2c/i2c-core.c     |   38 ++++++++++++++++--
 include/trace/events/i2c.h |   95 ++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 130 insertions(+), 3 deletions(-)
 create mode 100644 include/trace/events/i2c.h

diff --git a/drivers/i2c/i2c-core.c b/drivers/i2c/i2c-core.c
index d74c0b34248e..2128e106ca97 100644
--- a/drivers/i2c/i2c-core.c
+++ b/drivers/i2c/i2c-core.c
@@ -48,10 +48,13 @@
 #include <linux/rwsem.h>
 #include <linux/pm_runtime.h>
 #include <linux/acpi.h>
+#include <linux/jump_label.h>
 #include <asm/uaccess.h>
 
 #include "i2c-core.h"
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/i2c.h>
 
 /* core_lock protects i2c_adapter_idr, and guarantees
    that device detection, deletion of detected devices, and attach_adapter
@@ -62,6 +65,18 @@ static DEFINE_IDR(i2c_adapter_idr);
 static struct device_type i2c_client_type;
 static int i2c_detect(struct i2c_adapter *adapter, struct i2c_driver *driver);
 
+static struct static_key i2c_trace_msg = STATIC_KEY_INIT_FALSE;
+
+void i2c_transfer_trace_reg(void)
+{
+	static_key_slow_inc(&i2c_trace_msg);
+}
+
+void i2c_transfer_trace_unreg(void)
+{
+	static_key_slow_dec(&i2c_trace_msg);
+}
+
 /* ------------------------------------------------------------------------- */
 
 static const struct i2c_device_id *i2c_match_id(const struct i2c_device_id *id,
@@ -1680,6 +1695,7 @@ static void __exit i2c_exit(void)
 	class_compat_unregister(i2c_adapter_compat_class);
 #endif
 	bus_unregister(&i2c_bus_type);
+	tracepoint_synchronize_unregister();
 }
 
 /* We must initialize early, because some subsystems register i2c drivers
@@ -1720,6 +1736,16 @@ int __i2c_transfer(struct i2c_adapter *adap, struct i2c_msg *msgs, int num)
 			break;
 	}
 
+	/* i2c_trace_msg gets enabled when tracepoint i2c_transfer gets
+	 * enabled.  This is an efficient way of keeping the for-loop from
+	 * being executed when not needed.
+	 */
+	if (static_key_false(&i2c_trace_msg)) {
+		int i;
+		for (i = 0; i < num; i++)
+			trace_i2c_transfer(adap, &msgs[i], ret);
+	}
+
 	return ret;
 }
 EXPORT_SYMBOL(__i2c_transfer);
@@ -2535,15 +2561,21 @@ s32 i2c_smbus_xfer(struct i2c_adapter *adapter, u16 addr, unsigned short flags,
 		i2c_unlock_adapter(adapter);
 
 		if (res != -EOPNOTSUPP || !adapter->algo->master_xfer)
-			return res;
+			goto trace;
 		/*
 		 * Fall back to i2c_smbus_xfer_emulated if the adapter doesn't
 		 * implement native support for the SMBus operation.
 		 */
 	}
 
-	return i2c_smbus_xfer_emulated(adapter, addr, flags, read_write,
-				       command, protocol, data);
+	res = i2c_smbus_xfer_emulated(adapter, addr, flags, read_write,
+				      command, protocol, data);
+
+trace:
+	trace_smbus_transfer(adapter, addr, flags, read_write,
+			     command, protocol, data, res);
+
+	return res;
 }
 EXPORT_SYMBOL(i2c_smbus_xfer);
 
diff --git a/include/trace/events/i2c.h b/include/trace/events/i2c.h
new file mode 100644
index 000000000000..ed366e145c8d
--- /dev/null
+++ b/include/trace/events/i2c.h
@@ -0,0 +1,95 @@
+/* I2C message transfer tracepoint
+ *
+ * Copyright (C) 2013 Red Hat, Inc. All Rights Reserved.
+ * Written by David Howells (dhowells-H+wXaHxf7aLQT0dZR+AlfA@public.gmane.org)
+ *
+ * This program is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU General Public Licence
+ * as published by the Free Software Foundation; either version
+ * 2 of the Licence, or (at your option) any later version.
+ */
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM i2c
+
+#if !defined(_TRACE_I2C_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_I2C_H
+
+#include <linux/i2c.h>
+#include <linux/tracepoint.h>
+
+/*
+ * drivers/i2c/i2c-core.c
+ */
+extern void i2c_transfer_trace_reg(void);
+extern void i2c_transfer_trace_unreg(void);
+
+TRACE_EVENT_FN(i2c_transfer,
+	       TP_PROTO(const struct i2c_adapter *adap, const struct i2c_msg *msg,
+			int ret),
+	       TP_ARGS(adap, msg, ret),
+	       TP_STRUCT__entry(
+		       __field(	int,	adapter_nr		)
+		       __field(__u16,	addr			)
+		       __field(__u16,	flags			)
+		       __field(__u16,	len			)
+		       __field(__s16,	ret			)
+		       __dynamic_array(__u8, buf, msg->len)	),
+	       TP_fast_assign(
+		       __entry->adapter_nr = adap->nr;
+		       __entry->addr = msg->addr;
+		       __entry->flags = msg->flags;
+		       __entry->len = msg->len;
+		       __entry->ret = ret;
+		       memcpy(__get_dynamic_array(buf), msg->buf, msg->len);
+			      ),
+	       TP_printk("i2c-%d f=%02x a=%02x l=%u ret=%d [%*phN]",
+			 __entry->adapter_nr,
+			 __entry->flags,
+			 __entry->addr,
+			 __entry->len,
+			 __entry->ret,
+			 __entry->len, __get_dynamic_array(buf)
+			 ),
+	       i2c_transfer_trace_reg,
+	       i2c_transfer_trace_unreg);
+
+TRACE_EVENT(smbus_transfer,
+	    TP_PROTO(const struct i2c_adapter *adap,
+		     u16 addr, unsigned short flags,
+		     char read_write, u8 command, int protocol,
+		     const union i2c_smbus_data *data, int res),
+	    TP_ARGS(adap, addr, flags, read_write, command, protocol, data, res),
+	    TP_STRUCT__entry(
+		    __field(int,	adapter_nr		)
+		    __field(__u16,	addr			)
+		    __field(__u16,	flags			)
+		    __field(__u8,	read_write		)
+		    __field(__u8,	command			)
+		    __field(__s16,	res			)
+		    __field(__u32,	protocol		)
+		    __array(__u8, buf, I2C_SMBUS_BLOCK_MAX + 2)	),
+	    TP_fast_assign(
+		    __entry->adapter_nr = adap->nr;
+		    __entry->addr = addr;
+		    __entry->flags = flags;
+		    __entry->read_write = read_write;
+		    __entry->command = command;
+		    __entry->protocol = protocol;
+		    __entry->res = res;
+		    memcpy(__entry->buf, data->block, I2C_SMBUS_BLOCK_MAX + 2);
+			   ),
+	    TP_printk("i2c-%d f=%02x a=%02x r=%x c=%x p=%x res=%d [%*phN]",
+		      __entry->adapter_nr,
+		      __entry->flags,
+		      __entry->addr,
+		      __entry->read_write,
+		      __entry->command,
+		      __entry->protocol,
+		      __entry->res,
+		      I2C_SMBUS_BLOCK_MAX + 2, __entry->buf
+		      ));
+
+#endif /* _TRACE_I2C_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>

Re: [PATCH] i2c: Add message transfer tracepoints for I2C and SMBUS

[Jean Delvare]

Hi David,

Please note that I am no longer maintaining the i2c subsystem so you
should have sent this to Wolfram, not me.

On Fri, 13 Dec 2013 14:26:27 +0000, David Howells wrote:
> Add tracepoints into the I2C and SMBUS message transfer functions to retrieve
> the message sent or received.  The following config options must be turned on
> to make use of the facility:
> 
> 	CONFIG_FTRACE
> 	CONFIG_ENABLE_DEFAULT_TRACERS
> 
> The I2C tracepoint can be enabled thusly:
> 
> 	echo 1 >/sys/kernel/debug/tracing/events/i2c/i2c_transfer/enable
> 
> and will dump messages that can be viewed in /sys/kernel/debug/tracing/trace
> that look like:
> 
>         ... i2c_transfer: i2c-5 f=00 a=44 l=6 ret=1 [021433000000]
> 
> formatted as:
> 
> 	i2c-<adapter-nr>
> 	f=<flags>
> 	a=<addr>
> 	l=<datalen>
> 	ret=<result>
> 	[<data>]
> 
> (Bit 0 of the flags is set if this was a read and clear if it was a write).

Wouldn't the traces be more readable if the direction was written
explicitly as R or W?

> 
> 
> The SMBUS tracepoint can be enabled thusly:
> 
> 	echo 1 >/sys/kernel/debug/tracing/events/i2c/smbus_transfer/enable
> 
> and will dump messages that can be viewed in /sys/kernel/debug/tracing/trace
> that look like:
> 
> 	... smbus_transfer: i2c-0 f=00 a=51 r=1 c=0 p=2 res=0 [80ff0100000000000000800c693d0088ffffb83aee3b0088ffff0100000000000000]
> 
> formatted as:
> 
> 	i2c-<adapter-nr>
> 	f=<flags>
> 	a=<addr>
> 	r=<read_write>

Here too I would consider R and W as more readable than r=1 and r=0.

> 	c=<command>
> 	p=<protocol>

Would it be possible to print this as a string rather than a number?
The protocol numbers are completely arbitrary, so the reader would have
to open i2c.h each time to figure out what is what.

> 	res=<result>
> 	[<data-block>]
> 
> 
> In both cases, the adapters to be traced can be selected by something like:
> 
> 	echo adapter_nr==1 >/sys/kernel/debug/tracing/events/i2c/{i2c,smbus}_transfer/filter

I have no objection to the feature, but it should be noted that
i2c-core already offers something similar (albeit less flexible) for
I2C level transfers:

#ifdef DEBUG
		for (ret = 0; ret < num; ret++) {
			dev_dbg(&adap->dev, "master_xfer[%d] %c, addr=0x%02x, "
				"len=%d%s\n", ret, (msgs[ret].flags & I2C_M_RD)
				? 'R' : 'W', msgs[ret].addr, msgs[ret].len,
				(msgs[ret].flags & I2C_M_RECV_LEN) ? "+" : "");
		}
#endif

If your code goes in, I suppose the code above should be removed to
avoid redundancy.

One significant difference between both implementations is that the old
one logs before the actual transfer, while yours logs afterward. While I
understand this allows you to log the result of the transfer, this also
means you'll miss the log if the actual transaction locks the system
(we've seen this before.) Something to think about...

-- 
Jean Delvare

Re: [PATCH] i2c: Add message transfer tracepoints for I2C and SMBUS

[Jean Delvare]

Hi David,

Please note that I am no longer maintaining the i2c subsystem so you
should have sent this to Wolfram, not me.

On Fri, 13 Dec 2013 14:26:27 +0000, David Howells wrote:
> Add tracepoints into the I2C and SMBUS message transfer functions to retrieve
> the message sent or received.  The following config options must be turned on
> to make use of the facility:
> 
> 	CONFIG_FTRACE
> 	CONFIG_ENABLE_DEFAULT_TRACERS
> 
> The I2C tracepoint can be enabled thusly:
> 
> 	echo 1 >/sys/kernel/debug/tracing/events/i2c/i2c_transfer/enable
> 
> and will dump messages that can be viewed in /sys/kernel/debug/tracing/trace
> that look like:
> 
>         ... i2c_transfer: i2c-5 f=00 a=44 l=6 ret=1 [021433000000]
> 
> formatted as:
> 
> 	i2c-<adapter-nr>
> 	f=<flags>
> 	a=<addr>
> 	l=<datalen>
> 	ret=<result>
> 	[<data>]
> 
> (Bit 0 of the flags is set if this was a read and clear if it was a write).

Wouldn't the traces be more readable if the direction was written
explicitly as R or W?

> 
> 
> The SMBUS tracepoint can be enabled thusly:
> 
> 	echo 1 >/sys/kernel/debug/tracing/events/i2c/smbus_transfer/enable
> 
> and will dump messages that can be viewed in /sys/kernel/debug/tracing/trace
> that look like:
> 
> 	... smbus_transfer: i2c-0 f=00 a=51 r=1 c=0 p=2 res=0 [80ff0100000000000000800c693d0088ffffb83aee3b0088ffff0100000000000000]
> 
> formatted as:
> 
> 	i2c-<adapter-nr>
> 	f=<flags>
> 	a=<addr>
> 	r=<read_write>

Here too I would consider R and W as more readable than r=1 and r=0.

> 	c=<command>
> 	p=<protocol>

Would it be possible to print this as a string rather than a number?
The protocol numbers are completely arbitrary, so the reader would have
to open i2c.h each time to figure out what is what.

> 	res=<result>
> 	[<data-block>]
> 
> 
> In both cases, the adapters to be traced can be selected by something like:
> 
> 	echo adapter_nr==1 >/sys/kernel/debug/tracing/events/i2c/{i2c,smbus}_transfer/filter

I have no objection to the feature, but it should be noted that
i2c-core already offers something similar (albeit less flexible) for
I2C level transfers:

#ifdef DEBUG
		for (ret = 0; ret < num; ret++) {
			dev_dbg(&adap->dev, "master_xfer[%d] %c, addr=0x%02x, "
				"len=%d%s\n", ret, (msgs[ret].flags & I2C_M_RD)
				? 'R' : 'W', msgs[ret].addr, msgs[ret].len,
				(msgs[ret].flags & I2C_M_RECV_LEN) ? "+" : "");
		}
#endif

If your code goes in, I suppose the code above should be removed to
avoid redundancy.

One significant difference between both implementations is that the old
one logs before the actual transfer, while yours logs afterward. While I
understand this allows you to log the result of the transfer, this also
means you'll miss the log if the actual transaction locks the system
(we've seen this before.) Something to think about...

-- 
Jean Delvare

Re: [PATCH] i2c: Add message transfer tracepoints for I2C and SMBUS

[Steven Rostedt]

On Fri, 13 Dec 2013 16:33:49 +0100
Jean Delvare <khali@linux-fr.org> wrote:

> Hi David,
> 
> Please note that I am no longer maintaining the i2c subsystem so you
> should have sent this to Wolfram, not me.
> 
> On Fri, 13 Dec 2013 14:26:27 +0000, David Howells wrote:
> > Add tracepoints into the I2C and SMBUS message transfer functions to retrieve
> > the message sent or received.  The following config options must be turned on
> > to make use of the facility:
> > 
> > 	CONFIG_FTRACE
> > 	CONFIG_ENABLE_DEFAULT_TRACERS
> > 
> > The I2C tracepoint can be enabled thusly:
> > 
> > 	echo 1 >/sys/kernel/debug/tracing/events/i2c/i2c_transfer/enable
> > 
> > and will dump messages that can be viewed in /sys/kernel/debug/tracing/trace
> > that look like:
> > 
> >         ... i2c_transfer: i2c-5 f=00 a=44 l=6 ret=1 [021433000000]
> > 
> > formatted as:
> > 
> > 	i2c-<adapter-nr>
> > 	f=<flags>
> > 	a=<addr>
> > 	l=<datalen>
> > 	ret=<result>
> > 	[<data>]
> > 
> > (Bit 0 of the flags is set if this was a read and clear if it was a write).
> 
> Wouldn't the traces be more readable if the direction was written
> explicitly as R or W?

We can easily do that by adding in the TP_printk()

	".. (%s) ..", ..., __entry->flags & 1 ? "R" : "W", ...

> 
> > 
> > 
> > The SMBUS tracepoint can be enabled thusly:
> > 
> > 	echo 1 >/sys/kernel/debug/tracing/events/i2c/smbus_transfer/enable
> > 
> > and will dump messages that can be viewed in /sys/kernel/debug/tracing/trace
> > that look like:
> > 
> > 	... smbus_transfer: i2c-0 f=00 a=51 r=1 c=0 p=2 res=0 [80ff0100000000000000800c693d0088ffffb83aee3b0088ffff0100000000000000]
> > 
> > formatted as:
> > 
> > 	i2c-<adapter-nr>
> > 	f=<flags>
> > 	a=<addr>
> > 	r=<read_write>
> 
> Here too I would consider R and W as more readable than r=1 and r=0.

Same thing can be done here.

> 
> > 	c=<command>
> > 	p=<protocol>
> 
> Would it be possible to print this as a string rather than a number?
> The protocol numbers are completely arbitrary, so the reader would have
> to open i2c.h each time to figure out what is what.

That can be done in the TP_printk() with:

	".. %s ..", ..,
	__print_symbolic(__entry->protocol,
		{ I2C_SMBUS_QUICK	,	"QUICK"	},
		{ I2C_SMBUS_BYTE	,	"BYTE"	},
		{ I2C_SMBUS_BYTE_DATA	,	"BYTE_DATA" },
		[...]
		{ I2C_SMBUS_I2C_BLOCK_DATA,	"I2C_BLOCK_DATA"}), ...


> 
> > 	res=<result>
> > 	[<data-block>]
> > 
> > 
> > In both cases, the adapters to be traced can be selected by something like:
> > 
> > 	echo adapter_nr==1 >/sys/kernel/debug/tracing/events/i2c/{i2c,smbus}_transfer/filter
> 
> I have no objection to the feature, but it should be noted that
> i2c-core already offers something similar (albeit less flexible) for
> I2C level transfers:
> 
> #ifdef DEBUG
> 		for (ret = 0; ret < num; ret++) {
> 			dev_dbg(&adap->dev, "master_xfer[%d] %c, addr=0x%02x, "
> 				"len=%d%s\n", ret, (msgs[ret].flags & I2C_M_RD)
> 				? 'R' : 'W', msgs[ret].addr, msgs[ret].len,
> 				(msgs[ret].flags & I2C_M_RECV_LEN) ? "+" : "");
> 		}
> #endif
> 
> If your code goes in, I suppose the code above should be removed to
> avoid redundancy.
> 
> One significant difference between both implementations is that the old
> one logs before the actual transfer, while yours logs afterward. While I
> understand this allows you to log the result of the transfer, this also
> means you'll miss the log if the actual transaction locks the system
> (we've seen this before.) Something to think about...
> 

Note, as this is being added to the trace system, one can use function
tracing to see if this is causing the crash. Yeah, you wont be able to
see what the transfer packet was, but you can use kprobes to help there
too.

-- Steve

Re: [PATCH] i2c: Add message transfer tracepoints for I2C and SMBUS

[Steven Rostedt]

On Fri, 13 Dec 2013 16:33:49 +0100
Jean Delvare <khali-PUYAD+kWke1g9hUCZPvPmw@public.gmane.org> wrote:

> Hi David,
> 
> Please note that I am no longer maintaining the i2c subsystem so you
> should have sent this to Wolfram, not me.
> 
> On Fri, 13 Dec 2013 14:26:27 +0000, David Howells wrote:
> > Add tracepoints into the I2C and SMBUS message transfer functions to retrieve
> > the message sent or received.  The following config options must be turned on
> > to make use of the facility:
> > 
> > 	CONFIG_FTRACE
> > 	CONFIG_ENABLE_DEFAULT_TRACERS
> > 
> > The I2C tracepoint can be enabled thusly:
> > 
> > 	echo 1 >/sys/kernel/debug/tracing/events/i2c/i2c_transfer/enable
> > 
> > and will dump messages that can be viewed in /sys/kernel/debug/tracing/trace
> > that look like:
> > 
> >         ... i2c_transfer: i2c-5 f=00 a=44 l=6 ret=1 [021433000000]
> > 
> > formatted as:
> > 
> > 	i2c-<adapter-nr>
> > 	f=<flags>
> > 	a=<addr>
> > 	l=<datalen>
> > 	ret=<result>
> > 	[<data>]
> > 
> > (Bit 0 of the flags is set if this was a read and clear if it was a write).
> 
> Wouldn't the traces be more readable if the direction was written
> explicitly as R or W?

We can easily do that by adding in the TP_printk()

	".. (%s) ..", ..., __entry->flags & 1 ? "R" : "W", ...

> 
> > 
> > 
> > The SMBUS tracepoint can be enabled thusly:
> > 
> > 	echo 1 >/sys/kernel/debug/tracing/events/i2c/smbus_transfer/enable
> > 
> > and will dump messages that can be viewed in /sys/kernel/debug/tracing/trace
> > that look like:
> > 
> > 	... smbus_transfer: i2c-0 f=00 a=51 r=1 c=0 p=2 res=0 [80ff0100000000000000800c693d0088ffffb83aee3b0088ffff0100000000000000]
> > 
> > formatted as:
> > 
> > 	i2c-<adapter-nr>
> > 	f=<flags>
> > 	a=<addr>
> > 	r=<read_write>
> 
> Here too I would consider R and W as more readable than r=1 and r=0.

Same thing can be done here.

> 
> > 	c=<command>
> > 	p=<protocol>
> 
> Would it be possible to print this as a string rather than a number?
> The protocol numbers are completely arbitrary, so the reader would have
> to open i2c.h each time to figure out what is what.

That can be done in the TP_printk() with:

	".. %s ..", ..,
	__print_symbolic(__entry->protocol,
		{ I2C_SMBUS_QUICK	,	"QUICK"	},
		{ I2C_SMBUS_BYTE	,	"BYTE"	},
		{ I2C_SMBUS_BYTE_DATA	,	"BYTE_DATA" },
		[...]
		{ I2C_SMBUS_I2C_BLOCK_DATA,	"I2C_BLOCK_DATA"}), ...


> 
> > 	res=<result>
> > 	[<data-block>]
> > 
> > 
> > In both cases, the adapters to be traced can be selected by something like:
> > 
> > 	echo adapter_nr==1 >/sys/kernel/debug/tracing/events/i2c/{i2c,smbus}_transfer/filter
> 
> I have no objection to the feature, but it should be noted that
> i2c-core already offers something similar (albeit less flexible) for
> I2C level transfers:
> 
> #ifdef DEBUG
> 		for (ret = 0; ret < num; ret++) {
> 			dev_dbg(&adap->dev, "master_xfer[%d] %c, addr=0x%02x, "
> 				"len=%d%s\n", ret, (msgs[ret].flags & I2C_M_RD)
> 				? 'R' : 'W', msgs[ret].addr, msgs[ret].len,
> 				(msgs[ret].flags & I2C_M_RECV_LEN) ? "+" : "");
> 		}
> #endif
> 
> If your code goes in, I suppose the code above should be removed to
> avoid redundancy.
> 
> One significant difference between both implementations is that the old
> one logs before the actual transfer, while yours logs afterward. While I
> understand this allows you to log the result of the transfer, this also
> means you'll miss the log if the actual transaction locks the system
> (we've seen this before.) Something to think about...
> 

Note, as this is being added to the trace system, one can use function
tracing to see if this is causing the crash. Yeah, you wont be able to
see what the transfer packet was, but you can use kprobes to help there
too.

-- Steve

Re: [PATCH] i2c: Add message transfer tracepoints for I2C and SMBUS

[David Howells]

Jean Delvare <khali@linux-fr.org> wrote:

> One significant difference between both implementations is that the old
> one logs before the actual transfer, while yours logs afterward. While I
> understand this allows you to log the result of the transfer, this also
> means you'll miss the log if the actual transaction locks the system
> (we've seen this before.) Something to think about...

I could split each into three messages:

	- Write request (has params & data buffer)
	- Read request (has params but no data buffer)
	- Read reply (has data buffer only)

It will make the transfer functions more complex, though, and will mean that,
for i2c, you won't get all the replies to the messages in a batch in with the
requests.  I can also label the messages with the index number.  Mostly I
suspect this won't be a problem.

David

Re: [PATCH] i2c: Add message transfer tracepoints for I2C and SMBUS

[David Howells]

Jean Delvare <khali-PUYAD+kWke1g9hUCZPvPmw@public.gmane.org> wrote:

> One significant difference between both implementations is that the old
> one logs before the actual transfer, while yours logs afterward. While I
> understand this allows you to log the result of the transfer, this also
> means you'll miss the log if the actual transaction locks the system
> (we've seen this before.) Something to think about...

I could split each into three messages:

	- Write request (has params & data buffer)
	- Read request (has params but no data buffer)
	- Read reply (has data buffer only)

It will make the transfer functions more complex, though, and will mean that,
for i2c, you won't get all the replies to the messages in a batch in with the
requests.  I can also label the messages with the index number.  Mostly I
suspect this won't be a problem.

David

Re: [PATCH] i2c: Add message transfer tracepoints for I2C and SMBUS

[Jean Delvare]

On Fri, 13 Dec 2013 16:05:36 +0000, David Howells wrote:
> Jean Delvare <khali@linux-fr.org> wrote:
> 
> > One significant difference between both implementations is that the old
> > one logs before the actual transfer, while yours logs afterward. While I
> > understand this allows you to log the result of the transfer, this also
> > means you'll miss the log if the actual transaction locks the system
> > (we've seen this before.) Something to think about...
> 
> I could split each into three messages:
> 
> 	- Write request (has params & data buffer)
> 	- Read request (has params but no data buffer)
> 	- Read reply (has data buffer only)
> 
> It will make the transfer functions more complex, though, and will mean that,
> for i2c, you won't get all the replies to the messages in a batch in with the
> requests.  I can also label the messages with the index number.  Mostly I
> suspect this won't be a problem.

Fine with me, we can leave it as is and revisit if it ever is a
problem in practice.

-- 
Jean Delvare

Re: [PATCH] i2c: Add message transfer tracepoints for I2C and SMBUS

[David Howells]

Steven Rostedt <rostedt@goodmis.org> wrote:

> > Would it be possible to print this as a string rather than a number?
> > The protocol numbers are completely arbitrary, so the reader would have
> > to open i2c.h each time to figure out what is what.
> 
> That can be done in the TP_printk() with:
> 
> 	".. %s ..", ..,
> 	__print_symbolic(__entry->protocol,
> 		{ I2C_SMBUS_QUICK	,	"QUICK"	},
> 		{ I2C_SMBUS_BYTE	,	"BYTE"	},
> 		{ I2C_SMBUS_BYTE_DATA	,	"BYTE_DATA" },
> 		[...]
> 		{ I2C_SMBUS_I2C_BLOCK_DATA,	"I2C_BLOCK_DATA"}), ...

What happens if the number isn't in the table?

David

Re: [PATCH] i2c: Add message transfer tracepoints for I2C and SMBUS

[David Howells]

Steven Rostedt <rostedt-nx8X9YLhiw1AfugRpC6u6w@public.gmane.org> wrote:

> > Would it be possible to print this as a string rather than a number?
> > The protocol numbers are completely arbitrary, so the reader would have
> > to open i2c.h each time to figure out what is what.
> 
> That can be done in the TP_printk() with:
> 
> 	".. %s ..", ..,
> 	__print_symbolic(__entry->protocol,
> 		{ I2C_SMBUS_QUICK	,	"QUICK"	},
> 		{ I2C_SMBUS_BYTE	,	"BYTE"	},
> 		{ I2C_SMBUS_BYTE_DATA	,	"BYTE_DATA" },
> 		[...]
> 		{ I2C_SMBUS_I2C_BLOCK_DATA,	"I2C_BLOCK_DATA"}), ...

What happens if the number isn't in the table?

David

Re: [PATCH] i2c: Add message transfer tracepoints for I2C and SMBUS

[David Howells]

Here's a tentative patch on top of the previous one to split the messages.  I
haven't tested the I2C side yet and cannot test the SMBUS write.

Each is split four ways:

  (1) i2c/smbus_write - Show write request before submitting

  (2) i2c/smbus_read - Show read request before submitting

  (3) i2c/smbus_reply - Show read reply after submitting (if no failure)

  (4) i2c/smbus_result - Show operation result

So this might give you something like:
 
	... i2c_write: i2c-5 #0 f=00 a=44 l=2 [0800]
	... i2c_read: i2c-5 #1 f=01 a=44 l=1
	... i2c_reply: i2c-5 #1 f=01 a=44 l=1 [fe]
	... i2c_result: n=2 ret=2

from a single __i2c_transfer() given an array of two messages.

Or:

        ... smbus_read: i2c-0 a=51 f=00 c=fc BYTE_DATA
        ... smbus_reply: i2c-0 a=51 f=00 c=fc BYTE_DATA [41ff01000...]
        ... smbus_result: i2c-0 a=51 f=00 c=fc BYTE_DATA rd res=0

from a single i2c_smbus_xfer().

David
---
commit 31d5367657a64453d48b89b09296f7ebc6a5ee94
Author: David Howells <dhowells@redhat.com>
Date:   Fri Dec 13 17:13:19 2013 +0000

    i2c: Split traces

diff --git a/drivers/i2c/i2c-core.c b/drivers/i2c/i2c-core.c
index 2128e106ca97..0dbf0dcff6ce 100644
--- a/drivers/i2c/i2c-core.c
+++ b/drivers/i2c/i2c-core.c
@@ -1726,6 +1726,19 @@ int __i2c_transfer(struct i2c_adapter *adap, struct i2c_msg *msgs, int num)
 	unsigned long orig_jiffies;
 	int ret, try;
 
+	/* i2c_trace_msg gets enabled when tracepoint i2c_transfer gets
+	 * enabled.  This is an efficient way of keeping the for-loop from
+	 * being executed when not needed.
+	 */
+	if (static_key_false(&i2c_trace_msg)) {
+		int i;
+		for (i = 0; i < num; i++)
+			if (msgs[i].flags & I2C_M_RD)
+				trace_i2c_read(adap, &msgs[i], i);
+			else
+				trace_i2c_write(adap, &msgs[i], i);
+	}
+
 	/* Retry automatically on arbitration loss */
 	orig_jiffies = jiffies;
 	for (ret = 0, try = 0; try <= adap->retries; try++) {
@@ -1736,14 +1749,12 @@ int __i2c_transfer(struct i2c_adapter *adap, struct i2c_msg *msgs, int num)
 			break;
 	}
 
-	/* i2c_trace_msg gets enabled when tracepoint i2c_transfer gets
-	 * enabled.  This is an efficient way of keeping the for-loop from
-	 * being executed when not needed.
-	 */
 	if (static_key_false(&i2c_trace_msg)) {
 		int i;
-		for (i = 0; i < num; i++)
-			trace_i2c_transfer(adap, &msgs[i], ret);
+		for (i = 0; i < ret; i++)
+			if (msgs[i].flags & I2C_M_RD)
+				trace_i2c_reply(adap, &msgs[i], i);
+		trace_i2c_result(adap, i, ret);
 	}
 
 	return ret;
@@ -2541,6 +2552,11 @@ s32 i2c_smbus_xfer(struct i2c_adapter *adapter, u16 addr, unsigned short flags,
 	int try;
 	s32 res;
 
+	if (read_write == I2C_SMBUS_WRITE)
+		trace_smbus_write(adapter, addr, flags, command, protocol, data);
+	else
+		trace_smbus_read(adapter, addr, flags, command, protocol);
+
 	flags &= I2C_M_TEN | I2C_CLIENT_PEC | I2C_CLIENT_SCCB;
 
 	if (adapter->algo->smbus_xfer) {
@@ -2572,8 +2588,11 @@ s32 i2c_smbus_xfer(struct i2c_adapter *adapter, u16 addr, unsigned short flags,
 				      command, protocol, data);
 
 trace:
-	trace_smbus_transfer(adapter, addr, flags, read_write,
-			     command, protocol, data, res);
+	if (read_write == I2C_SMBUS_READ)
+		trace_smbus_reply(adapter, addr, flags,
+				  command, protocol, data);
+	trace_smbus_result(adapter, addr, flags, read_write,
+			   command, protocol, res);
 
 	return res;
 }
diff --git a/include/trace/events/i2c.h b/include/trace/events/i2c.h
index ed366e145c8d..ca19f4948290 100644
--- a/include/trace/events/i2c.h
+++ b/include/trace/events/i2c.h
@@ -23,42 +23,259 @@
 extern void i2c_transfer_trace_reg(void);
 extern void i2c_transfer_trace_unreg(void);
 
-TRACE_EVENT_FN(i2c_transfer,
+/*
+ * __i2c_transfer() write request
+ */
+TRACE_EVENT_FN(i2c_write,
 	       TP_PROTO(const struct i2c_adapter *adap, const struct i2c_msg *msg,
-			int ret),
-	       TP_ARGS(adap, msg, ret),
+			int num),
+	       TP_ARGS(adap, msg, num),
 	       TP_STRUCT__entry(
-		       __field(	int,	adapter_nr		)
+		       __field(int,	adapter_nr		)
+		       __field(__u16,	msg_nr			)
 		       __field(__u16,	addr			)
 		       __field(__u16,	flags			)
 		       __field(__u16,	len			)
-		       __field(__s16,	ret			)
 		       __dynamic_array(__u8, buf, msg->len)	),
 	       TP_fast_assign(
 		       __entry->adapter_nr = adap->nr;
+		       __entry->msg_nr = num;
+		       __entry->addr = msg->addr;
+		       __entry->flags = msg->flags;
+		       __entry->len = msg->len;
+		       memcpy(__get_dynamic_array(buf), msg->buf, msg->len);
+			      ),
+	       TP_printk("i2c-%d #%u f=%02x a=%02x l=%u [%*phN]",
+			 __entry->adapter_nr,
+			 __entry->msg_nr,
+			 __entry->flags,
+			 __entry->addr,
+			 __entry->len,
+			 __entry->len, __get_dynamic_array(buf)
+			 ),
+	       i2c_transfer_trace_reg,
+	       i2c_transfer_trace_unreg);
+
+/*
+ * __i2c_transfer() read request
+ */
+TRACE_EVENT_FN(i2c_read,
+	       TP_PROTO(const struct i2c_adapter *adap, const struct i2c_msg *msg,
+			int num),
+	       TP_ARGS(adap, msg, num),
+	       TP_STRUCT__entry(
+		       __field(int,	adapter_nr		)
+		       __field(__u16,	msg_nr			)
+		       __field(__u16,	addr			)
+		       __field(__u16,	flags			)
+		       __field(__u16,	len			)
+				),
+	       TP_fast_assign(
+		       __entry->adapter_nr = adap->nr;
+		       __entry->msg_nr = num;
+		       __entry->addr = msg->addr;
+		       __entry->flags = msg->flags;
+		       __entry->len = msg->len;
+			      ),
+	       TP_printk("i2c-%d #%u f=%02x a=%02x l=%u",
+			 __entry->adapter_nr,
+			 __entry->msg_nr,
+			 __entry->flags,
+			 __entry->addr,
+			 __entry->len
+			 ),
+	       i2c_transfer_trace_reg,
+		       i2c_transfer_trace_unreg);
+
+/*
+ * __i2c_transfer() read reply
+ */
+TRACE_EVENT_FN(i2c_reply,
+	       TP_PROTO(const struct i2c_adapter *adap, const struct i2c_msg *msg,
+			int num),
+	       TP_ARGS(adap, msg, num),
+	       TP_STRUCT__entry(
+		       __field(int,	adapter_nr		)
+		       __field(__u16,	msg_nr			)
+		       __field(__u16,	addr			)
+		       __field(__u16,	flags			)
+		       __field(__u16,	len			)
+		       __dynamic_array(__u8, buf, msg->len)	),
+	       TP_fast_assign(
+		       __entry->adapter_nr = adap->nr;
+		       __entry->msg_nr = num;
 		       __entry->addr = msg->addr;
 		       __entry->flags = msg->flags;
 		       __entry->len = msg->len;
-		       __entry->ret = ret;
 		       memcpy(__get_dynamic_array(buf), msg->buf, msg->len);
 			      ),
-	       TP_printk("i2c-%d f=%02x a=%02x l=%u ret=%d [%*phN]",
+	       TP_printk("i2c-%d #%u f=%02x a=%02x l=%u [%*phN]",
 			 __entry->adapter_nr,
+			 __entry->msg_nr,
 			 __entry->flags,
 			 __entry->addr,
 			 __entry->len,
-			 __entry->ret,
 			 __entry->len, __get_dynamic_array(buf)
 			 ),
 	       i2c_transfer_trace_reg,
 	       i2c_transfer_trace_unreg);
 
-TRACE_EVENT(smbus_transfer,
+/*
+ * __i2c_transfer() result
+ */
+TRACE_EVENT_FN(i2c_result,
+	       TP_PROTO(const struct i2c_adapter *adap, int num, int ret),
+	       TP_ARGS(adap, num, ret),
+	       TP_STRUCT__entry(
+		       __field(int,	adapter_nr		)
+		       __field(__u16,	nr_msgs			)
+		       __field(__s16,	ret			)
+				),
+	       TP_fast_assign(
+		       __entry->adapter_nr = adap->nr;
+		       __entry->nr_msgs = num;
+		       __entry->ret = ret;
+			      ),
+	       TP_printk("i2c-%d n=%u ret=%d",
+			 __entry->adapter_nr,
+			 __entry->nr_msgs,
+			 __entry->ret
+			 ),
+	       i2c_transfer_trace_reg,
+	       i2c_transfer_trace_unreg);
+
+/*
+ * i2c_smbus_xfer() write request
+ */
+TRACE_EVENT(smbus_write,
+	    TP_PROTO(const struct i2c_adapter *adap,
+		     u16 addr, unsigned short flags,
+		     u8 command, int protocol,
+		     const union i2c_smbus_data *data),
+	    TP_ARGS(adap, addr, flags, command, protocol, data),
+	    TP_STRUCT__entry(
+		    __field(int,	adapter_nr		)
+		    __field(__u16,	addr			)
+		    __field(__u16,	flags			)
+		    __field(__u8,	command			)
+		    __field(__u32,	protocol		)
+		    __array(__u8, buf, I2C_SMBUS_BLOCK_MAX + 2)	),
+	    TP_fast_assign(
+		    __entry->adapter_nr = adap->nr;
+		    __entry->addr = addr;
+		    __entry->flags = flags;
+		    __entry->command = command;
+		    __entry->protocol = protocol;
+		    memcpy(__entry->buf, data->block, I2C_SMBUS_BLOCK_MAX + 2);
+			   ),
+	    TP_printk("i2c-%d a=%02x f=%02x c=%x %s [%*phN]",
+		      __entry->adapter_nr,
+		      __entry->addr,
+		      __entry->flags,
+		      __entry->command,
+		      __print_symbolic(__entry->protocol,
+				       { I2C_SMBUS_QUICK,		"QUICK"	},
+				       { I2C_SMBUS_BYTE,		"BYTE"	},
+				       { I2C_SMBUS_BYTE_DATA,		"BYTE_DATA" },
+				       { I2C_SMBUS_WORD_DATA,		"WORD_DATA" },
+				       { I2C_SMBUS_PROC_CALL,		"PROC_CALL" },
+				       { I2C_SMBUS_BLOCK_DATA,		"BLOCK_DATA" },
+				       { I2C_SMBUS_I2C_BLOCK_BROKEN,	"I2C_BLOCK_BROKEN" },
+				       { I2C_SMBUS_BLOCK_PROC_CALL,	"BLOCK_PROC_CALL" },
+				       { I2C_SMBUS_I2C_BLOCK_DATA,	"I2C_BLOCK_DATA" }),
+		      I2C_SMBUS_BLOCK_MAX + 2, __entry->buf
+		      ));
+
+/*
+ * i2c_smbus_xfer() read request
+ */
+TRACE_EVENT(smbus_read,
+	    TP_PROTO(const struct i2c_adapter *adap,
+		     u16 addr, unsigned short flags,
+		     u8 command, int protocol),
+	    TP_ARGS(adap, addr, flags, command, protocol),
+	    TP_STRUCT__entry(
+		    __field(int,	adapter_nr		)
+		    __field(__u16,	addr			)
+		    __field(__u16,	flags			)
+		    __field(__u8,	command			)
+		    __field(__u32,	protocol		)
+		    __array(__u8, buf, I2C_SMBUS_BLOCK_MAX + 2)	),
+	    TP_fast_assign(
+		    __entry->adapter_nr = adap->nr;
+		    __entry->addr = addr;
+		    __entry->flags = flags;
+		    __entry->command = command;
+		    __entry->protocol = protocol;
+			   ),
+	    TP_printk("i2c-%d a=%02x f=%02x c=%x %s",
+		      __entry->adapter_nr,
+		      __entry->addr,
+		      __entry->flags,
+		      __entry->command,
+		      __print_symbolic(__entry->protocol,
+				       { I2C_SMBUS_QUICK,		"QUICK"	},
+				       { I2C_SMBUS_BYTE,		"BYTE"	},
+				       { I2C_SMBUS_BYTE_DATA,		"BYTE_DATA" },
+				       { I2C_SMBUS_WORD_DATA,		"WORD_DATA" },
+				       { I2C_SMBUS_PROC_CALL,		"PROC_CALL" },
+				       { I2C_SMBUS_BLOCK_DATA,		"BLOCK_DATA" },
+				       { I2C_SMBUS_I2C_BLOCK_BROKEN,	"I2C_BLOCK_BROKEN" },
+				       { I2C_SMBUS_BLOCK_PROC_CALL,	"BLOCK_PROC_CALL" },
+				       { I2C_SMBUS_I2C_BLOCK_DATA,	"I2C_BLOCK_DATA" })
+		      ));
+
+/*
+ * i2c_smbus_xfer() read reply
+ */
+TRACE_EVENT(smbus_reply,
+	    TP_PROTO(const struct i2c_adapter *adap,
+		     u16 addr, unsigned short flags,
+		     u8 command, int protocol,
+		     const union i2c_smbus_data *data),
+	    TP_ARGS(adap, addr, flags, command, protocol, data),
+	    TP_STRUCT__entry(
+		    __field(int,	adapter_nr		)
+		    __field(__u16,	addr			)
+		    __field(__u16,	flags			)
+		    __field(__u8,	command			)
+		    __field(__u32,	protocol		)
+		    __array(__u8, buf, I2C_SMBUS_BLOCK_MAX + 2)	),
+	    TP_fast_assign(
+		    __entry->adapter_nr = adap->nr;
+		    __entry->addr = addr;
+		    __entry->flags = flags;
+		    __entry->command = command;
+		    __entry->protocol = protocol;
+		    memcpy(__entry->buf, data->block, I2C_SMBUS_BLOCK_MAX + 2);
+			   ),
+	    TP_printk("i2c-%d a=%02x f=%02x c=%x %s [%*phN]",
+		      __entry->adapter_nr,
+		      __entry->addr,
+		      __entry->flags,
+		      __entry->command,
+		      __print_symbolic(__entry->protocol,
+				       { I2C_SMBUS_QUICK,		"QUICK"	},
+				       { I2C_SMBUS_BYTE,		"BYTE"	},
+				       { I2C_SMBUS_BYTE_DATA,		"BYTE_DATA" },
+				       { I2C_SMBUS_WORD_DATA,		"WORD_DATA" },
+				       { I2C_SMBUS_PROC_CALL,		"PROC_CALL" },
+				       { I2C_SMBUS_BLOCK_DATA,		"BLOCK_DATA" },
+				       { I2C_SMBUS_I2C_BLOCK_BROKEN,	"I2C_BLOCK_BROKEN" },
+				       { I2C_SMBUS_BLOCK_PROC_CALL,	"BLOCK_PROC_CALL" },
+				       { I2C_SMBUS_I2C_BLOCK_DATA,	"I2C_BLOCK_DATA" }),
+		      I2C_SMBUS_BLOCK_MAX + 2, __entry->buf
+		      ));
+
+/*
+ * i2c_smbus_xfer() result
+ */
+TRACE_EVENT(smbus_result,
 	    TP_PROTO(const struct i2c_adapter *adap,
 		     u16 addr, unsigned short flags,
 		     char read_write, u8 command, int protocol,
-		     const union i2c_smbus_data *data, int res),
-	    TP_ARGS(adap, addr, flags, read_write, command, protocol, data, res),
+		     int res),
+	    TP_ARGS(adap, addr, flags, read_write, command, protocol, res),
 	    TP_STRUCT__entry(
 		    __field(int,	adapter_nr		)
 		    __field(__u16,	addr			)
@@ -67,7 +284,7 @@ TRACE_EVENT(smbus_transfer,
 		    __field(__u8,	command			)
 		    __field(__s16,	res			)
 		    __field(__u32,	protocol		)
-		    __array(__u8, buf, I2C_SMBUS_BLOCK_MAX + 2)	),
+			     ),
 	    TP_fast_assign(
 		    __entry->adapter_nr = adap->nr;
 		    __entry->addr = addr;
@@ -76,17 +293,24 @@ TRACE_EVENT(smbus_transfer,
 		    __entry->command = command;
 		    __entry->protocol = protocol;
 		    __entry->res = res;
-		    memcpy(__entry->buf, data->block, I2C_SMBUS_BLOCK_MAX + 2);
 			   ),
-	    TP_printk("i2c-%d f=%02x a=%02x r=%x c=%x p=%x res=%d [%*phN]",
+	    TP_printk("i2c-%d a=%02x f=%02x c=%x %s %s res=%d",
 		      __entry->adapter_nr,
-		      __entry->flags,
 		      __entry->addr,
-		      __entry->read_write,
+		      __entry->flags,
 		      __entry->command,
-		      __entry->protocol,
-		      __entry->res,
-		      I2C_SMBUS_BLOCK_MAX + 2, __entry->buf
+		      __print_symbolic(__entry->protocol,
+				       { I2C_SMBUS_QUICK,		"QUICK"	},
+				       { I2C_SMBUS_BYTE,		"BYTE"	},
+				       { I2C_SMBUS_BYTE_DATA,		"BYTE_DATA" },
+				       { I2C_SMBUS_WORD_DATA,		"WORD_DATA" },
+				       { I2C_SMBUS_PROC_CALL,		"PROC_CALL" },
+				       { I2C_SMBUS_BLOCK_DATA,		"BLOCK_DATA" },
+				       { I2C_SMBUS_I2C_BLOCK_BROKEN,	"I2C_BLOCK_BROKEN" },
+				       { I2C_SMBUS_BLOCK_PROC_CALL,	"BLOCK_PROC_CALL" },
+				       { I2C_SMBUS_I2C_BLOCK_DATA,	"I2C_BLOCK_DATA" }),
+		      __entry->read_write == I2C_SMBUS_WRITE ? "wr" : "rd",
+		      __entry->res
 		      ));
 
 #endif /* _TRACE_I2C_H */

Re: [PATCH] i2c: Add message transfer tracepoints for I2C and SMBUS

[Steven Rostedt]

On Fri, 13 Dec 2013 17:04:14 +0000
David Howells <dhowells@redhat.com> wrote:

> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > > Would it be possible to print this as a string rather than a number?
> > > The protocol numbers are completely arbitrary, so the reader would have
> > > to open i2c.h each time to figure out what is what.
> > 
> > That can be done in the TP_printk() with:
> > 
> > 	".. %s ..", ..,
> > 	__print_symbolic(__entry->protocol,
> > 		{ I2C_SMBUS_QUICK	,	"QUICK"	},
> > 		{ I2C_SMBUS_BYTE	,	"BYTE"	},
> > 		{ I2C_SMBUS_BYTE_DATA	,	"BYTE_DATA" },
> > 		[...]
> > 		{ I2C_SMBUS_I2C_BLOCK_DATA,	"I2C_BLOCK_DATA"}), ...
> 
> What happens if the number isn't in the table?

It simply prints the hex value. See trace_output.c:

const char *
ftrace_print_symbols_seq(struct trace_seq *p, unsigned long val,
			 const struct trace_print_flags *symbol_array)
{
	int i;
	const char *ret = p->buffer + p->len;

	for (i = 0;  symbol_array[i].name; i++) {

		if (val != symbol_array[i].mask)
			continue;

		trace_seq_puts(p, symbol_array[i].name);
		break;
	}

	if (ret == (const char *)(p->buffer + p->len))
		trace_seq_printf(p, "0x%lx", val);
		
	trace_seq_putc(p, 0);

	return ret;
}

-- Steve

Re: [PATCH] i2c: Add message transfer tracepoints for I2C and SMBUS

[Steven Rostedt]

On Fri, 13 Dec 2013 17:04:14 +0000
David Howells <dhowells-H+wXaHxf7aLQT0dZR+AlfA@public.gmane.org> wrote:

> Steven Rostedt <rostedt-nx8X9YLhiw1AfugRpC6u6w@public.gmane.org> wrote:
> 
> > > Would it be possible to print this as a string rather than a number?
> > > The protocol numbers are completely arbitrary, so the reader would have
> > > to open i2c.h each time to figure out what is what.
> > 
> > That can be done in the TP_printk() with:
> > 
> > 	".. %s ..", ..,
> > 	__print_symbolic(__entry->protocol,
> > 		{ I2C_SMBUS_QUICK	,	"QUICK"	},
> > 		{ I2C_SMBUS_BYTE	,	"BYTE"	},
> > 		{ I2C_SMBUS_BYTE_DATA	,	"BYTE_DATA" },
> > 		[...]
> > 		{ I2C_SMBUS_I2C_BLOCK_DATA,	"I2C_BLOCK_DATA"}), ...
> 
> What happens if the number isn't in the table?

It simply prints the hex value. See trace_output.c:

const char *
ftrace_print_symbols_seq(struct trace_seq *p, unsigned long val,
			 const struct trace_print_flags *symbol_array)
{
	int i;
	const char *ret = p->buffer + p->len;

	for (i = 0;  symbol_array[i].name; i++) {

		if (val != symbol_array[i].mask)
			continue;

		trace_seq_puts(p, symbol_array[i].name);
		break;
	}

	if (ret == (const char *)(p->buffer + p->len))
		trace_seq_printf(p, "0x%lx", val);
		
	trace_seq_putc(p, 0);

	return ret;
}

-- Steve

Re: [PATCH] i2c: Add message transfer tracepoints for I2C and SMBUS

[Steven Rostedt]

On Fri, 13 Dec 2013 17:26:53 +0000
David Howells <dhowells@redhat.com> wrote:

> index ed366e145c8d..ca19f4948290 100644
> --- a/include/trace/events/i2c.h
> +++ b/include/trace/events/i2c.h
> @@ -23,42 +23,259 @@
>  extern void i2c_transfer_trace_reg(void);
>  extern void i2c_transfer_trace_unreg(void);
>  
> -TRACE_EVENT_FN(i2c_transfer,
> +/*
> + * __i2c_transfer() write request
> + */
> +TRACE_EVENT_FN(i2c_write,
>  	       TP_PROTO(const struct i2c_adapter *adap, const struct i2c_msg *msg,
> -			int ret),
> -	       TP_ARGS(adap, msg, ret),
> +			int num),
> +	       TP_ARGS(adap, msg, num),
>  	       TP_STRUCT__entry(
> -		       __field(	int,	adapter_nr		)
> +		       __field(int,	adapter_nr		)
> +		       __field(__u16,	msg_nr			)
>  		       __field(__u16,	addr			)
>  		       __field(__u16,	flags			)
>  		       __field(__u16,	len			)
> -		       __field(__s16,	ret			)
>  		       __dynamic_array(__u8, buf, msg->len)	),
>  	       TP_fast_assign(
>  		       __entry->adapter_nr = adap->nr;
> +		       __entry->msg_nr = num;
> +		       __entry->addr = msg->addr;
> +		       __entry->flags = msg->flags;
> +		       __entry->len = msg->len;
> +		       memcpy(__get_dynamic_array(buf), msg->buf, msg->len);
> +			      ),
> +	       TP_printk("i2c-%d #%u f=%02x a=%02x l=%u [%*phN]",
> +			 __entry->adapter_nr,
> +			 __entry->msg_nr,
> +			 __entry->flags,
> +			 __entry->addr,
> +			 __entry->len,
> +			 __entry->len, __get_dynamic_array(buf)
> +			 ),
> +	       i2c_transfer_trace_reg,
> +	       i2c_transfer_trace_unreg);
> +
> +/*
> + * __i2c_transfer() read request
> + */
> +TRACE_EVENT_FN(i2c_read,
> +	       TP_PROTO(const struct i2c_adapter *adap, const struct i2c_msg *msg,
> +			int num),
> +	       TP_ARGS(adap, msg, num),
> +	       TP_STRUCT__entry(
> +		       __field(int,	adapter_nr		)
> +		       __field(__u16,	msg_nr			)
> +		       __field(__u16,	addr			)
> +		       __field(__u16,	flags			)
> +		       __field(__u16,	len			)
> +				),
> +	       TP_fast_assign(
> +		       __entry->adapter_nr = adap->nr;
> +		       __entry->msg_nr = num;
> +		       __entry->addr = msg->addr;
> +		       __entry->flags = msg->flags;
> +		       __entry->len = msg->len;
> +			      ),
> +	       TP_printk("i2c-%d #%u f=%02x a=%02x l=%u",
> +			 __entry->adapter_nr,
> +			 __entry->msg_nr,
> +			 __entry->flags,
> +			 __entry->addr,
> +			 __entry->len
> +			 ),
> +	       i2c_transfer_trace_reg,
> +		       i2c_transfer_trace_unreg);
> +

Now that you have two tracepoints that are identical, you can use
DECLARE_EVENT_CLASS() and DEFINE_EVENT_FN(). That is:

DECLARE_EVENT_CLASS(i2c_read_write,
	       TP_PROTO(const struct i2c_adapter *adap, const struct i2c_msg *msg,
			int num),
	       TP_ARGS(adap, msg, num),
	       TP_STRUCT__entry(
		       __field(int,	adapter_nr		)
	               __field(__u16,   msg_nr			)
                       __field(__u16,   addr			)
                       __field(__u16,   flags			)
                       __field(__u16,   len			)),
	       TP_fast_assign(
		       __entry->adapter_nr = adap->nr;
		       __entry->msg_nr = num;
		       __entry->addr = msg->addr;
		       __entry->flags = msg->flags;
		       __entry->len = msg->len;
			      ),
	       TP_printk("i2c-%d #%u f=%02x a=%02x l=%u",
			 __entry->adapter_nr,
			 __entry->msg_nr,
			 __entry->flags,
			 __entry->addr,
			 __entry->len
			 )
		);

DEFINE_EVENT_FN(i2c_read_write, i2c_read,
	       TP_PROTO(const struct i2c_adapter *adap, const struct i2c_ msg *msg,
			int num),
	       TP_ARGS(adap, msg, num),
	       i2c_transfer_trace_reg,
	       i2c_transfer_trace_unreg);

DEFINE_EVENT_FN(i2c_read_write, i2c_write,
	       TP_PROTO(const struct i2c_adapter *adap, const struct i2c_ msg *msg,
			int num),
	       TP_ARGS(adap, msg, num),
	       i2c_transfer_trace_reg,
	       i2c_transfer_trace_unreg);

This will reduce duplication of code by several kilobytes.


-- Steve

Re: [PATCH] i2c: Add message transfer tracepoints for I2C and SMBUS

[Steven Rostedt]

On Fri, 13 Dec 2013 17:26:53 +0000
David Howells <dhowells-H+wXaHxf7aLQT0dZR+AlfA@public.gmane.org> wrote:

> index ed366e145c8d..ca19f4948290 100644
> --- a/include/trace/events/i2c.h
> +++ b/include/trace/events/i2c.h
> @@ -23,42 +23,259 @@
>  extern void i2c_transfer_trace_reg(void);
>  extern void i2c_transfer_trace_unreg(void);
>  
> -TRACE_EVENT_FN(i2c_transfer,
> +/*
> + * __i2c_transfer() write request
> + */
> +TRACE_EVENT_FN(i2c_write,
>  	       TP_PROTO(const struct i2c_adapter *adap, const struct i2c_msg *msg,
> -			int ret),
> -	       TP_ARGS(adap, msg, ret),
> +			int num),
> +	       TP_ARGS(adap, msg, num),
>  	       TP_STRUCT__entry(
> -		       __field(	int,	adapter_nr		)
> +		       __field(int,	adapter_nr		)
> +		       __field(__u16,	msg_nr			)
>  		       __field(__u16,	addr			)
>  		       __field(__u16,	flags			)
>  		       __field(__u16,	len			)
> -		       __field(__s16,	ret			)
>  		       __dynamic_array(__u8, buf, msg->len)	),
>  	       TP_fast_assign(
>  		       __entry->adapter_nr = adap->nr;
> +		       __entry->msg_nr = num;
> +		       __entry->addr = msg->addr;
> +		       __entry->flags = msg->flags;
> +		       __entry->len = msg->len;
> +		       memcpy(__get_dynamic_array(buf), msg->buf, msg->len);
> +			      ),
> +	       TP_printk("i2c-%d #%u f=%02x a=%02x l=%u [%*phN]",
> +			 __entry->adapter_nr,
> +			 __entry->msg_nr,
> +			 __entry->flags,
> +			 __entry->addr,
> +			 __entry->len,
> +			 __entry->len, __get_dynamic_array(buf)
> +			 ),
> +	       i2c_transfer_trace_reg,
> +	       i2c_transfer_trace_unreg);
> +
> +/*
> + * __i2c_transfer() read request
> + */
> +TRACE_EVENT_FN(i2c_read,
> +	       TP_PROTO(const struct i2c_adapter *adap, const struct i2c_msg *msg,
> +			int num),
> +	       TP_ARGS(adap, msg, num),
> +	       TP_STRUCT__entry(
> +		       __field(int,	adapter_nr		)
> +		       __field(__u16,	msg_nr			)
> +		       __field(__u16,	addr			)
> +		       __field(__u16,	flags			)
> +		       __field(__u16,	len			)
> +				),
> +	       TP_fast_assign(
> +		       __entry->adapter_nr = adap->nr;
> +		       __entry->msg_nr = num;
> +		       __entry->addr = msg->addr;
> +		       __entry->flags = msg->flags;
> +		       __entry->len = msg->len;
> +			      ),
> +	       TP_printk("i2c-%d #%u f=%02x a=%02x l=%u",
> +			 __entry->adapter_nr,
> +			 __entry->msg_nr,
> +			 __entry->flags,
> +			 __entry->addr,
> +			 __entry->len
> +			 ),
> +	       i2c_transfer_trace_reg,
> +		       i2c_transfer_trace_unreg);
> +

Now that you have two tracepoints that are identical, you can use
DECLARE_EVENT_CLASS() and DEFINE_EVENT_FN(). That is:

DECLARE_EVENT_CLASS(i2c_read_write,
	       TP_PROTO(const struct i2c_adapter *adap, const struct i2c_msg *msg,
			int num),
	       TP_ARGS(adap, msg, num),
	       TP_STRUCT__entry(
		       __field(int,	adapter_nr		)
	               __field(__u16,   msg_nr			)
                       __field(__u16,   addr			)
                       __field(__u16,   flags			)
                       __field(__u16,   len			)),
	       TP_fast_assign(
		       __entry->adapter_nr = adap->nr;
		       __entry->msg_nr = num;
		       __entry->addr = msg->addr;
		       __entry->flags = msg->flags;
		       __entry->len = msg->len;
			      ),
	       TP_printk("i2c-%d #%u f=%02x a=%02x l=%u",
			 __entry->adapter_nr,
			 __entry->msg_nr,
			 __entry->flags,
			 __entry->addr,
			 __entry->len
			 )
		);

DEFINE_EVENT_FN(i2c_read_write, i2c_read,
	       TP_PROTO(const struct i2c_adapter *adap, const struct i2c_ msg *msg,
			int num),
	       TP_ARGS(adap, msg, num),
	       i2c_transfer_trace_reg,
	       i2c_transfer_trace_unreg);

DEFINE_EVENT_FN(i2c_read_write, i2c_write,
	       TP_PROTO(const struct i2c_adapter *adap, const struct i2c_ msg *msg,
			int num),
	       TP_ARGS(adap, msg, num),
	       i2c_transfer_trace_reg,
	       i2c_transfer_trace_unreg);

This will reduce duplication of code by several kilobytes.


-- Steve

Re: [PATCH] i2c: Add message transfer tracepoints for I2C and SMBUS

[David Howells]

Steven Rostedt <rostedt@goodmis.org> wrote:

> Now that you have two tracepoints that are identical, you can use
> DECLARE_EVENT_CLASS() and DEFINE_EVENT_FN(). That is:

They're not identical.  i2c_write() has a data buffer that i2c_read() does
not.

David