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

[Jean Delvare <khali-PUYAD+kWke1g9hUCZPvPmw@public.gmane.org>]

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