diff mbox

[2/2] i2c: Add message transfer tracepoints for SMBUS

Message ID 20140109215002.25590.51609.stgit@warthog.procyon.org.uk
State Changes Requested
Headers show

Commit Message

David Howells Jan. 9, 2014, 9:50 p.m. UTC 
The SMBUS tracepoints can be enabled thusly:

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

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

         ... smbus_read: i2c-0 a=51 f=00 c=fa BYTE_DATA
         ... smbus_reply: i2c-0 a=51 f=00 c=fa BYTE_DATA l=1 [39]
         ... smbus_result: i2c-0 a=51 f=00 c=fa BYTE_DATA rd res=0

formatted as:

	i2c-<adapter-nr>
	a=<addr>
	f=<flags>
	c=<command>
	<protocol-name>
	<rd|wr>
	res=<result>
	l=<data-len>
	[<data-block>]


The adapters to be traced can be selected by something like:

	echo adapter_nr==1 >/sys/kernel/debug/tracing/events/i2c/filter

Note that this shares the same filter and enablement as i2c.

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

 drivers/i2c/i2c-core.c     |   23 ++++-
 include/trace/events/i2c.h |  224 ++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 243 insertions(+), 4 deletions(-)


--
To unsubscribe from this list: send the line "unsubscribe linux-i2c" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Comments

