Message-ID: <20250812151613.437e3fe8@gandalf.local.home>
Date: Tue, 12 Aug 2025 15:16:13 -0400
From: Steven Rostedt <rostedt@...dmis.org>
To: Mohammad Gomaa <midomaxgomaa@...il.com>
Cc: Wolfram Sang <wsa+renesas@...g-engineering.com>, Masami Hiramatsu
 <mhiramat@...nel.org>, Mathieu Desnoyers <mathieu.desnoyers@...icios.com>,
 linux-i2c@...r.kernel.org, linux-kernel@...r.kernel.org,
 linux-trace-kernel@...r.kernel.org, kenalba@...gle.com,
 hbarnor@...omium.org, rayxu@...gle.com
Subject: Re: [PATCH WIP] i2c: add tracepoints to aid debugging in
 i2c-core-base

On Wed, 06 Aug 2025 12:14:32 +0300
Mohammad Gomaa <midomaxgomaa@...il.com> wrote:

> @@ -509,38 +511,54 @@ static int i2c_device_probe(struct device *dev)
>  			/* Keep adapter active when Host Notify is
> required */ pm_runtime_get_sync(&client->adapter->dev);
>  			irq = i2c_smbus_host_notify_to_irq(client);
> +			reason = "IRQ 0: could not get irq from Host
> Notify"; } else if (is_of_node(fwnode)) {
>  			irq = fwnode_irq_get_byname(fwnode, "irq");
>  			if (irq == -EINVAL || irq == -ENODATA)
>  				irq = fwnode_irq_get(fwnode, 0);
> +			reason = "IRQ 0: could not get irq from OF";

Instead of using strings, can't you use enums?

