[PATCH WIP] i2c: add tracepoints to aid debugging in i2c-core-base

[PATCH WIP] i2c: add tracepoints to aid debugging in i2c-core-base

[Mohammad Gomaa]

Add tracepoints to i2c-core-base.c file to help trace
and debug I2C device probe failures.

The new trace points are:
- i2c_device_probe_debug: records non-failure routines
  e.g. IRQ 0.
- i2c_device_probe_failed: records failure routines e.g.
  failure to set default clocks.

To support operation of these tracepoints a variable
was added to record reason for debug and failure.

Signed-off-by: Mohammad Gomaa <midomaxgomaa@gmail.com>
---
Hello,

This patch adds tracepoints to i2c-core-base to aid with debugging I2C probing failrues.

The motivation for this comes from my work in Google Summer of Code (GSoC) 2025:
"ChromeOS Platform Input Device Quality Monitoring"
https://summerofcode.withgoogle.com/programs/2025/projects/uCdIgK7K

This is my first submission to the Linux kernel, so any feedback is welcome.
---
 drivers/i2c/i2c-core-base.c | 61 ++++++++++++++++++++++++++++++++++-----------
 include/trace/events/i2c.h  | 23 +++++++++++++++++
 2 files changed, 70 insertions(+), 14 deletions(-)

diff --git a/drivers/i2c/i2c-core-base.c b/drivers/i2c/i2c-core-base.c
index ecca8c006b020379fb53293b20ab09ba25314609..c145af56a17d74117985430d04b75fff5b45b9b2 100644
--- a/drivers/i2c/i2c-core-base.c
+++ b/drivers/i2c/i2c-core-base.c
@@ -495,6 +495,8 @@ static int i2c_device_probe(struct device *dev)
 	struct i2c_driver	*driver;
 	bool do_power_on;
 	int status;
+	const char *reason = NULL;
+	bool has_id_table, has_acpi_match, has_of_match;
 
 	if (!client)
 		return 0;
@@ -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";
 		} 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))
+);
+
 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,
-- 
Mohammad Gomaa <midomaxgomaa@gmail.com>

Re: [PATCH WIP] i2c: add tracepoints to aid debugging in i2c-core-base

[Steven Rostedt]

On Wed, 06 Aug 2025 12:14:32 +0300
Mohammad Gomaa <midomaxgomaa@gmail.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,