Wolfram Sang Feb. 18, 2014, 8:54 p.m. UTC | #1 
> +	TP_printk("i2c-%d a=%02x f=%02x c=%x %s l=%u [%*phN]",

Although SMBus has no 10-bit addresses, we probably should also use %03x
there for consistency reasons?

Also, the I2C tracing has first 'f' then 'a', that should be consistent,
too.

'flags' should be %04x again and I'd prefer %*ph (or %*phD) for the buffer.


> +		  __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" }),

Can we have something like this for 'flags'?
David Howells Feb. 27, 2014, 1:19 p.m. UTC | #2 
Wolfram Sang <wsa@the-dreams.de> wrote:

> Although SMBus has no 10-bit addresses, we probably should also use %03x
> there for consistency reasons?

Done.

> Also, the I2C tracing has first 'f' then 'a', that should be consistent,
> too.

Flags first or address first?  Do you have a preference (for both)?

> 'flags' should be %04x again

Done.

> and I'd prefer %*ph (or %*phD) for the buffer.

Again, I'm not so certain.

> Can we have something like this for 'flags'?

There's a __print_flags() which should work.  One thing I'm concerned about
there is how do we handle more flags being added - does that count as an ABI
break if the printed format changes?

SMBus flags are basically the same as I2C flags, right?

David
--
To unsubscribe from this list: send the line "unsubscribe linux-i2c" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Wolfram Sang Feb. 28, 2014, 9:21 p.m. UTC | #3 
> > Also, the I2C tracing has first 'f' then 'a', that should be consistent,
> > too.
> 
> Flags first or address first?  Do you have a preference (for both)?

I'd say address first, yet no strong preference.

> > Can we have something like this for 'flags'?
> 
> There's a __print_flags() which should work.  One thing I'm concerned about
> there is how do we handle more flags being added - does that count as an ABI
> break if the printed format changes?

Not sure, I mean, this is debug output, no?

> SMBus flags are basically the same as I2C flags, right?

Basically, yes.

Thanks,

   Wolfram
David Howells March 1, 2014, 7:48 a.m. UTC | #4 
Wolfram Sang <wsa@the-dreams.de> wrote:

> > > Can we have something like this for 'flags'?
> > 
> > There's a __print_flags() which should work.  One thing I'm concerned about
> > there is how do we handle more flags being added - does that count as an ABI
> > break if the printed format changes?
> 
> Not sure, I mean, this is debug output, no?

Apparently, the raw messages are ABI, but the text dump (which is what we're
talking out) is not.  So doing this should be okay.

David
--
To unsubscribe from this list: send the line "unsubscribe linux-i2c" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
David Howells March 6, 2014, 1:13 p.m. UTC | #5 
David Howells <dhowells@redhat.com> wrote:

> > Can we have something like this for 'flags'?
> 
> There's a __print_flags() which should work.  One thing I'm concerned about
> there is how do we handle more flags being added - does that count as an ABI
> break if the printed format changes?
> 
> SMBus flags are basically the same as I2C flags, right?

Hmmm... __print_flags() seems to append a string if a flag is set, and doesn't
if it isn't set.  It places a separator between each string.  I would prefer
something that emits a single char per flag or a dash if it isn't present.
Are you okay with that?

David
--
To unsubscribe from this list: send the line "unsubscribe linux-i2c" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Wolfram Sang March 6, 2014, 1:17 p.m. UTC | #6 
On Thu, Mar 06, 2014 at 01:13:55PM +0000, David Howells wrote:
> David Howells <dhowells@redhat.com> wrote:
> 
> > > Can we have something like this for 'flags'?
> > 
> > There's a __print_flags() which should work.  One thing I'm concerned about
> > there is how do we handle more flags being added - does that count as an ABI
> > break if the printed format changes?
> > 
> > SMBus flags are basically the same as I2C flags, right?
> 
> Hmmm... __print_flags() seems to append a string if a flag is set, and doesn't
> if it isn't set.  It places a separator between each string.  I would prefer
> something that emits a single char per flag or a dash if it isn't present.
> Are you okay with that?

Yes, that's good, too!

Thanks!
David Howells March 6, 2014, 1:38 p.m. UTC | #7 
Wolfram Sang <wsa@the-dreams.de> wrote:

> Yes, that's good, too!

I've posted my current patches.  I've put address before flags and increased
the address field to 3 hex chars and the flags to four.  I've made it
interpolate dashes to indicate the byte divisions in the data dump.

I'll follow up with a separate patch to turn the flags into a more readable
format.

David
--
To unsubscribe from this list: send the line "unsubscribe linux-i2c" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
diff mbox

Patch

diff --git a/drivers/i2c/i2c-core.c b/drivers/i2c/i2c-core.c
index c8b97490461d..619910632d26 100644
--- a/drivers/i2c/i2c-core.c
+++ b/drivers/i2c/i2c-core.c
@@ -2552,6 +2552,14 @@  s32 i2c_smbus_xfer(struct i2c_adapter *adapter, u16 addr, unsigned short flags,
 	int try;
 	s32 res;
 
+	/* If enabled, the following two tracepoints are conditional on
+	 * read_write and protocol.
+	 */
+	trace_smbus_write(adapter, addr, flags, read_write,
+			  command, protocol, data);
+	trace_smbus_read(adapter, addr, flags, read_write,
+			 command, protocol);
+
 	flags &= I2C_M_TEN | I2C_CLIENT_PEC | I2C_CLIENT_SCCB;
 
 	if (adapter->algo->smbus_xfer) {
@@ -2572,15 +2580,24 @@  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:
+	/* If enabled, the reply tracepoint is conditional on read_write. */
+	trace_smbus_reply(adapter, addr, flags, read_write,
+			  command, protocol, data);
+	trace_smbus_result(adapter, addr, flags, read_write,
+			   command, protocol, res);
+
+	return res;
 }
 EXPORT_SYMBOL(i2c_smbus_xfer);
 
diff --git a/include/trace/events/i2c.h b/include/trace/events/i2c.h
index d30f008527b2..222aae9c6e3d 100644
--- a/include/trace/events/i2c.h
+++ b/include/trace/events/i2c.h
@@ -1,4 +1,4 @@ 
-/* I2C message transfer tracepoints
+/* I2C and SMBUS message transfer tracepoints
  *
  * Copyright (C) 2013 Red Hat, Inc. All Rights Reserved.
  * Written by David Howells (dhowells@redhat.com)
@@ -144,6 +144,228 @@  TRACE_EVENT_FN(i2c_result,
 	       i2c_transfer_trace_reg,
 	       i2c_transfer_trace_unreg);
 
+/*
+ * i2c_smbus_xfer() write data or procedure call request
+ */
+TRACE_EVENT_CONDITION(smbus_write,
+	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),
+	TP_ARGS(adap, addr, flags, read_write, command, protocol, data),
+	TP_CONDITION(read_write == I2C_SMBUS_WRITE ||
+		     protocol == I2C_SMBUS_PROC_CALL ||
+		     protocol == I2C_SMBUS_BLOCK_PROC_CALL),
+	TP_STRUCT__entry(
+		__field(int,	adapter_nr		)
+		__field(__u16,	addr			)
+		__field(__u16,	flags			)
+		__field(__u8,	command			)
+		__field(__u8,	len			)
+		__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;
+
+		switch (protocol) {
+		case I2C_SMBUS_BYTE_DATA:
+			__entry->len = 1;
+			goto copy;
+		case I2C_SMBUS_WORD_DATA:
+		case I2C_SMBUS_PROC_CALL:
+			__entry->len = 2;
+			goto copy;
+		case I2C_SMBUS_BLOCK_DATA:
+		case I2C_SMBUS_BLOCK_PROC_CALL:
+		case I2C_SMBUS_I2C_BLOCK_DATA:
+			__entry->len = data->block[0] + 1;
+		copy:
+			memcpy(__entry->buf, data->block, __entry->len);
+			break;
+		case I2C_SMBUS_QUICK:
+		case I2C_SMBUS_BYTE:
+		case I2C_SMBUS_I2C_BLOCK_BROKEN:
+		default:
+			__entry->len = 0;
+		}
+		       ),
+	TP_printk("i2c-%d a=%02x f=%02x c=%x %s l=%u [%*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" }),
+		  __entry->len,
+		  __entry->len, __entry->buf
+		  ));
+
+/*
+ * i2c_smbus_xfer() read data request
+ */
+TRACE_EVENT_CONDITION(smbus_read,
+	TP_PROTO(const struct i2c_adapter *adap,
+		 u16 addr, unsigned short flags,
+		 char read_write, u8 command, int protocol),
+	TP_ARGS(adap, addr, flags, read_write, command, protocol),
+	TP_CONDITION(!(read_write == I2C_SMBUS_WRITE ||
+		       protocol == I2C_SMBUS_PROC_CALL ||
+		       protocol == I2C_SMBUS_BLOCK_PROC_CALL)),
+	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 data or procedure call reply
+ */
+TRACE_EVENT_CONDITION(smbus_reply,
+	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),
+	TP_ARGS(adap, addr, flags, read_write, command, protocol, data),
+	TP_CONDITION(read_write == I2C_SMBUS_READ),
+	TP_STRUCT__entry(
+		__field(int,	adapter_nr		)
+		__field(__u16,	addr			)
+		__field(__u16,	flags			)
+		__field(__u8,	command			)
+		__field(__u8,	len			)
+		__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;
+
+		switch (protocol) {
+		case I2C_SMBUS_BYTE:
+		case I2C_SMBUS_BYTE_DATA:
+			__entry->len = 1;
+			goto copy;
+		case I2C_SMBUS_WORD_DATA:
+		case I2C_SMBUS_PROC_CALL:
+			__entry->len = 2;
+			goto copy;
+		case I2C_SMBUS_BLOCK_DATA:
+		case I2C_SMBUS_BLOCK_PROC_CALL:
+		case I2C_SMBUS_I2C_BLOCK_DATA:
+			__entry->len = data->block[0] + 1;
+		copy:
+			memcpy(__entry->buf, data->block, __entry->len);
+			break;
+		case I2C_SMBUS_QUICK:
+		case I2C_SMBUS_I2C_BLOCK_BROKEN:
+		default:
+			__entry->len = 0;
+		}
+		       ),
+	TP_printk("i2c-%d a=%02x f=%02x c=%x %s l=%u [%*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" }),
+		  __entry->len,
+		  __entry->len, __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,
+		     int res),
+	    TP_ARGS(adap, addr, flags, read_write, command, protocol, 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		)
+			     ),
+	    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;
+			   ),
+	    TP_printk("i2c-%d a=%02x f=%02x c=%x %s %s res=%d",
+		      __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" }),
+		      __entry->read_write == I2C_SMBUS_WRITE ? "wr" : "rd",
+		      __entry->res
+		      ));
+
 #endif /* _TRACE_I2C_H */
 
 /* This part must be outside protection */