>  		} else if (is_acpi_device_node(fwnode)) {
>  			bool wake_capable;
>  
>  			irq = i2c_acpi_get_irq(client, &wake_capable);
>  			if (irq > 0 && wake_capable)
>  				client->flags |= I2C_CLIENT_WAKE;
> +			reason = "IRQ 0: could not get irq from ACPI";
>  		}
>  		if (irq == -EPROBE_DEFER) {
>  			status = dev_err_probe(dev, irq, "can't get
> irq\n");
> +			reason = "IRQ 0: could not get IRQ due to
> EPROBE_DEFER"; goto put_sync_adapter;
>  		}
>  
> -		if (irq < 0)
> +		if (irq < 0) {
> +			trace_i2c_device_probe_debug(dev, reason);
>  			irq = 0;
> +		}
>  
>  		client->irq = irq;
>  	}
>  
>  	driver = to_i2c_driver(dev->driver);
>  
> +	has_id_table = driver->id_table;
> +	has_acpi_match = acpi_driver_match_device(dev, dev->driver);
> +	has_of_match = i2c_of_match_device(dev->driver->of_match_table,
> client); +
> +	if (!has_id_table)
> +		trace_i2c_device_probe_debug(dev, "no I2C ID table");
> +	if (!has_acpi_match)
> +		trace_i2c_device_probe_debug(dev, "ACPI ID table
> mismatch");
> +	if (!has_of_match)
> +		trace_i2c_device_probe_debug(dev, "OF ID table
> mismatch"); +
>  	/*
>  	 * An I2C ID table is not mandatory, if and only if, a suitable
> OF
>  	 * or ACPI ID table is supplied for the probing device.
>  	 */
> -	if (!driver->id_table &&
> -	    !acpi_driver_match_device(dev, dev->driver) &&
> -	    !i2c_of_match_device(dev->driver->of_match_table, client)) {
> +	if (!has_id_table && !has_acpi_match && !has_of_match) {
>  		status = -ENODEV;
> +		reason = "no I2C ID table and no ACPI/OF match";
>  		goto put_sync_adapter;
>  	}
>  
> @@ -550,47 +568,60 @@ static int i2c_device_probe(struct device *dev)
>  		wakeirq = fwnode_irq_get_byname(fwnode, "wakeup");
>  		if (wakeirq == -EPROBE_DEFER) {
>  			status = dev_err_probe(dev, wakeirq, "can't get
> wakeirq\n");
> +			reason = "get wake IRQ due to EPROBE_DEFER";
>  			goto put_sync_adapter;
>  		}
>  
>  		device_init_wakeup(&client->dev, true);
>  
> -		if (wakeirq > 0 && wakeirq != client->irq)
> +		if (wakeirq > 0 && wakeirq != client->irq) {
>  			status = dev_pm_set_dedicated_wake_irq(dev,
> wakeirq);
> -		else if (client->irq > 0)
> +			reason = "failed to set dedicated wakeup IRQ";
> +		} else if (client->irq > 0) {
>  			status = dev_pm_set_wake_irq(dev, client->irq);
> -		else
> +			reason = "failed to set wakeup IRQ";
> +		} else {
>  			status = 0;
> +			reason = "no IRQ";
> +		}
>  
> -		if (status)
> +		if (status) {
>  			dev_warn(&client->dev, "failed to set up wakeup
> irq\n");
> +			trace_i2c_device_probe_debug(&client->dev,
> reason);
> +		}
>  	}
>  
>  	dev_dbg(dev, "probe\n");
>  
>  	status = of_clk_set_defaults(to_of_node(fwnode), false);
> -	if (status < 0)
> +	if (status < 0) {
> +		reason = "set default clocks";
>  		goto err_clear_wakeup_irq;
> -
> +	}
>  	do_power_on = !i2c_acpi_waive_d0_probe(dev);
>  	status = dev_pm_domain_attach(&client->dev, do_power_on ?
> PD_FLAG_ATTACH_POWER_ON : 0);
> -	if (status)
> +	if (status) {
> +		reason = "attach PM domain";
>  		goto err_clear_wakeup_irq;
> -
> +	}
>  	client->devres_group_id = devres_open_group(&client->dev, NULL,
>  						    GFP_KERNEL);
>  	if (!client->devres_group_id) {
>  		status = -ENOMEM;
> +		reason = "open devres group";
>  		goto err_detach_pm_domain;
>  	}
>  
>  	client->debugfs = debugfs_create_dir(dev_name(&client->dev),
>  					     client->adapter->debugfs);
>  
> -	if (driver->probe)
> +	if (driver->probe) {
>  		status = driver->probe(client);
> -	else
> +		reason = "specific driver probe failed";
> +	} else {
>  		status = -EINVAL;
> +		reason = "no probe defined";
> +	}
>  
>  	/*
>  	 * Note that we are not closing the devres group opened above so
> @@ -617,6 +648,8 @@ static int i2c_device_probe(struct device *dev)
>  	if (client->flags & I2C_CLIENT_HOST_NOTIFY)
>  		pm_runtime_put_sync(&client->adapter->dev);
>  
> +	trace_i2c_device_probe_failed(&client->dev, status, reason);
> +
>  	return status;
>  }
>  
> diff --git a/include/trace/events/i2c.h b/include/trace/events/i2c.h
> index
> 142a23c6593c611de9abc2a89a146b95550b23cd..1a08800dcdd760e2a5a40b76c4a244e1b4ef3b1e
> 100644 --- a/include/trace/events/i2c.h +++ b/include/trace/events/i2c.h
> @@ -16,6 +16,29 @@
>  /*
>   * drivers/i2c/i2c-core-base.c
>   */
> +TRACE_EVENT(i2c_device_probe_debug,
> +	    TP_PROTO(struct device *dev, const char *message),
> +	    TP_ARGS(dev, message),
> +	    TP_STRUCT__entry(__string(devname, dev_name(dev))
> __string(message, message)),
> +	    TP_fast_assign(__assign_str(devname);
> __assign_str(message);),
> +	    TP_printk("device=%s: %s", __get_str(devname),
> __get_str(message)) +);
> +
> +TRACE_EVENT(i2c_device_probe_failed,
> +	    TP_PROTO(struct device *dev, int status, const char *reason),
> +	    TP_ARGS(dev, status, reason),
> +	    TP_STRUCT__entry(__string(dev_name, dev_name(dev))
> +			     __field(int, status)
> +			     __string(reason, reason)),
> +	    TP_fast_assign(__assign_str(dev_name);
> +		__entry->status = status;
> +		__assign_str(reason);),
> +	    TP_printk("failed to probe %s: %d (%s)",
> +		      __get_str(dev_name),
> +		      __entry->status,
> +		      __get_str(reason))
> +);

Note, TRACE_EVENT() macros have their own space formatting, as they are not
normal macros and instead are to emulate code. That is, TP_STRUCT__entry is
supposed to look like a structure, and the TP_fast_assign should look like
a function. The above should look like:


TRACE_EVENT(i2c_device_probe_debug,

	TP_PROTO(struct device *dev, const char *message),

	TP_ARGS(dev, message),

	TP_STRUCT__entry(
		__string(	devname,	dev_name(dev)	)
		__string(	message,	message		)
	),

	TP_fast_assign(
		__assign_str(devname);
		__assign_str(message);
	),

	TP_printk("device=%s: %s", __get_str(devname), __get_str(message))
);

TRACE_EVENT(i2c_device_probe_failed,

	TP_PROTO(struct device *dev, int status, const char *reason),

	TP_ARGS(dev, status, reason),

	TP_STRUCT__entry(
		__string(	dev_name,	dev_name(dev)	)
		__field(	int,		status		)
		__string(	reason,		reason)
	),

	TP_fast_assign(
		__assign_str(dev_name);
		__entry->status = status;
		__assign_str(reason);
	),

	TP_printk("failed to probe %s: %d (%s)",
		  __get_str(dev_name),
		  __entry->status,
		  __get_str(reason))
);

See the difference. It's much easier to read. You can look at the other
files in include/trace/events/*.h for reference.

Instead of passing in a string for "reason" (and waste time and ring buffer
size for a string) use enums and __print_symbolic()

#define I2C_TRACE_REASON						\
	EM(HOST_NOTIFY,	"IRQ 0: could not get irq from Host
Notify")	\
	EM(FROM_OF,	"IRQ 0: could not get irq from OF")
	\
	EM(FROM_ACPI,	"IRQ 0: could not get irq from ACPI")
	\
	[..]
\
	EMe(NO_PROBE,	"no probe defined")

#undef EM
#undef EMe
#define EM(a,b)	 I2C_TRACE_REASON_##a,
#define EMe(a,b) I2C_TRACE_REASON_##a

enum {
	I2C_TRACE_REASON
};

In the trace/events/i2c.h file:

#undef EM
#undef EMe
#define EM(a,b)		TRACE_DEFINE_ENUM(I2C_TRACE_REASON_##a);
#define EMe(a,b)	TRACE_DEFINE_ENUM(I2C_TRACE_REASON_##a);

I2C_TRACE_REASON

#undef EM
#undef EMe
#define EM(a,b)		{ I2C_TRACE_REASON_##a, b },
#define EMe(a,b)	{ I2C_TRACE_REASON_##a, b }

And in the TRACE_EVENT() macro:

	TP_PROTO(struct device *dev, int status, int reason),

	TP_ARGS(dev, status, reason),

	[..]
		__field(	int,	reason		)
	[..]
		__entry->reason = reason;
	[..]

	TP_printk("device=%s: %s", __get_str(devname),
		  __print_symbolic(reason, I2C_TRACE_REASON) )

And it should work nicely both in the kernel and in user space, and not
have the overhead of copying strings during execution.

Maybe this is overkill because it's just for debugging and you shouldn't
have many of these events. But I wanted to at least educate you on the use
of these macros in case you have other areas to do this with.

-- Steve


> +
>  extern int i2c_transfer_trace_reg(void);
>  extern void i2c_transfer_trace_unreg(void);
>  
> 
> ---
> base-commit: 7e161a991ea71e6ec526abc8f40c6852ebe3d946
> change-id: 20250806-refactor-add-i2c-tracepoints-b6e2b92d4cd9
> 
> Best regards,

Powered by blists - more mailing lists