LWIS: Support logging recent register io history programmatically and with DebugFS.

Bug: 261645011
Test: Manual
Change-Id: I55482ba4fe741214a147cc8d998766cb025a3a82
Signed-off-by: linyuny <linyuny@google.com>

10 files changed, 144 insertions, 65 deletions

diff --git a/lwis_debug.c b/lwis_debug.c
index 90eaaeb..5813476 100644
--- a/lwis_debug.c
+++ b/lwis_debug.c
@@ -320,70 +320,61 @@ static int generate_buffer_info(struct lwis_device *lwis_dev, char *buffer, size
 	return 0;
 }
 
-void lwis_debug_save_register_io_to_history(struct lwis_device *lwis_dev,
-					    struct lwis_io_entry *entry, size_t access_size)
+static int generate_register_io_history(struct lwis_device *lwis_dev, char *buffer, size_t buffer_size)
 {
-	lwis_dev->debug_info.io_entry_hist[lwis_dev->debug_info.cur_io_entry_hist_idx].io_entry =
-		*entry;
-	lwis_dev->debug_info.io_entry_hist[lwis_dev->debug_info.cur_io_entry_hist_idx].access_size =
-		access_size;
-	lwis_dev->debug_info.io_entry_hist[lwis_dev->debug_info.cur_io_entry_hist_idx]
-		.start_timestamp = ktime_to_ns(lwis_get_time());
-	lwis_dev->debug_info.cur_io_entry_hist_idx++;
-	if (lwis_dev->debug_info.cur_io_entry_hist_idx >= IO_ENTRY_DEBUG_HISTORY_SIZE) {
-		lwis_dev->debug_info.cur_io_entry_hist_idx = 0;
-	}
-}
-
-int lwis_debug_print_register_io_history(struct lwis_device *lwis_dev)
-{
-	int i, hist_idx;
+	/* Temporary buffer to be concatenated to the main buffer. */
+	char tmp_buf[128] = {};
 	struct lwis_register_io_info *reg_io;
+	int i, hist_idx;
 
-	/* TODO(bian): Change dev_warn to print_to_log style. */
-	dev_warn(lwis_dev->dev, "=== LWIS REGISTER IO INFO: %s ===", lwis_dev->name);
-	dev_warn(lwis_dev->dev, "Last register read/writes:\n");
+	if (lwis_dev == NULL) {
+		pr_err("Unknown LWIS device pointer\n");
+		return -EINVAL;
+	}
+
+	scnprintf(buffer, buffer_size, "=== LWIS REGISTER IO INFO: %s ===\n", lwis_dev->name);
+	strlcat(buffer, "Last register read/writes:\n", buffer_size);
 	hist_idx = lwis_dev->debug_info.cur_io_entry_hist_idx;
 	for (i = 0; i < IO_ENTRY_DEBUG_HISTORY_SIZE; ++i) {
 		reg_io = &lwis_dev->debug_info.io_entry_hist[hist_idx];
 		/* Skip uninitialized entries */
 		if (reg_io->start_timestamp != 0) {
 			if (reg_io->io_entry.type == LWIS_IO_ENTRY_READ) {
-				dev_warn(
-					lwis_dev->dev,
-					"READ: bid %d, offset %llu, val %llu, access_size %lu, start_timestamp %llu\n",
-					reg_io->io_entry.rw.bid, reg_io->io_entry.rw.offset,
-					reg_io->io_entry.rw.val, reg_io->access_size,
-					reg_io->start_timestamp);
+				scnprintf(tmp_buf, sizeof(tmp_buf),
+					  "READ: bid %d, offset %llu, val %llu, access_size %lu, start_timestamp %llu\n",
+					  reg_io->io_entry.rw.bid, reg_io->io_entry.rw.offset,
+					  reg_io->io_entry.rw.val, reg_io->access_size,
+					  reg_io->start_timestamp);
+				strlcat(buffer, tmp_buf, buffer_size);
 			} else if (reg_io->io_entry.type == LWIS_IO_ENTRY_READ_BATCH) {
-				dev_warn(
-					lwis_dev->dev,
-					"READ_BATCH: bid %d, offset %llu, size_in_bytes %lu, access_size %lu, start_timestamp %llu\n",
-					reg_io->io_entry.rw_batch.bid,
-					reg_io->io_entry.rw_batch.offset,
-					reg_io->io_entry.rw_batch.size_in_bytes,
-					reg_io->access_size, reg_io->start_timestamp);
+				scnprintf(tmp_buf, sizeof(tmp_buf),
+					 "READ_BATCH: bid %d, offset %llu, size_in_bytes %lu, access_size %lu, start_timestamp %llu\n",
+					 reg_io->io_entry.rw_batch.bid,
+					 reg_io->io_entry.rw_batch.offset,
+					 reg_io->io_entry.rw_batch.size_in_bytes,
+					 reg_io->access_size, reg_io->start_timestamp);
+				strlcat(buffer, tmp_buf, buffer_size);
 			} else if (reg_io->io_entry.type == LWIS_IO_ENTRY_WRITE) {
-				dev_warn(
-					lwis_dev->dev,
-					"WRITE: bid %d, offset %llu, val %llu, access_size %lu, start_timestamp %llu\n",
-					reg_io->io_entry.rw.bid, reg_io->io_entry.rw.offset,
-					reg_io->io_entry.rw.val, reg_io->access_size,
-					reg_io->start_timestamp);
+				scnprintf(tmp_buf, sizeof(tmp_buf),
+					 "WRITE: bid %d, offset %llu, val %llu, access_size %lu, start_timestamp %llu\n",
+					 reg_io->io_entry.rw.bid, reg_io->io_entry.rw.offset,
+					 reg_io->io_entry.rw.val, reg_io->access_size,
+					 reg_io->start_timestamp);
+				strlcat(buffer, tmp_buf, buffer_size);
 			} else if (reg_io->io_entry.type == LWIS_IO_ENTRY_WRITE_BATCH) {
-				dev_warn(
-					lwis_dev->dev,
-					"WRITE_BATCH: bid %d, offset %llu, size_in_bytes %lu, access_size %lu, start_timestamp %llu\n",
-					reg_io->io_entry.rw_batch.bid,
-					reg_io->io_entry.rw_batch.offset,
-					reg_io->io_entry.rw_batch.size_in_bytes,
-					reg_io->access_size, reg_io->start_timestamp);
+				scnprintf(tmp_buf, sizeof(tmp_buf),
+					 "WRITE_BATCH: bid %d, offset %llu, size_in_bytes %lu, access_size %lu, start_timestamp %llu\n",
+					 reg_io->io_entry.rw_batch.bid,
+					 reg_io->io_entry.rw_batch.offset,
+					 reg_io->io_entry.rw_batch.size_in_bytes,
+					 reg_io->access_size, reg_io->start_timestamp);
+				strlcat(buffer, tmp_buf, buffer_size);
 			} else if (reg_io->io_entry.type == LWIS_IO_ENTRY_MODIFY) {
-				dev_warn(
-					lwis_dev->dev,
-					"MODIFY: bid %d, offset %llu, access_size %lu, start_timestamp %llu\n",
-					reg_io->io_entry.mod.bid, reg_io->io_entry.mod.offset,
-					reg_io->access_size, reg_io->start_timestamp);
+				scnprintf(tmp_buf, sizeof(tmp_buf),
+					 "MODIFY: bid %d, offset %llu, access_size %lu, start_timestamp %llu\n",
+					 reg_io->io_entry.mod.bid, reg_io->io_entry.mod.offset,
+					 reg_io->access_size, reg_io->start_timestamp);
+				strlcat(buffer, tmp_buf, buffer_size);
 			}
 		}
 		hist_idx++;
@@ -395,6 +386,29 @@ int lwis_debug_print_register_io_history(struct lwis_device *lwis_dev)
 	return 0;
 }
 
+int lwis_debug_print_register_io_history(struct lwis_device *lwis_dev)
+{
+	int ret = 0;
+	/* Buffer to store information */
+	const size_t buffer_size = 10240;
+	char *buffer = kzalloc(buffer_size, GFP_KERNEL);
+	if (!buffer) {
+		dev_err(lwis_dev->dev, "Failed to allocate register io history log buffer\n");
+		return -ENOMEM;
+	}
+
+	ret = generate_register_io_history(lwis_dev, buffer, buffer_size);
+	if (ret) {
+		dev_err(lwis_dev->dev, "Failed to generate register io history");
+		goto exit;
+	}
+	print_to_log(buffer);
+
+exit:
+	kfree(buffer);
+	return 0;
+}
+
 int lwis_debug_print_device_info(struct lwis_device *lwis_dev)
 {
 	int ret = 0;
@@ -571,6 +585,31 @@ exit:
 	return ret;
 }
 
+static ssize_t register_io_history_read(struct file *fp, char __user *user_buf, size_t count,
+					loff_t *position)
+{
+	int ret = 0;
+	/* Buffer to store information */
+	const size_t buffer_size = 10240;
+	struct lwis_device *lwis_dev = fp->f_inode->i_private;
+	char *buffer = kzalloc(buffer_size, GFP_KERNEL);
+	if (!buffer) {
+		dev_err(lwis_dev->dev, "Failed to allocate register io history log buffer\n");
+		return -ENOMEM;
+	}
+
+	ret = generate_register_io_history(lwis_dev, buffer, buffer_size);
+	if (ret) {
+		dev_err(lwis_dev->dev, "Failed to generate register io history");
+		goto exit;
+	}
+
+	ret = simple_read_from_buffer(user_buf, count, position, buffer, strlen(buffer));
+exit:
+	kfree(buffer);
+	return ret;
+}
+
 static struct file_operations dev_info_fops = {
 	.owner = THIS_MODULE,
 	.read = dev_info_read,
@@ -591,6 +630,11 @@ static struct file_operations buffer_info_fops = {
 	.read = buffer_info_read,
 };
 
+static struct file_operations register_io_history_fops = {
+	.owner = THIS_MODULE,
+	.read = register_io_history_read,
+};
+
 int lwis_device_debugfs_setup(struct lwis_device *lwis_dev, struct dentry *dbg_root)
 {
 	struct dentry *dbg_dir;
@@ -598,6 +642,7 @@ int lwis_device_debugfs_setup(struct lwis_device *lwis_dev, struct dentry *dbg_r
 	struct dentry *dbg_event_file;
 	struct dentry *dbg_transaction_file;
 	struct dentry *dbg_buffer_file;
+	struct dentry *dbg_reg_io_file;
 
 	/* DebugFS not present, just return */
 	if (dbg_root == NULL) {
@@ -643,11 +688,20 @@ int lwis_device_debugfs_setup(struct lwis_device *lwis_dev, struct dentry *dbg_r
 		dbg_buffer_file = NULL;
 	}
 
+	dbg_reg_io_file =
+		debugfs_create_file("io_history", 0444, dbg_dir, lwis_dev, &register_io_history_fops);
+	if (IS_ERR_OR_NULL(dbg_reg_io_file)) {
+		dev_warn(lwis_dev->dev, "Failed to create DebugFS io_history - %ld",
+			 PTR_ERR(dbg_reg_io_file));
+		dbg_reg_io_file = NULL;
+	}
+
 	lwis_dev->dbg_dir = dbg_dir;
 	lwis_dev->dbg_dev_info_file = dbg_dev_info_file;
 	lwis_dev->dbg_event_file = dbg_event_file;
 	lwis_dev->dbg_transaction_file = dbg_transaction_file;
 	lwis_dev->dbg_buffer_file = dbg_buffer_file;
+	lwis_dev->dbg_reg_io_file = dbg_reg_io_file;
 
 	return 0;
 }
@@ -664,6 +718,7 @@ int lwis_device_debugfs_cleanup(struct lwis_device *lwis_dev)
 	lwis_dev->dbg_event_file = NULL;
 	lwis_dev->dbg_transaction_file = NULL;
 	lwis_dev->dbg_buffer_file = NULL;
+	lwis_dev->dbg_reg_io_file = NULL;
 	return 0;
 }
 
diff --git a/lwis_debug.h b/lwis_debug.h
index 4978606..85996a3 100644
--- a/lwis_debug.h
+++ b/lwis_debug.h
@@ -10,10 +10,6 @@
 
 #include "lwis_device.h"
 
-/* Functions to save information for debugging */
-void lwis_debug_save_register_io_to_history(struct lwis_device *lwis_dev,
-					    struct lwis_io_entry *entry, size_t access_size);
-
 /* Functions to print debugging info */
 int lwis_debug_print_device_info(struct lwis_device *lwis_dev);
 int lwis_debug_print_event_states_info(struct lwis_device *lwis_dev, int lwis_event_dump_cnt);
diff --git a/lwis_device.c b/lwis_device.c
index 05ca8fa..7e64435 100644
--- a/lwis_device.c
+++ b/lwis_device.c
@@ -1198,6 +1198,21 @@ void lwis_device_crash_info_dump(struct lwis_device *lwis_dev)
 	lwis_debug_print_event_states_info(lwis_dev, /*lwis_event_dump_cnt=*/dump_cnt);
 }
 
+void lwis_save_register_io_info(struct lwis_device *lwis_dev, struct lwis_io_entry *io_entry,
+				size_t access_size)
+{
+	lwis_dev->debug_info.io_entry_hist[lwis_dev->debug_info.cur_io_entry_hist_idx].io_entry =
+		*io_entry;
+	lwis_dev->debug_info.io_entry_hist[lwis_dev->debug_info.cur_io_entry_hist_idx].access_size =
+		access_size;
+	lwis_dev->debug_info.io_entry_hist[lwis_dev->debug_info.cur_io_entry_hist_idx]
+		.start_timestamp = ktime_to_ns(lwis_get_time());
+	lwis_dev->debug_info.cur_io_entry_hist_idx++;
+	if (lwis_dev->debug_info.cur_io_entry_hist_idx >= IO_ENTRY_DEBUG_HISTORY_SIZE) {
+		lwis_dev->debug_info.cur_io_entry_hist_idx = 0;
+	}
+}
+
 /*
  *  lwis_base_probe: Create a device instance for each of the LWIS device.
  */
diff --git a/lwis_device.h b/lwis_device.h
index 5b774e8..1cfa5c4 100644
--- a/lwis_device.h
+++ b/lwis_device.h
@@ -235,6 +235,7 @@ struct lwis_device {
 	struct dentry *dbg_event_file;
 	struct dentry *dbg_transaction_file;
 	struct dentry *dbg_buffer_file;
+	struct dentry *dbg_reg_io_file;
 #endif
 	/* Structure to store info to help debugging device data */
 	struct lwis_device_debug_info debug_info;
@@ -412,6 +413,13 @@ void lwis_device_info_dump(const char *name, void (*func)(struct lwis_device *))
 void lwis_device_crash_info_dump(struct lwis_device *lwis_dev);
 
 /*
+ * lwis_save_register_io_info: Saves the register io info in a history buffer
+ * for better debugability.
+ */
+void lwis_save_register_io_info(struct lwis_device *lwis_dev, struct lwis_io_entry *io_entry,
+                                size_t access_size);
+
+/*
  * lwis_process_worker_queue:
  * Function to process the transaction process queue and
  * periodic io queue on the transaction thread
diff --git a/lwis_device_i2c.c b/lwis_device_i2c.c
index 2f78278..da2e6d0 100644
--- a/lwis_device_i2c.c
+++ b/lwis_device_i2c.c
@@ -10,7 +10,6 @@
 
 #define pr_fmt(fmt) KBUILD_MODNAME "-i2c-dev: " fmt
 
-#include "lwis_debug.h"
 #include "lwis_device_i2c.h"
 
 #include <linux/device.h>
@@ -25,6 +24,7 @@
 #include <linux/slab.h>
 #include <uapi/linux/sched/types.h>
 
+#include "lwis_device.h"
 #include "lwis_i2c.h"
 #include "lwis_init.h"
 #include "lwis_periodic_io.h"
@@ -139,7 +139,7 @@ static int lwis_i2c_register_io(struct lwis_device *lwis_dev, struct lwis_io_ent
 	if (in_interrupt()) {
 		return -EAGAIN;
 	}
-	lwis_debug_save_register_io_to_history(lwis_dev, entry, access_size);
+	lwis_save_register_io_info(lwis_dev, entry, access_size);
 
 	return lwis_i2c_io_entry_rw(i2c_dev, entry);
 }
diff --git a/lwis_device_ioreg.c b/lwis_device_ioreg.c
index 59187c9..c6fa44c 100644
--- a/lwis_device_ioreg.c
+++ b/lwis_device_ioreg.c
@@ -10,7 +10,6 @@
 
 #define pr_fmt(fmt) KBUILD_MODNAME "-ioreg-dev: " fmt
 
-#include "lwis_debug.h"
 #include "lwis_device_ioreg.h"
 
 #include <linux/device.h>
@@ -69,7 +68,7 @@ static int lwis_ioreg_device_disable(struct lwis_device *lwis_dev)
 static int lwis_ioreg_register_io(struct lwis_device *lwis_dev, struct lwis_io_entry *entry,
 				  int access_size)
 {
-	lwis_debug_save_register_io_to_history(lwis_dev, entry, access_size);
+	lwis_save_register_io_info(lwis_dev, entry, access_size);
 	return lwis_ioreg_io_entry_rw((struct lwis_ioreg_device *)lwis_dev, entry, access_size);
 }
 
diff --git a/lwis_device_top.c b/lwis_device_top.c
index 3175173..449936b 100644
--- a/lwis_device_top.c
+++ b/lwis_device_top.c
@@ -10,11 +10,7 @@
 
 #define pr_fmt(fmt) KBUILD_MODNAME "-top-dev: " fmt
 
-#include "lwis_debug.h"
 #include "lwis_device_top.h"
-#include "lwis_event.h"
-#include "lwis_init.h"
-#include "lwis_util.h"
 
 #include <linux/device.h>
 #include <linux/init.h>
@@ -24,6 +20,11 @@
 #include <linux/platform_device.h>
 #include <linux/slab.h>
 
+#include "lwis_device.h"
+#include "lwis_event.h"
+#include "lwis_init.h"
+#include "lwis_util.h"
+
 #ifdef CONFIG_OF
 #include "lwis_dt.h"
 #endif
@@ -392,7 +393,7 @@ static int lwis_top_register_io(struct lwis_device *lwis_dev, struct lwis_io_ent
 		dev_err(top_dev->base_dev.dev, "IO entry is NULL.\n");
 		return -EINVAL;
 	}
-	lwis_debug_save_register_io_to_history(lwis_dev, entry, access_size);
+	lwis_save_register_io_info(lwis_dev, entry, access_size);
 
 	if (entry->type == LWIS_IO_ENTRY_READ) {
 		if (entry->rw.offset >= SCRATCH_MEMORY_SIZE) {
diff --git a/lwis_ioreg.c b/lwis_ioreg.c
index 0a8478c..90870aa 100644
--- a/lwis_ioreg.c
+++ b/lwis_ioreg.c
@@ -17,6 +17,7 @@
 
 #include "lwis_device.h"
 #include "lwis_ioreg.h"
+#include "lwis_util.h"
 
 static int find_block_idx_by_name(struct lwis_ioreg_list *list, char *name)
 {
@@ -589,4 +590,4 @@ int lwis_ioreg_set_io_barrier(struct lwis_ioreg_device *ioreg_dev, bool use_read
 		dma_wmb();
 	}
 	return 0;
-}
+}
\ No newline at end of file
diff --git a/platform/anchorage/lwis_platform_anchorage.c b/platform/anchorage/lwis_platform_anchorage.c
index 26355f9..c01b8c6 100644
--- a/platform/anchorage/lwis_platform_anchorage.c
+++ b/platform/anchorage/lwis_platform_anchorage.c
@@ -80,6 +80,8 @@ static int lwis_iommu_fault_handler(struct iommu_fault *fault, void *param)
 	pr_err("\n");
 	lwis_debug_print_transaction_info(lwis_dev);
 	pr_err("\n");
+	lwis_debug_print_register_io_history(lwis_dev);
+	pr_err("\n");
 	lwis_debug_print_event_states_info(lwis_dev, /*lwis_event_dump_cnt=*/-1);
 	pr_err("\n");
 	lwis_debug_print_buffer_info(lwis_dev);
diff --git a/platform/busan/lwis_platform_busan.c b/platform/busan/lwis_platform_busan.c
index a34f892..2dd543f 100644
--- a/platform/busan/lwis_platform_busan.c
+++ b/platform/busan/lwis_platform_busan.c
@@ -77,6 +77,8 @@ static int lwis_iommu_fault_handler(struct iommu_fault *fault, void *param)
 	pr_err("\n");
 	lwis_debug_print_transaction_info(lwis_dev);
 	pr_err("\n");
+	lwis_debug_print_register_io_history(lwis_dev);
+	pr_err("\n");
 	lwis_debug_print_event_states_info(lwis_dev, /*lwis_event_dump_cnt=*/-1);
 	pr_err("\n");
 	lwis_debug_print_buffer_info(lwis_dev);