[PATCH 1/2] i2c: Add message transfer tracepoints for I2C

[David Howells]

Add tracepoints into the I2C message transfer function 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_write: i2c-5 #0 f=00 a=44 l=2 [0214]
... i2c_read: i2c-5 #1 f=01 a=44 l=4
... i2c_reply: i2c-5 #1 f=01 a=44 l=4 [33000000]
... i2c_result: i2c-5 n=2 ret=2

formatted as:

i2c-<adapter-nr>
#<message-array-index>
f=<flags>
a=<addr>
l=<datalen>
n=<message-array-size>
ret=<result>
[<data>]

The operation is done between the i2c_write/i2c_read lines and the i2c_reply
and i2c_result lines so that if the hardware hangs, the trace buffer can be
consulted to determine the problematic operation.

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

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

These changes are based on code from Steven Rostedt.

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

drivers/i2c/i2c-core.c | 37 +++++++++++
include/trace/events/i2c.h | 150 ++++++++++++++++++++++++++++++++++++++++++++
2 files changed, 187 insertions(+)
create mode 100644 include/trace/events/i2c.h

diff --git a/drivers/i2c/i2c-core.c b/drivers/i2c/i2c-core.c
index d74c0b34248e..c8b97490461d 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
@@ -1710,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++) {
@@ -1720,6 +1749,14 @@ int __i2c_transfer(struct i2c_adapter *adap, struct i2c_msg *msgs, int num)
break;
}

+ if (static_key_false(&i2c_trace_msg)) {
+ int i;
+ 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;
}
EXPORT_SYMBOL(__i2c_transfer);
diff --git a/include/trace/events/i2c.h b/include/trace/events/i2c.h
new file mode 100644
index 000000000000..d30f008527b2
--- /dev/null
+++ b/include/trace/events/i2c.h
@@ -0,0 +1,150 @@
+/* I2C message transfer tracepoints
+ *
+ * Copyright (C) 2013 Red Hat, Inc. All Rights Reserved.
+ * Written by David Howells (dhow...@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);
+
+/*
+ * __i2c_transfer() write request
+ */
+TRACE_EVENT_FN(i2c_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 )
+ __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;
+ 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() 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);
+
+#endif /* _TRACE_I2C_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majo...@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

[David Howells]

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 <dhow...@redhat.com>
Reviewed-by: Steven Rostedt <ros...@goodmis.org>
---

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

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 (dhow...@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 */

[Wolfram Sang]

Thanks for doing this, much appreciated. One of the first things I'll
review (and play with) next. But hey, has nobody else checked this out
by now? Tested-by or acks very welcome.

Thanks,

Wolfram

[Wolfram Sang]

Hi David,

On Thu, Jan 09, 2014 at 09:49:54PM +0000, David Howells wrote:

I like it very much, just have some comments about the format.

> +TRACE_EVENT_FN(i2c_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 )
> + __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]",

'flags' are u16 and the whole range is needed -> %04x

'addr' is u16 and either 7 or 10 bits are needed. The core does the
following when assigning names because it is possible to have devices
0x50 (7-bit) and 0x050 (10-bit) on the bus:

/* For 10-bit clients, add an arbitrary offset to avoid collisions */
dev_set_name(&client->dev, "%d-%04x", i2c_adapter_id(adap),
client->addr | ((client->flags & I2C_CLIENT_TEN)
? 0xa000 : 0));

I don't know if this can be implemented. Actually, I don't think it
needs to be implemented since flags are printed, too. So, with this the
10-bit case is visible and for the address simply %03x should do.

And for the buffer: %*phN is difficult to read IMO. What about %*ph? Or
%*phD at least?

Thanks,

Wolfram

[Wolfram Sang]

> + 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]

Wolfram Sang <w...@the-dreams.de> wrote:

> 'flags' are u16 and the whole range is needed -> %04x

Done. Note that %02x does not preclude more digits, but I guess it's better
to have things line up.

> for the address simply %03x should do.

Done.

> And for the buffer: %*phN is difficult to read IMO. What about %*ph? Or
> %*phD at least?

My problem with that is that it increases the length of the output by 50% and
there's a hard limit on how much output we may produce.

David

[David Howells]

Wolfram Sang <w...@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

[Wolfram Sang]

> > And for the buffer: %*phN is difficult to read IMO. What about %*ph? Or
> > %*phD at least?
>
> My problem with that is that it increases the length of the output by 50% and
> there's a hard limit on how much output we may produce.

Is it PAGE_SIZE? How is this handled when the buffer is so big that the
limit will be reached anyhow? Note that it is really uncommon to
transfer kilobytes in one go via i2c. Usually, big transfers are split
up into smaller fragments, say 128-256 byte. So, for readability, I'd
still favour %*ph.

[Wolfram Sang]

> > 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]

Wolfram Sang <w...@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 Howells]

I was thinking that limited the size of the output field to 64 bytes. But
reading vsprintf.c again, it appears it's actually the size of the binary blob
that it's converting to hex that's limited to 64 bytes.

I would prefer shorter lines - 128 bytes of hex still isn't entirely readable,
even with separators interpolated, but I'll add this.

[David Howells]

David Howells <dhow...@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?

[Wolfram Sang]

On Thu, Mar 06, 2014 at 01:13:55PM +0000, David Howells wrote:
> David Howells <dhow...@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]

Wolfram Sang <w...@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.