[PATCH] tty/serial: create debugfs interface for UART register tracing

[PATCH] tty/serial: create debugfs interface for UART register tracing

[Dan Raymond]

Implement a UART register tracing facility using the debugfs.  This can be
used as a "serial port sniffer" to monitor UART traffic and line settings
with timestamps at microsecond granularity.  This can be useful for general
serial port debugging or to debug the UART driver itself.

Signed-off-by: Dan Raymond<draymond@foxvalley.net>
---
diff -uprN -X a/Documentation/dontdiff a/drivers/tty/serial/8250/8250.h b/drivers/tty/serial/8250/8250.h
--- a/drivers/tty/serial/8250/8250.h	2022-11-16 02:04:15.000000000 -0700
+++ b/drivers/tty/serial/8250/8250.h	2023-08-21 16:15:51.429933400 -0600
@@ -403,3 +403,6 @@ static inline int serial_index(struct ua
  {
  	return port->minor - 64;
  }
+
+extern void uart_debug_create(struct uart_port *port);
+extern void uart_debug_destroy(struct uart_port *port);
diff -uprN -X a/Documentation/dontdiff a/drivers/tty/serial/8250/8250_core.c b/drivers/tty/serial/8250/8250_core.c
--- a/drivers/tty/serial/8250/8250_core.c	2022-11-16 02:04:15.000000000 -0700
+++ b/drivers/tty/serial/8250/8250_core.c	2023-08-21 16:16:47.502740700 -0600
@@ -1094,6 +1094,7 @@ int serial8250_register_8250_port(const
  			if (ret)
  				goto err;
  
+			uart_debug_create(&uart->port);
  			ret = uart->port.line;
  		} else {
  			dev_info(uart->port.dev,
@@ -1151,6 +1152,7 @@ void serial8250_unregister_port(int line
  		spin_unlock_irqrestore(&uart->port.lock, flags);
  	}
  
+	uart_debug_destroy(&uart->port);
  	uart_remove_one_port(&serial8250_reg, &uart->port);
  	if (serial8250_isa_devs) {
  		uart->port.flags &= ~UPF_BOOT_AUTOCONF;
diff -uprN -X a/Documentation/dontdiff a/drivers/tty/serial/8250/8250_debug.c b/drivers/tty/serial/8250/8250_debug.c
--- a/drivers/tty/serial/8250/8250_debug.c	1969-12-31 17:00:00.000000000 -0700
+++ b/drivers/tty/serial/8250/8250_debug.c	2023-08-22 13:19:12.234454600 -0600
@@ -0,0 +1,519 @@
+// SPDX-License-Identifier: GPL-2.0+
+/*
+ *  This module creates a debugfs interface that can be used to hook the low level serial
+ *  I/O routines and generate timestamped traces of UART register reads and writes.  This
+ *  feature provides an accurate and reliable "serial port sniffer" that can be used for
+ *  debugging problems with the serial port.
+ *
+ *  Each serial port ("ttyS0", "ttyS1", etc.) will have its own directory in the root of
+ *  the debug filesystem.  Inside each directory will be the following pseudo-files:
+ *
+ *  trace_all    - toggles tracing of all registers vs. just the RX/TX registers
+ *  trace_buffer - for consuming the trace data
+ *  trace_enable - enables/disables tracing
+ *  trace_size   - configures the size of the trace buffer
+ *
+ *  When tracing is disabled there will be zero impact to the operation of the UART
+ *  driver.  When tracing is enabled a small cost will be incurred after every register
+ *  access to write an entry to the trace buffer in RAM.  The buffer size is limited
+ *  only by the amount of virtual memory available to the kernel.  This is 128 MiB by
+ *  default but it can be increased using vmalloc=xxx on the kernel command line.  The
+ *  memory will be freed after tracing is disabled and all data in the buffer has been
+ *  consumed.
+ *
+ *  Example session:
+ *
+ *  > mount -t debugfs debugfs /sys/kernel/debug
+ *  > echo '1' > /sys/kernel/debug/ttyS1/trace_all
+ *  > echo '1' > /sys/kernel/debug/ttyS1/trace_enable
+ *
+ *  (perform UART operation)
+ *
+ *  > cat /sys/kernel/debug/ttyS1/trace_buffer
+ *
+ *  00:03:04.822166  IER <- 07
+ *  00:03:04.822175  IIR -> C2
+ *  00:03:04.822177  LSR -> 60
+ *  00:03:04.822178  MSR -> 00
+ *  00:03:04.822180  THR <- C9
+ *  00:03:04.822184  IER <- 05
+ *  00:03:04.822185  IIR -> C1
+ *  00:03:05.062943  IIR -> CC
+ *  00:03:05.062945  LSR -> 61
+ *  00:03:05.062948  RBR -> C9
+ *  00:03:05.062950  LSR -> 61
+ *  00:03:05.062952  RBR -> ED
+ *  00:03:05.062953  LSR -> 61
+ *  00:03:05.062954  RBR -> 00
+ *  00:03:05.062955  LSR -> 60
+ *  00:03:05.062965  MSR -> 00
+ *  00:03:05.062967  IIR -> C1
+ */
+
+#include <linux/cpufreq.h>
+#include <linux/debugfs.h>
+#include <linux/fs.h>
+#include <linux/math64.h>
+#include <linux/serial_8250.h>
+
+struct reg_event {
+	uint32_t  cycle_lo;  /* CPU cycle count (lower 32-bits) */
+	uint16_t  cycle_hi;  /* CPU cycle count (upper 16-bits) */
+	uint8_t   access;    /* write flag + register number */
+	uint8_t   data;      /* register data */
+};
+
+struct reg_queue {
+	uint32_t          read_idx;   /* first full (written) slot */
+	uint32_t          write_idx;  /* first empty (unwritten) slot */
+	struct reg_event *buf;        /* array to hold the data */
+	uint32_t          size;       /* array size (number of entries - must be power of 2) */
+	bool              wrap;       /* true if write_idx wrapped around and reached read_idx */
+};
+
+struct uart_debug {
+	spinlock_t        lock;
+	struct mutex      mutex;
+	bool              trace_enable;
+	bool              trace_all;
+	uint32_t          trace_size;
+	unsigned int      (*original_serial_in)(struct uart_port *p, int offset);
+	void              (*original_serial_out)(struct uart_port *p, int offset, int value);
+	struct reg_queue  register_queue;
+	char              line[64];  /* buffer to hold text of last item removed from queue */
+	uint32_t          offset;    /* offset of first unread byte in line */
+};
+
+static ssize_t      all_read(struct file *filp, char __user *buf, size_t size, loff_t *ppos);
+static ssize_t      all_write(struct file *filp,
+			const char __user *buf, size_t size, loff_t *ppos);
+static ssize_t      buffer_read(struct file *filp, char __user *buf, size_t size, loff_t *ppos);
+static ssize_t      enable_read(struct file *filp, char __user *buf, size_t size, loff_t *ppos);
+static ssize_t      enable_write(struct file *filp,
+			const char __user *buf, size_t size, loff_t *ppos);
+static void         format_cycle(uint64_t cpu_cycles, char *buf, uint32_t size);
+static void         queue_add(struct uart_port *port, uint8_t reg, uint8_t data, bool write);
+static bool         queue_alloc(struct uart_port *port);
+static void         queue_free(struct uart_port *port, bool force);
+static void         queue_remove(struct uart_port *port, char *buf, uint32_t size);
+static unsigned int serial_in_wrapper(struct uart_port *port, int offset);
+static void         serial_out_wrapper(struct uart_port *port, int offset, int value);
+static ssize_t      size_read(struct file *filp, char __user *buf, size_t size, loff_t *ppos);
+static ssize_t      size_write(struct file *filp,
+			const char __user *buf, size_t size, loff_t *ppos);
+
+static const struct file_operations all_fops = {
+	.open  = simple_open,
+	.read  = all_read,
+	.write = all_write,
+};
+
+static const struct file_operations buffer_fops = {
+	.open = simple_open,
+	.read = buffer_read,
+};
+
+static const struct file_operations enable_fops = {
+	.open  = simple_open,
+	.read  = enable_read,
+	.write = enable_write,
+};
+
+static const struct file_operations size_fops = {
+	.open  = simple_open,
+	.read  = size_read,
+	.write = size_write,
+};
+
+/*
+ *  Handle reads from the 'trace_all' pseudo-file.  Report the state of the trace_all flag.
+ */
+static ssize_t all_read(struct file *filp, char __user *buf, size_t size, loff_t *ppos)
+{
+	struct uart_port *port = filp->private_data;
+	struct uart_debug *uart_debug = port->private_data;
+	char text[16];
+	uint32_t len;
+
+	len = snprintf(text, sizeof(text), "%u\n", uart_debug->trace_all);
+	return simple_read_from_buffer(buf, size, ppos, text, len);
+}
+
+/*
+ *  Handle writes to the 'trace_all' pseudo-file.  Set the state of the trace_all flag.
+ */
+static ssize_t all_write(struct file *filp, const char __user *buf, size_t size, loff_t *ppos)
+{
+	struct uart_port *port = filp->private_data;
+	struct uart_debug *uart_debug = port->private_data;
+	int error;
+
+	error = kstrtobool_from_user(buf, size, &uart_debug->trace_all);
+	if (error)
+		return error;
+
+	return size;
+}
+
+/*
+ *  Handle reads from the 'trace_buffer' pseudo-file.  This function consumes content in
+ *  the register event queue.  A best effort will be made to avoid splitting lines of text.
+ */
+static ssize_t buffer_read(struct file *filp, char __user *buf, size_t size, loff_t *ppos)
+{
+	struct uart_port *port = filp->private_data;
+	struct uart_debug *uart_debug = port->private_data;
+	uint32_t len, num_bytes, total_bytes = 0;
+	const char *ptr;
+	int error = 0;
+
+	if (mutex_lock_interruptible(&uart_debug->mutex))
+		return -ERESTARTSYS;
+
+	while (size) {
+		if (uart_debug->line[uart_debug->offset] == '\0') {
+			uart_debug->offset = 0;
+			queue_remove(port, uart_debug->line, sizeof(uart_debug->line));
+			if (uart_debug->line[0] == '\0')
+				break;
+		}
+
+		ptr = uart_debug->line + uart_debug->offset;
+		len = strlen(ptr);
+		num_bytes = (size < len) ? size : len;
+
+		if (num_bytes < len && total_bytes)
+			break;
+		if (copy_to_user(buf, ptr, num_bytes)) {
+			error = -EFAULT;
+			break;
+		}
+
+		buf += num_bytes;
+		size -= num_bytes;
+		total_bytes += num_bytes;
+		uart_debug->offset += num_bytes;
+	}
+
+	if (!uart_debug->trace_enable)
+		queue_free(port, false);
+
+	mutex_unlock(&uart_debug->mutex);
+	if (error)
+		return total_bytes ? total_bytes : error;
+	return total_bytes;
+}
+
+/*
+ *  Handle reads from the 'trace_enable' pseudo-file.  Report the current state of the
+ *  trace_enable flag.
+ */
+static ssize_t enable_read(struct file *filp, char __user *buf, size_t size, loff_t *ppos)
+{
+	struct uart_port *port = filp->private_data;
+	struct uart_debug *uart_debug = port->private_data;
+	char text[16];
+	uint32_t len;
+
+	len = snprintf(text, sizeof(text), "%u\n", uart_debug->trace_enable);
+	return simple_read_from_buffer(buf, size, ppos, text, len);
+}
+
+/*
+ *  Handle writes to the 'trace_enable' pseudo-file.  When tracing is enabled allocate
+ *  memory for the register event queue and install our hooks.  When tracing is disabled
+ *  remove our hooks and free the memory used by the register event queue if it is empty.
+ */
+static ssize_t enable_write(struct file *filp, const char __user *buf, size_t size, loff_t *ppos)
+{
+	struct uart_port *port = filp->private_data;
+	struct uart_debug *uart_debug = port->private_data;
+	bool trace_enable;
+	int error;
+
+	error = kstrtobool_from_user(buf, size, &trace_enable);
+	if (error)
+		return error;
+
+	if (mutex_lock_interruptible(&uart_debug->mutex))
+		return -ERESTARTSYS;
+	if (trace_enable == uart_debug->trace_enable)
+		goto exit;
+
+	if (trace_enable) {
+		uart_debug->line[0] = '\0';
+		uart_debug->offset = 0;
+		queue_free(port, true);
+		if (!queue_alloc(port))
+			goto exit;
+
+		uart_debug->original_serial_out = port->serial_out;
+		uart_debug->original_serial_in  = port->serial_in;
+		port->serial_out = serial_out_wrapper;
+		port->serial_in  = serial_in_wrapper;
+	} else {
+		port->serial_out = uart_debug->original_serial_out;
+		port->serial_in  = uart_debug->original_serial_in;
+
+		queue_free(port, false);
+	}
+
+	uart_debug->trace_enable = trace_enable;
+exit:
+	mutex_unlock(&uart_debug->mutex);
+	return size;
+}
+
+/*
+ *  Convert 'cpu_cycles' to a string that reports the time elapsed since boot in
+ *  hours/mins/seconds/microseconds.
+ */
+static void format_cycle(uint64_t cpu_cycles, char *buf, uint32_t size)
+{
+	static uint64_t cpu_freq;  /* cycles per second */
+	uint32_t h, m, s, us;
+
+	if (cpu_freq == 0)
+		cpu_freq = arch_freq_get_on_cpu(0) * 1000ULL;
+
+	s = div64_u64_rem(cpu_cycles, cpu_freq, &cpu_cycles);
+	us = div64_u64(cpu_cycles * 1000 * 1000 + 500 * 1000, cpu_freq);
+
+	m = s / 60; s = s % 60;
+	h = m / 60; m = m % 60;
+
+	snprintf(buf, size, "%02d:%02d:%02d.%06u", h, m, s, us);
+}
+
+/*
+ *  Add an entry to the register event queue.  This can run in interrupt context
+ *  so it needs to be as fast as possible.
+ */
+static void queue_add(struct uart_port *port, uint8_t reg, uint8_t data, bool write)
+{
+	struct uart_debug *uart_debug = port->private_data;
+	struct reg_queue *queue = &uart_debug->register_queue;
+	uint64_t cpu_cycle;
+	struct reg_event event;
+	unsigned long flags;
+
+	if (!uart_debug->trace_all && reg != 0x00)
+		return;
+
+	cpu_cycle      = rdtsc();
+	event.cycle_lo = (uint32_t)cpu_cycle;
+	event.cycle_hi = (uint16_t)(cpu_cycle >> 32);
+	event.access   = (write ? 0x08 : 0x00) | reg;
+	event.data     = data;
+
+	spin_lock_irqsave(&uart_debug->lock, flags);
+
+	queue->buf[queue->write_idx & (queue->size - 1)] = event;
+	queue->write_idx++;
+
+	if (queue->write_idx == queue->read_idx)
+		queue->wrap = true;
+
+	spin_unlock_irqrestore(&uart_debug->lock, flags);
+}
+
+/*
+ *  Allocate memory for the register event queue.  We use vmalloc() instead of kmalloc()
+ *  because we don't need physically contiguous memory and kmalloc() is limited to 4 MiB.
+ *  If memory allocation fails we will try again with a smaller buffer.  The user can
+ *  detect this by reading 'trace_size' after enabling tracing.
+ */
+static bool queue_alloc(struct uart_port *port)
+{
+	struct uart_debug *uart_debug = port->private_data;
+	struct reg_queue *queue = &uart_debug->register_queue;
+
+	queue->size = uart_debug->trace_size;
+	queue->buf = vmalloc(queue->size * sizeof(struct reg_event));
+
+	while (queue->buf == NULL) {
+		queue->size >>= 1;
+		if (queue->size == 0)
+			return false;
+		queue->buf = vmalloc(queue->size * sizeof(struct reg_event));
+	}
+
+	uart_debug->trace_size = queue->size;
+	return true;
+}
+
+/*
+ *  Free the memory used by the register event queue if the queue is empty.  If the 'force'
+ *  flag is 'true' free the memory even if the queue is not empty.
+ *
+ *  The noinline attribute suppresses a bug in gcc 11.3.0 that generates a bogus error:
+ *
+ *  error: ‘__builtin_memset’ offset [0, 19] is out of the bounds [0, 0] [-Werror=array-bounds]
+ */
+static noinline void queue_free(struct uart_port *port, bool force)
+{
+	struct uart_debug *uart_debug = port->private_data;
+	struct reg_queue *queue = &uart_debug->register_queue;
+
+	if (force || queue->read_idx == queue->write_idx) {
+		vfree(queue->buf);
+		memset(queue, 0, sizeof(*queue));
+	}
+}
+
+/*
+ *  Remove an entry from the register event queue.  The entry will be converted to a text
+ *  string and written to the caller's buffer.  If no entries are available an empty string
+ *  will be written.
+ */
+static void queue_remove(struct uart_port *port, char *buf, uint32_t size)
+{
+	struct uart_debug *uart_debug = port->private_data;
+	struct reg_queue *queue = &uart_debug->register_queue;
+	struct reg_event event;
+	const char * const in_regs[]  = { "RBR", "IER", "IIR", "LCR", "MCR", "LSR", "MSR", "SCR" };
+	const char * const out_regs[] = { "THR", "IER", "FCR", "LCR", "MCR", "LSR", "MSR", "SCR" };
+	uint8_t reg;
+	const char *sym, *dir;
+	char elapsed[sizeof("hh:mm:ss.mmmuuu")];
+	uint32_t num_events, events_lost;
+	unsigned long flags;
+
+	spin_lock_irqsave(&uart_debug->lock, flags);
+
+	num_events = queue->write_idx - queue->read_idx;
+	events_lost = num_events > queue->size ? num_events - queue->size : 0;
+	events_lost = queue->wrap ? 0xFFFFFFFF : events_lost;
+
+	if (events_lost) {
+		queue->read_idx += num_events - queue->size;
+		queue->wrap = false;
+	} else if (num_events) {
+		event = queue->buf[queue->read_idx & (queue->size - 1)];
+		queue->read_idx++;
+	}
+
+	spin_unlock_irqrestore(&uart_debug->lock, flags);
+
+	if (events_lost) {
+		snprintf(buf, size, "queue overflow (%u events lost)\n", events_lost);
+	} else if (num_events) {
+		reg = event.access & 0x07;
+		sym = event.access & 0x08 ? out_regs[reg] : in_regs[reg];
+		dir = event.access & 0x08 ? "<-" : "->";
+		format_cycle((((uint64_t)event.cycle_hi << 32) | event.cycle_lo),
+			elapsed, sizeof(elapsed));
+		snprintf(buf, size, "%s  %s %s %02X\n", elapsed, sym, dir, event.data);
+	} else if (size) {
+		buf[0] = '\0';
+	}
+}
+
+/*
+ *  This is the hook we install for register reads when tracing is enabled.  It calls
+ *  the original serial_in function and logs the read to the register event queue.
+ */
+static unsigned int serial_in_wrapper(struct uart_port *port, int offset)
+{
+	struct uart_debug *uart_debug = port->private_data;
+	uint8_t value;
+
+	value = uart_debug->original_serial_in(port, offset);
+	queue_add(port, offset, value, false);
+	return value;
+}
+
+/*
+ *  This is the hook we install for register writes when tracing is enabled.  It calls
+ *  the original serial_out function and logs the write to the register event queue.
+ */
+static void serial_out_wrapper(struct uart_port *port, int offset, int value)
+{
+	struct uart_debug *uart_debug = port->private_data;
+
+	uart_debug->original_serial_out(port, offset, value);
+	queue_add(port, offset, value, true);
+}
+
+/*
+ *  Handle reads from the 'trace_size' pseudo-file.  Report the configured trace size.
+ *  If it changes between (partial) reads then the output will likely be corrupted.  The
+ *  only way to fix this is to store the text buffer in the file private data.  Users
+ *  should be encouraged to provide a buffer large enough to read the entire value at once.
+ */
+static ssize_t size_read(struct file *filp, char __user *buf, size_t size, loff_t *ppos)
+{
+	struct uart_port *port = filp->private_data;
+	struct uart_debug *uart_debug = port->private_data;
+	char text[16];
+	uint32_t len;
+
+	len = snprintf(text, sizeof(text), "%u\n", uart_debug->trace_size);
+	return simple_read_from_buffer(buf, size, ppos, text, len);
+}
+
+/*
+ *  Handle writes to the 'trace_size' pseudo-file.  Set the configured trace size (maximum
+ *  number of log entries).
+ */
+static ssize_t size_write(struct file *filp, const char __user *buf, size_t size, loff_t *ppos)
+{
+	struct uart_port *port = filp->private_data;
+	struct uart_debug *uart_debug = port->private_data;
+	uint32_t trace_size, rounded_size = 1;
+	int error;
+
+	error = kstrtouint_from_user(buf, size, 0, &trace_size);
+	if (error)
+		return error;
+
+	if (trace_size == 0)
+		return -EINVAL;
+	while (trace_size >>= 1)
+		rounded_size <<= 1;  /* round down to nearest power of 2 */
+	uart_debug->trace_size = rounded_size;
+	return size;
+}
+
+/*
+ *  Create the debugfs interface.  This should be called during port registration after
+ *  port->name, port->serial_in, and port->serial_out have been initialized.  We are
+ *  using port->private_data to store a pointer to our data structure.  That field appears
+ *  to be otherwise unused.  If this is wrong we will need to create a new field.
+ */
+void uart_debug_create(struct uart_port *port)
+{
+	struct uart_debug *uart_debug;
+	struct dentry *dir;
+
+	uart_debug = port->private_data = kzalloc(sizeof(struct uart_debug), GFP_KERNEL);
+	if (uart_debug == NULL)
+		return;
+
+	spin_lock_init(&uart_debug->lock);
+	mutex_init(&uart_debug->mutex);
+	uart_debug->trace_size = 4096;
+
+	dir = debugfs_create_dir(port->name, NULL);  /* ie. "ttyS0" */
+	debugfs_create_file("trace_all",    0644, dir, port, &all_fops);
+	debugfs_create_file("trace_buffer", 0444, dir, port, &buffer_fops);
+	debugfs_create_file("trace_enable", 0644, dir, port, &enable_fops);
+	debugfs_create_file("trace_size",   0644, dir, port, &size_fops);
+}
+
+/*
+ *  Destroy the debugfs interface.  This should be called during port deregistration.
+ */
+void uart_debug_destroy(struct uart_port *port)
+{
+	struct uart_debug *uart_debug;
+
+	uart_debug = port->private_data;
+	port->private_data = NULL;
+
+	if (uart_debug) {
+		debugfs_lookup_and_remove(port->name, NULL);  /* ie. "ttyS0 */
+		queue_free(port, true);
+		kfree(uart_debug);
+	}
+}
diff -uprN -X a/Documentation/dontdiff a/drivers/tty/serial/8250/Makefile b/drivers/tty/serial/8250/Makefile
--- a/drivers/tty/serial/8250/Makefile	2022-11-16 02:04:15.000000000 -0700
+++ b/drivers/tty/serial/8250/Makefile	2023-08-21 16:17:11.835722200 -0600
@@ -8,7 +8,7 @@ obj-$(CONFIG_SERIAL_8250)		+= 8250.o 825
  8250-$(CONFIG_ALPHA_GENERIC)		+= 8250_alpha.o
  8250-$(CONFIG_ALPHA_JENSEN)		+= 8250_alpha.o
  8250-$(CONFIG_SERIAL_8250_PNP)		+= 8250_pnp.o
-8250_base-y				:= 8250_port.o
+8250_base-y				:= 8250_port.o 8250_debug.o
  8250_base-$(CONFIG_SERIAL_8250_DMA)	+= 8250_dma.o
  8250_base-$(CONFIG_SERIAL_8250_DWLIB)	+= 8250_dwlib.o
  8250_base-$(CONFIG_SERIAL_8250_FINTEK)	+= 8250_fintek.o

Re: [PATCH] tty/serial: create debugfs interface for UART register tracing

[Greg KH]

On Tue, Aug 22, 2023 at 02:50:45PM -0600, Dan Raymond wrote:
> Implement a UART register tracing facility using the debugfs.  This can be
> used as a "serial port sniffer" to monitor UART traffic and line settings
> with timestamps at microsecond granularity.  This can be useful for general
> serial port debugging or to debug the UART driver itself.

Nice!

Some comments on the patch:

> Signed-off-by: Dan Raymond<draymond@foxvalley.net>

Nit, you need a ' ' before the '<' character.

> ---
> diff -uprN -X a/Documentation/dontdiff a/drivers/tty/serial/8250/8250.h b/drivers/tty/serial/8250/8250.h
> --- a/drivers/tty/serial/8250/8250.h	2022-11-16 02:04:15.000000000 -0700
> +++ b/drivers/tty/serial/8250/8250.h	2023-08-21 16:15:51.429933400 -0600
> @@ -403,3 +403,6 @@ static inline int serial_index(struct ua
>  {
>  	return port->minor - 64;
>  }
> +
> +extern void uart_debug_create(struct uart_port *port);
> +extern void uart_debug_destroy(struct uart_port *port);

This really should be a Kconfig option as some people will not want the
added size, or feature, in their system as many serial ports have data
that other users, even root ones, shouldn't be snooping on (i.e.
cell modems.)

> diff -uprN -X a/Documentation/dontdiff a/drivers/tty/serial/8250/8250_core.c b/drivers/tty/serial/8250/8250_core.c
> --- a/drivers/tty/serial/8250/8250_core.c	2022-11-16 02:04:15.000000000 -0700
> +++ b/drivers/tty/serial/8250/8250_core.c	2023-08-21 16:16:47.502740700 -0600
> @@ -1094,6 +1094,7 @@ int serial8250_register_8250_port(const
>  			if (ret)
>  				goto err;
> +			uart_debug_create(&uart->port);
>  			ret = uart->port.line;
>  		} else {
>  			dev_info(uart->port.dev,
> @@ -1151,6 +1152,7 @@ void serial8250_unregister_port(int line
>  		spin_unlock_irqrestore(&uart->port.lock, flags);
>  	}
> +	uart_debug_destroy(&uart->port);
>  	uart_remove_one_port(&serial8250_reg, &uart->port);
>  	if (serial8250_isa_devs) {
>  		uart->port.flags &= ~UPF_BOOT_AUTOCONF;
> diff -uprN -X a/Documentation/dontdiff a/drivers/tty/serial/8250/8250_debug.c b/drivers/tty/serial/8250/8250_debug.c
> --- a/drivers/tty/serial/8250/8250_debug.c	1969-12-31 17:00:00.000000000 -0700
> +++ b/drivers/tty/serial/8250/8250_debug.c	2023-08-22 13:19:12.234454600 -0600
> @@ -0,0 +1,519 @@
> +// SPDX-License-Identifier: GPL-2.0+
> +/*
> + *  This module creates a debugfs interface that can be used to hook the low level serial
> + *  I/O routines and generate timestamped traces of UART register reads and writes.  This
> + *  feature provides an accurate and reliable "serial port sniffer" that can be used for
> + *  debugging problems with the serial port.

Can you wrap comments at 80 columns please?  Code is fine to go to 100.

> + *
> + *  Each serial port ("ttyS0", "ttyS1", etc.) will have its own directory in the root of
> + *  the debug filesystem.  Inside each directory will be the following pseudo-files:
> + *
> + *  trace_all    - toggles tracing of all registers vs. just the RX/TX registers

So 0 is just rx/tx?

> + *  trace_buffer - for consuming the trace data
> + *  trace_enable - enables/disables tracing
> + *  trace_size   - configures the size of the trace buffer

This should be documented somewhere in Documentation/ OR better yet, in
kernel doc format so that when building the documentation, it sucks it
in from this file to be included there automatically.

And what are the default values of these files at boot?

> + *
> + *  When tracing is disabled there will be zero impact to the operation of the UART
> + *  driver.  When tracing is enabled a small cost will be incurred after every register
> + *  access to write an entry to the trace buffer in RAM.  The buffer size is limited
> + *  only by the amount of virtual memory available to the kernel.  This is 128 MiB by
> + *  default but it can be increased using vmalloc=xxx on the kernel command line.  The
> + *  memory will be freed after tracing is disabled and all data in the buffer has been
> + *  consumed.
> + *
> + *  Example session:
> + *
> + *  > mount -t debugfs debugfs /sys/kernel/debug
> + *  > echo '1' > /sys/kernel/debug/ttyS1/trace_all
> + *  > echo '1' > /sys/kernel/debug/ttyS1/trace_enable

Any reason why you didn't just use the existing kernel tracing facility
for all of this?

> + *
> + *  (perform UART operation)
> + *
> + *  > cat /sys/kernel/debug/ttyS1/trace_buffer
> + *
> + *  00:03:04.822166  IER <- 07
> + *  00:03:04.822175  IIR -> C2
> + *  00:03:04.822177  LSR -> 60
> + *  00:03:04.822178  MSR -> 00
> + *  00:03:04.822180  THR <- C9
> + *  00:03:04.822184  IER <- 05
> + *  00:03:04.822185  IIR -> C1
> + *  00:03:05.062943  IIR -> CC
> + *  00:03:05.062945  LSR -> 61
> + *  00:03:05.062948  RBR -> C9
> + *  00:03:05.062950  LSR -> 61
> + *  00:03:05.062952  RBR -> ED
> + *  00:03:05.062953  LSR -> 61
> + *  00:03:05.062954  RBR -> 00
> + *  00:03:05.062955  LSR -> 60
> + *  00:03:05.062965  MSR -> 00
> + *  00:03:05.062967  IIR -> C1
> + */
> +
> +#include <linux/cpufreq.h>
> +#include <linux/debugfs.h>
> +#include <linux/fs.h>
> +#include <linux/math64.h>
> +#include <linux/serial_8250.h>
> +
> +struct reg_event {
> +	uint32_t  cycle_lo;  /* CPU cycle count (lower 32-bits) */

This is the big issue I have with this change, sorry, it's an odd one.

The use of "uintX_t" variable types belongs in userspace, these are not
kernel data types (yes, they are used in places, but no, they do not
make sense, see the many times Linus and I have talked about this in the
past, wrong namespace, etc.)

Can you change these all to the normal types of u32, u16, u8 and so on
please?


> +	uint16_t  cycle_hi;  /* CPU cycle count (upper 16-bits) */
> +	uint8_t   access;    /* write flag + register number */
> +	uint8_t   data;      /* register data */
> +};
> +
> +struct reg_queue {
> +	uint32_t          read_idx;   /* first full (written) slot */
> +	uint32_t          write_idx;  /* first empty (unwritten) slot */
> +	struct reg_event *buf;        /* array to hold the data */
> +	uint32_t          size;       /* array size (number of entries - must be power of 2) */
> +	bool              wrap;       /* true if write_idx wrapped around and reached read_idx */

If you use pahole on this structure, you will see you can get this a bit
smaller.  Although I don't think you use this a lot, right?

> +};
> +
> +struct uart_debug {
> +	spinlock_t        lock;
> +	struct mutex      mutex;

Why 2 locks?  Please document these.

> +	bool              trace_enable;
> +	bool              trace_all;
> +	uint32_t          trace_size;
> +	unsigned int      (*original_serial_in)(struct uart_port *p, int offset);
> +	void              (*original_serial_out)(struct uart_port *p, int offset, int value);
> +	struct reg_queue  register_queue;
> +	char              line[64];  /* buffer to hold text of last item removed from queue */

Why 64?

> +	uint32_t          offset;    /* offset of first unread byte in line */
> +};
> +
> +static ssize_t      all_read(struct file *filp, char __user *buf, size_t size, loff_t *ppos);
> +static ssize_t      all_write(struct file *filp,
> +			const char __user *buf, size_t size, loff_t *ppos);
> +static ssize_t      buffer_read(struct file *filp, char __user *buf, size_t size, loff_t *ppos);
> +static ssize_t      enable_read(struct file *filp, char __user *buf, size_t size, loff_t *ppos);
> +static ssize_t      enable_write(struct file *filp,
> +			const char __user *buf, size_t size, loff_t *ppos);
> +static void         format_cycle(uint64_t cpu_cycles, char *buf, uint32_t size);
> +static void         queue_add(struct uart_port *port, uint8_t reg, uint8_t data, bool write);
> +static bool         queue_alloc(struct uart_port *port);
> +static void         queue_free(struct uart_port *port, bool force);
> +static void         queue_remove(struct uart_port *port, char *buf, uint32_t size);
> +static unsigned int serial_in_wrapper(struct uart_port *port, int offset);
> +static void         serial_out_wrapper(struct uart_port *port, int offset, int value);
> +static ssize_t      size_read(struct file *filp, char __user *buf, size_t size, loff_t *ppos);
> +static ssize_t      size_write(struct file *filp,
> +			const char __user *buf, size_t size, loff_t *ppos);

Any chance to reorginize the code to not need the forward declarations?

> +/*
> + *  Handle writes to the 'trace_enable' pseudo-file.  When tracing is enabled allocate
> + *  memory for the register event queue and install our hooks.  When tracing is disabled
> + *  remove our hooks and free the memory used by the register event queue if it is empty.
> + */
> +static ssize_t enable_write(struct file *filp, const char __user *buf, size_t size, loff_t *ppos)
> +{
> +	struct uart_port *port = filp->private_data;
> +	struct uart_debug *uart_debug = port->private_data;
> +	bool trace_enable;
> +	int error;
> +
> +	error = kstrtobool_from_user(buf, size, &trace_enable);
> +	if (error)
> +		return error;
> +
> +	if (mutex_lock_interruptible(&uart_debug->mutex))
> +		return -ERESTARTSYS;
> +	if (trace_enable == uart_debug->trace_enable)
> +		goto exit;
> +
> +	if (trace_enable) {
> +		uart_debug->line[0] = '\0';
> +		uart_debug->offset = 0;
> +		queue_free(port, true);
> +		if (!queue_alloc(port))
> +			goto exit;
> +
> +		uart_debug->original_serial_out = port->serial_out;
> +		uart_debug->original_serial_in  = port->serial_in;
> +		port->serial_out = serial_out_wrapper;
> +		port->serial_in  = serial_in_wrapper;

Nice hack to make the overhead "zero" but now you have 2 function jumps
per character, on some systems that can be a lot of overhead.  Why not
just use the existing trace functionality for this instead?  If the
feature is not enabled, it will not have any overhead, and if it is, it
will only have the one call to your hook, saving you another function
call jump (which on modern processors is VERY slow thanks to spectre
issues...)

> +/*
> + *  Remove an entry from the register event queue.  The entry will be converted to a text
> + *  string and written to the caller's buffer.  If no entries are available an empty string
> + *  will be written.
> + */
> +static void queue_remove(struct uart_port *port, char *buf, uint32_t size)
> +{
> +	struct uart_debug *uart_debug = port->private_data;
> +	struct reg_queue *queue = &uart_debug->register_queue;
> +	struct reg_event event;
> +	const char * const in_regs[]  = { "RBR", "IER", "IIR", "LCR", "MCR", "LSR", "MSR", "SCR" };
> +	const char * const out_regs[] = { "THR", "IER", "FCR", "LCR", "MCR", "LSR", "MSR", "SCR" };
> +	uint8_t reg;
> +	const char *sym, *dir;
> +	char elapsed[sizeof("hh:mm:ss.mmmuuu")];
> +	uint32_t num_events, events_lost;
> +	unsigned long flags;
> +
> +	spin_lock_irqsave(&uart_debug->lock, flags);
> +
> +	num_events = queue->write_idx - queue->read_idx;
> +	events_lost = num_events > queue->size ? num_events - queue->size : 0;
> +	events_lost = queue->wrap ? 0xFFFFFFFF : events_lost;

We do have at least 2 different ringbuffer structures in the kernel, why
create another one?

Anyway, again, cool feature, I like it, but if you can tie it into the
existing trace framework better (either by using that entirely which
might be best), or at the least, putting your hook into the data path
with it, that would be best.

thanks,

greg k-h

Re: [PATCH] tty/serial: create debugfs interface for UART register tracing

[Ilpo Järvinen]

[-- Attachment #1: Type: text/plain, Size: 22057 bytes --]

On Tue, 22 Aug 2023, Dan Raymond wrote:

> Implement a UART register tracing facility using the debugfs.  This can be
> used as a "serial port sniffer" to monitor UART traffic and line settings
> with timestamps at microsecond granularity.  This can be useful for general
> serial port debugging or to debug the UART driver itself.

Thanks, looks useful (although it might have challenge in tracing hw 
during early init).

> Signed-off-by: Dan Raymond<draymond@foxvalley.net>
> ---
> diff -uprN -X a/Documentation/dontdiff a/drivers/tty/serial/8250/8250.h
> b/drivers/tty/serial/8250/8250.h
> --- a/drivers/tty/serial/8250/8250.h	2022-11-16 02:04:15.000000000 -0700
> +++ b/drivers/tty/serial/8250/8250.h	2023-08-21 16:15:51.429933400 -0600
> @@ -403,3 +403,6 @@ static inline int serial_index(struct ua
>  {
>  	return port->minor - 64;
>  }
> +
> +extern void uart_debug_create(struct uart_port *port);
> +extern void uart_debug_destroy(struct uart_port *port);
> diff -uprN -X a/Documentation/dontdiff a/drivers/tty/serial/8250/8250_core.c
> b/drivers/tty/serial/8250/8250_core.c
> --- a/drivers/tty/serial/8250/8250_core.c	2022-11-16 02:04:15.000000000
> -0700
> +++ b/drivers/tty/serial/8250/8250_core.c	2023-08-21 16:16:47.502740700
> -0600
> @@ -1094,6 +1094,7 @@ int serial8250_register_8250_port(const
>  			if (ret)
>  				goto err;
>  +			uart_debug_create(&uart->port);
>  			ret = uart->port.line;
>  		} else {
>  			dev_info(uart->port.dev,
> @@ -1151,6 +1152,7 @@ void serial8250_unregister_port(int line
>  		spin_unlock_irqrestore(&uart->port.lock, flags);
>  	}
>  +	uart_debug_destroy(&uart->port);
>  	uart_remove_one_port(&serial8250_reg, &uart->port);
>  	if (serial8250_isa_devs) {
>  		uart->port.flags &= ~UPF_BOOT_AUTOCONF;
> diff -uprN -X a/Documentation/dontdiff a/drivers/tty/serial/8250/8250_debug.c
> b/drivers/tty/serial/8250/8250_debug.c
> --- a/drivers/tty/serial/8250/8250_debug.c	1969-12-31 17:00:00.000000000
> -0700
> +++ b/drivers/tty/serial/8250/8250_debug.c	2023-08-22 13:19:12.234454600
> -0600
> @@ -0,0 +1,519 @@
> +// SPDX-License-Identifier: GPL-2.0+
> +/*
> + *  This module creates a debugfs interface that can be used to hook the low
> level serial
> + *  I/O routines and generate timestamped traces of UART register reads and
> writes.  This
> + *  feature provides an accurate and reliable "serial port sniffer" that can
> be used for
> + *  debugging problems with the serial port.
> + *
> + *  Each serial port ("ttyS0", "ttyS1", etc.) will have its own directory in
> the root of
> + *  the debug filesystem.  Inside each directory will be the following
> pseudo-files:
> + *
> + *  trace_all    - toggles tracing of all registers vs. just the RX/TX
> registers
> + *  trace_buffer - for consuming the trace data
> + *  trace_enable - enables/disables tracing
> + *  trace_size   - configures the size of the trace buffer
> + *
> + *  When tracing is disabled there will be zero impact to the operation of
> the UART
> + *  driver.  When tracing is enabled a small cost will be incurred after
> every register
> + *  access to write an entry to the trace buffer in RAM.  The buffer size is
> limited
> + *  only by the amount of virtual memory available to the kernel.  This is
> 128 MiB by
> + *  default but it can be increased using vmalloc=xxx on the kernel command
> line.  The
> + *  memory will be freed after tracing is disabled and all data in the buffer
> has been
> + *  consumed.
> + *
> + *  Example session:
> + *
> + *  > mount -t debugfs debugfs /sys/kernel/debug
> + *  > echo '1' > /sys/kernel/debug/ttyS1/trace_all
> + *  > echo '1' > /sys/kernel/debug/ttyS1/trace_enable
> + *
> + *  (perform UART operation)
> + *
> + *  > cat /sys/kernel/debug/ttyS1/trace_buffer
> + *
> + *  00:03:04.822166  IER <- 07
> + *  00:03:04.822175  IIR -> C2
> + *  00:03:04.822177  LSR -> 60
> + *  00:03:04.822178  MSR -> 00
> + *  00:03:04.822180  THR <- C9
> + *  00:03:04.822184  IER <- 05
> + *  00:03:04.822185  IIR -> C1
> + *  00:03:05.062943  IIR -> CC
> + *  00:03:05.062945  LSR -> 61
> + *  00:03:05.062948  RBR -> C9
> + *  00:03:05.062950  LSR -> 61
> + *  00:03:05.062952  RBR -> ED
> + *  00:03:05.062953  LSR -> 61
> + *  00:03:05.062954  RBR -> 00
> + *  00:03:05.062955  LSR -> 60
> + *  00:03:05.062965  MSR -> 00
> + *  00:03:05.062967  IIR -> C1
> + */
> +
> +#include <linux/cpufreq.h>
> +#include <linux/debugfs.h>
> +#include <linux/fs.h>
> +#include <linux/math64.h>
> +#include <linux/serial_8250.h>
> +
> +struct reg_event {
> +	uint32_t  cycle_lo;  /* CPU cycle count (lower 32-bits) */
> +	uint16_t  cycle_hi;  /* CPU cycle count (upper 16-bits) */
> +	uint8_t   access;    /* write flag + register number */
> +	uint8_t   data;      /* register data */

Some HW-specific registers are larger than 8 bits.

> +};

> +
> +struct reg_queue {
> +	uint32_t          read_idx;   /* first full (written) slot */
> +	uint32_t          write_idx;  /* first empty (unwritten) slot */
> +	struct reg_event *buf;        /* array to hold the data */
> +	uint32_t          size;       /* array size (number of entries - must
> be power of 2) */
> +	bool              wrap;       /* true if write_idx wrapped around and
> reached read_idx */
> +};
> +
> +struct uart_debug {
> +	spinlock_t        lock;
> +	struct mutex      mutex;
> +	bool              trace_enable;
> +	bool              trace_all;
> +	uint32_t          trace_size;
> +	unsigned int      (*original_serial_in)(struct uart_port *p, int
> offset);
> +	void              (*original_serial_out)(struct uart_port *p, int
> offset, int value);
> +	struct reg_queue  register_queue;
> +	char              line[64];  /* buffer to hold text of last item
> removed from queue */
> +	uint32_t          offset;    /* offset of first unread byte in line */
> +};
> +
> +static ssize_t      all_read(struct file *filp, char __user *buf, size_t
> size, loff_t *ppos);
> +static ssize_t      all_write(struct file *filp,
> +			const char __user *buf, size_t size, loff_t *ppos);
> +static ssize_t      buffer_read(struct file *filp, char __user *buf, size_t
> size, loff_t *ppos);
> +static ssize_t      enable_read(struct file *filp, char __user *buf, size_t
> size, loff_t *ppos);
> +static ssize_t      enable_write(struct file *filp,
> +			const char __user *buf, size_t size, loff_t *ppos);
> +static void         format_cycle(uint64_t cpu_cycles, char *buf, uint32_t
> size);
> +static void         queue_add(struct uart_port *port, uint8_t reg, uint8_t
> data, bool write);
> +static bool         queue_alloc(struct uart_port *port);
> +static void         queue_free(struct uart_port *port, bool force);
> +static void         queue_remove(struct uart_port *port, char *buf, uint32_t
> size);
> +static unsigned int serial_in_wrapper(struct uart_port *port, int offset);
> +static void         serial_out_wrapper(struct uart_port *port, int offset,
> int value);
> +static ssize_t      size_read(struct file *filp, char __user *buf, size_t
> size, loff_t *ppos);
> +static ssize_t      size_write(struct file *filp,
> +			const char __user *buf, size_t size, loff_t *ppos);
> +
> +static const struct file_operations all_fops = {
> +	.open  = simple_open,
> +	.read  = all_read,
> +	.write = all_write,
> +};
> +
> +static const struct file_operations buffer_fops = {
> +	.open = simple_open,
> +	.read = buffer_read,
> +};
> +
> +static const struct file_operations enable_fops = {
> +	.open  = simple_open,
> +	.read  = enable_read,
> +	.write = enable_write,
> +};
> +
> +static const struct file_operations size_fops = {
> +	.open  = simple_open,
> +	.read  = size_read,
> +	.write = size_write,
> +};
> +
> +/*
> + *  Handle reads from the 'trace_all' pseudo-file.  Report the state of the
> trace_all flag.
> + */
> +static ssize_t all_read(struct file *filp, char __user *buf, size_t size,
> loff_t *ppos)
> +{
> +	struct uart_port *port = filp->private_data;
> +	struct uart_debug *uart_debug = port->private_data;
> +	char text[16];
> +	uint32_t len;
> +
> +	len = snprintf(text, sizeof(text), "%u\n", uart_debug->trace_all);
> +	return simple_read_from_buffer(buf, size, ppos, text, len);
> +}
> +
> +/*
> + *  Handle writes to the 'trace_all' pseudo-file.  Set the state of the
> trace_all flag.
> + */
> +static ssize_t all_write(struct file *filp, const char __user *buf, size_t
> size, loff_t *ppos)
> +{
> +	struct uart_port *port = filp->private_data;
> +	struct uart_debug *uart_debug = port->private_data;
> +	int error;
> +
> +	error = kstrtobool_from_user(buf, size, &uart_debug->trace_all);
> +	if (error)
> +		return error;
> +
> +	return size;
> +}
> +
> +/*
> + *  Handle reads from the 'trace_buffer' pseudo-file.  This function consumes
> content in
> + *  the register event queue.  A best effort will be made to avoid splitting
> lines of text.
> + */
> +static ssize_t buffer_read(struct file *filp, char __user *buf, size_t size,
> loff_t *ppos)
> +{
> +	struct uart_port *port = filp->private_data;
> +	struct uart_debug *uart_debug = port->private_data;
> +	uint32_t len, num_bytes, total_bytes = 0;
> +	const char *ptr;
> +	int error = 0;
> +
> +	if (mutex_lock_interruptible(&uart_debug->mutex))
> +		return -ERESTARTSYS;
> +
> +	while (size) {
> +		if (uart_debug->line[uart_debug->offset] == '\0') {
> +			uart_debug->offset = 0;
> +			queue_remove(port, uart_debug->line,
> sizeof(uart_debug->line));
> +			if (uart_debug->line[0] == '\0')
> +				break;
> +		}
> +
> +		ptr = uart_debug->line + uart_debug->offset;
> +		len = strlen(ptr);

Why you need to calculate length? Shouldn't queue_remove() be able to return 
this information?

> +		num_bytes = (size < len) ? size : len;

min_t().

> +
> +		if (num_bytes < len && total_bytes)
> +			break;
> +		if (copy_to_user(buf, ptr, num_bytes)) {
> +			error = -EFAULT;
> +			break;
> +		}
> +
> +		buf += num_bytes;
> +		size -= num_bytes;
> +		total_bytes += num_bytes;
> +		uart_debug->offset += num_bytes;
> +	}
> +
> +	if (!uart_debug->trace_enable)
> +		queue_free(port, false);
> +
> +	mutex_unlock(&uart_debug->mutex);
> +	if (error)
> +		return total_bytes ? total_bytes : error;
> +	return total_bytes;

So this is same as:
	if (!total_bytes)
		return error;

	return total_bytes;

> +}
> +
> +/*
> + *  Handle reads from the 'trace_enable' pseudo-file.  Report the current
> state of the
> + *  trace_enable flag.
> + */
> +static ssize_t enable_read(struct file *filp, char __user *buf, size_t size,
> loff_t *ppos)
> +{
> +	struct uart_port *port = filp->private_data;
> +	struct uart_debug *uart_debug = port->private_data;
> +	char text[16];
> +	uint32_t len;
> +
> +	len = snprintf(text, sizeof(text), "%u\n", uart_debug->trace_enable);
> +	return simple_read_from_buffer(buf, size, ppos, text, len);
> +}
> +
> +/*
> + *  Handle writes to the 'trace_enable' pseudo-file.  When tracing is enabled
> allocate
> + *  memory for the register event queue and install our hooks.  When tracing
> is disabled
> + *  remove our hooks and free the memory used by the register event queue if
> it is empty.
> + */
> +static ssize_t enable_write(struct file *filp, const char __user *buf, size_t
> size, loff_t *ppos)
> +{
> +	struct uart_port *port = filp->private_data;
> +	struct uart_debug *uart_debug = port->private_data;
> +	bool trace_enable;
> +	int error;
> +
> +	error = kstrtobool_from_user(buf, size, &trace_enable);
> +	if (error)
> +		return error;
> +
> +	if (mutex_lock_interruptible(&uart_debug->mutex))
> +		return -ERESTARTSYS;
> +	if (trace_enable == uart_debug->trace_enable)
> +		goto exit;
> +
> +	if (trace_enable) {
> +		uart_debug->line[0] = '\0';
> +		uart_debug->offset = 0;
> +		queue_free(port, true);
> +		if (!queue_alloc(port))
> +			goto exit;
> +
> +		uart_debug->original_serial_out = port->serial_out;
> +		uart_debug->original_serial_in  = port->serial_in;
> +		port->serial_out = serial_out_wrapper;
> +		port->serial_in  = serial_in_wrapper;
> +	} else {
> +		port->serial_out = uart_debug->original_serial_out;
> +		port->serial_in  = uart_debug->original_serial_in;
> +
> +		queue_free(port, false);
> +	}
> +
> +	uart_debug->trace_enable = trace_enable;
> +exit:
> +	mutex_unlock(&uart_debug->mutex);
> +	return size;
> +}
> +
> +/*
> + *  Convert 'cpu_cycles' to a string that reports the time elapsed since boot
> in
> + *  hours/mins/seconds/microseconds.
> + */
> +static void format_cycle(uint64_t cpu_cycles, char *buf, uint32_t size)

For in-kernel interfaces, use u64 and u32, uintxx_t is for userspace 
interactions.

> +{
> +	static uint64_t cpu_freq;  /* cycles per second */
> +	uint32_t h, m, s, us;
> +
> +	if (cpu_freq == 0)
> +		cpu_freq = arch_freq_get_on_cpu(0) * 1000ULL;
> +
> +	s = div64_u64_rem(cpu_cycles, cpu_freq, &cpu_cycles);
> +	us = div64_u64(cpu_cycles * 1000 * 1000 + 500 * 1000, cpu_freq);
> +
> +	m = s / 60; s = s % 60;
> +	h = m / 60; m = m % 60;
> +
> +	snprintf(buf, size, "%02d:%02d:%02d.%06u", h, m, s, us);

seconds.us is enough. If some additional formatting is to happen, it 
should be done in userspace.

> +}
> +
> +/*
> + *  Add an entry to the register event queue.  This can run in interrupt
> context
> + *  so it needs to be as fast as possible.
> + */
> +static void queue_add(struct uart_port *port, uint8_t reg, uint8_t data, bool
> write)
> +{
> +	struct uart_debug *uart_debug = port->private_data;
> +	struct reg_queue *queue = &uart_debug->register_queue;
> +	uint64_t cpu_cycle;
> +	struct reg_event event;
> +	unsigned long flags;
> +
> +	if (!uart_debug->trace_all && reg != 0x00)
> +		return;
> +
> +	cpu_cycle      = rdtsc();
> +	event.cycle_lo = (uint32_t)cpu_cycle;
> +	event.cycle_hi = (uint16_t)(cpu_cycle >> 32);
> +	event.access   = (write ? 0x08 : 0x00) | reg;

Use defines for these literals.

> +	event.data     = data;
> +
> +	spin_lock_irqsave(&uart_debug->lock, flags);
> +
> +	queue->buf[queue->write_idx & (queue->size - 1)] = event;
> +	queue->write_idx++;
> +
> +	if (queue->write_idx == queue->read_idx)
> +		queue->wrap = true;
> +
> +	spin_unlock_irqrestore(&uart_debug->lock, flags);
> +}
> +
> +/*
> + *  Allocate memory for the register event queue.  We use vmalloc() instead
> of kmalloc()
> + *  because we don't need physically contiguous memory and kmalloc() is
> limited to 4 MiB.
> + *  If memory allocation fails we will try again with a smaller buffer.  The
> user can
> + *  detect this by reading 'trace_size' after enabling tracing.
> + */
> +static bool queue_alloc(struct uart_port *port)
> +{
> +	struct uart_debug *uart_debug = port->private_data;
> +	struct reg_queue *queue = &uart_debug->register_queue;
> +
> +	queue->size = uart_debug->trace_size;
> +	queue->buf = vmalloc(queue->size * sizeof(struct reg_event));
> +
> +	while (queue->buf == NULL) {
> +		queue->size >>= 1;
> +		if (queue->size == 0)
> +			return false;
> +		queue->buf = vmalloc(queue->size * sizeof(struct reg_event));
> +	}
> +
> +	uart_debug->trace_size = queue->size;
> +	return true;
> +}
> +
> +/*
> + *  Free the memory used by the register event queue if the queue is empty.
> If the 'force'
> + *  flag is 'true' free the memory even if the queue is not empty.
> + *
> + *  The noinline attribute suppresses a bug in gcc 11.3.0 that generates a
> bogus error:
> + *
> + *  error: ‘__builtin_memset’ offset [0, 19] is out of the bounds [0, 0]
> [-Werror=array-bounds]
> + */
> +static noinline void queue_free(struct uart_port *port, bool force)
> +{
> +	struct uart_debug *uart_debug = port->private_data;
> +	struct reg_queue *queue = &uart_debug->register_queue;
> +
> +	if (force || queue->read_idx == queue->write_idx) {

Why cannot the only place where force=true just reset the indexes before 
making the call so no force parameter is required? ...I think there's a 
bug anyway with the indexes not getting properly reset in that case.

> +		vfree(queue->buf);
> +		memset(queue, 0, sizeof(*queue));
> +	}
> +}
> +
> +/*
> + *  Remove an entry from the register event queue.  The entry will be
> converted to a text
> + *  string and written to the caller's buffer.  If no entries are available
> an empty string
> + *  will be written.
> + */
> +static void queue_remove(struct uart_port *port, char *buf, uint32_t size)
> +{
> +	struct uart_debug *uart_debug = port->private_data;
> +	struct reg_queue *queue = &uart_debug->register_queue;
> +	struct reg_event event;
> +	const char * const in_regs[]  = { "RBR", "IER", "IIR", "LCR", "MCR",
> "LSR", "MSR", "SCR" };
> +	const char * const out_regs[] = { "THR", "IER", "FCR", "LCR", "MCR",
> "LSR", "MSR", "SCR" };
> +	uint8_t reg;
> +	const char *sym, *dir;
> +	char elapsed[sizeof("hh:mm:ss.mmmuuu")];
> +	uint32_t num_events, events_lost;
> +	unsigned long flags;
> +
> +	spin_lock_irqsave(&uart_debug->lock, flags);
> +
> +	num_events = queue->write_idx - queue->read_idx;
> +	events_lost = num_events > queue->size ? num_events - queue->size : 0;
> +	events_lost = queue->wrap ? 0xFFFFFFFF : events_lost;
> +
> +	if (events_lost) {
> +		queue->read_idx += num_events - queue->size;
> +		queue->wrap = false;
> +	} else if (num_events) {
> +		event = queue->buf[queue->read_idx & (queue->size - 1)];
> +		queue->read_idx++;
> +	}
> +
> +	spin_unlock_irqrestore(&uart_debug->lock, flags);
> +
> +	if (events_lost) {
> +		snprintf(buf, size, "queue overflow (%u events lost)\n",
> events_lost);
> +	} else if (num_events) {
> +		reg = event.access & 0x07;
> +		sym = event.access & 0x08 ? out_regs[reg] : in_regs[reg];

Some uarts have registers beyond 0x07 so this doesn't seem enough.
It would be nice if the driver could provide alternative set of names for 
the registers.

> +		dir = event.access & 0x08 ? "<-" : "->";
> +		format_cycle((((uint64_t)event.cycle_hi << 32) |
> event.cycle_lo),
> +			elapsed, sizeof(elapsed));
> +		snprintf(buf, size, "%s  %s %s %02X\n", elapsed, sym, dir,
> event.data);
> +	} else if (size) {
> +		buf[0] = '\0';
> +	}
> +}
> +
> +/*
> + *  This is the hook we install for register reads when tracing is enabled.
> It calls
> + *  the original serial_in function and logs the read to the register event
> queue.
> + */
> +static unsigned int serial_in_wrapper(struct uart_port *port, int offset)
> +{
> +	struct uart_debug *uart_debug = port->private_data;
> +	uint8_t value;
> +
> +	value = uart_debug->original_serial_in(port, offset);
> +	queue_add(port, offset, value, false);
> +	return value;
> +}
> +
> +/*
> + *  This is the hook we install for register writes when tracing is enabled.
> It calls
> + *  the original serial_out function and logs the write to the register event
> queue.
> + */
> +static void serial_out_wrapper(struct uart_port *port, int offset, int value)
> +{
> +	struct uart_debug *uart_debug = port->private_data;
> +
> +	uart_debug->original_serial_out(port, offset, value);
> +	queue_add(port, offset, value, true);
> +}
> +
> +/*
> + *  Handle reads from the 'trace_size' pseudo-file.  Report the configured
> trace size.
> + *  If it changes between (partial) reads then the output will likely be
> corrupted.  The
> + *  only way to fix this is to store the text buffer in the file private
> data.  Users
> + *  should be encouraged to provide a buffer large enough to read the entire
> value at once.
> + */
> +static ssize_t size_read(struct file *filp, char __user *buf, size_t size,
> loff_t *ppos)
> +{
> +	struct uart_port *port = filp->private_data;
> +	struct uart_debug *uart_debug = port->private_data;
> +	char text[16];
> +	uint32_t len;
> +
> +	len = snprintf(text, sizeof(text), "%u\n", uart_debug->trace_size);
> +	return simple_read_from_buffer(buf, size, ppos, text, len);
> +}
> +
> +/*
> + *  Handle writes to the 'trace_size' pseudo-file.  Set the configured trace
> size (maximum
> + *  number of log entries).
> + */
> +static ssize_t size_write(struct file *filp, const char __user *buf, size_t
> size, loff_t *ppos)
> +{
> +	struct uart_port *port = filp->private_data;
> +	struct uart_debug *uart_debug = port->private_data;
> +	uint32_t trace_size, rounded_size = 1;
> +	int error;
> +
> +	error = kstrtouint_from_user(buf, size, 0, &trace_size);
> +	if (error)
> +		return error;
> +
> +	if (trace_size == 0)
> +		return -EINVAL;
> +	while (trace_size >>= 1)
> +		rounded_size <<= 1;  /* round down to nearest power of 2 */

Comment is certainly misplaces as it's the whole while loop which 
calculates that.

> +	uart_debug->trace_size = rounded_size;
> +	return size;
> +}
> +
> +/*
> + *  Create the debugfs interface.  This should be called during port
> registration after
> + *  port->name, port->serial_in, and port->serial_out have been initialized.
> We are
> + *  using port->private_data to store a pointer to our data structure.  That
> field appears
> + *  to be otherwise unused.  If this is wrong we will need to create a new
> field.
> + */
> +void uart_debug_create(struct uart_port *port)
> +{
> +	struct uart_debug *uart_debug;
> +	struct dentry *dir;
> +
> +	uart_debug = port->private_data = kzalloc(sizeof(struct uart_debug),
> GFP_KERNEL);

How about the drivers which use port->private_data?

It would make this look cleaner if you split the double assignment.

> +	if (uart_debug == NULL)
> +		return;
> +
> +	spin_lock_init(&uart_debug->lock);
> +	mutex_init(&uart_debug->mutex);
> +	uart_debug->trace_size = 4096;

SZ_4K

> +
> +	dir = debugfs_create_dir(port->name, NULL);  /* ie. "ttyS0" */
> +	debugfs_create_file("trace_all",    0644, dir, port, &all_fops);
> +	debugfs_create_file("trace_buffer", 0444, dir, port, &buffer_fops);
> +	debugfs_create_file("trace_enable", 0644, dir, port, &enable_fops);
> +	debugfs_create_file("trace_size",   0644, dir, port, &size_fops);
> +}
> +
> +/*
> + *  Destroy the debugfs interface.  This should be called during port
> deregistration.
> + */
> +void uart_debug_destroy(struct uart_port *port)
> +{
> +	struct uart_debug *uart_debug;
> +
> +	uart_debug = port->private_data;
> +	port->private_data = NULL;
> +
> +	if (uart_debug) {
> +		debugfs_lookup_and_remove(port->name, NULL);  /* ie. "ttyS0 */
> +		queue_free(port, true);
> +		kfree(uart_debug);
> +	}
> +}


-- 
 i.

Re: [PATCH] tty/serial: create debugfs interface for UART register tracing

[Dan Raymond]

On 8/23/2023 1:01 AM, Greg KH wrote:

> This really should be a Kconfig option as some people will not want the
> added size, or feature, in their system as many serial ports have data
> that other users, even root ones, shouldn't be snooping on (i.e.
> cell modems.)

Done.

> Can you wrap comments at 80 columns please?  Code is fine to go to 100.

Sure.

>> + *
>> + *  Each serial port ("ttyS0", "ttyS1", etc.) will have its own directory in the root of
>> + *  the debug filesystem.  Inside each directory will be the following pseudo-files:
>> + *
>> + *  trace_all    - toggles tracing of all registers vs. just the RX/TX registers
> So 0 is just rx/tx?

Yes, 0 is just rx/tx.  I've updated the comment to reflect that.

> This should be documented somewhere in Documentation/ OR better yet, in
> kernel doc format so that when building the documentation, it sucks it
> in from this file to be included there automatically.
>
> And what are the default values of these files at boot?

I've converted this to kernel-doc format and linked it to 
Documentation/trace/index.rst.  I've also documented the default values.

>> + *  Example session:
>> + *
>> + *  > mount -t debugfs debugfs /sys/kernel/debug
>> + *  > echo '1' > /sys/kernel/debug/ttyS1/trace_all
>> + *  > echo '1' > /sys/kernel/debug/ttyS1/trace_enable
> Any reason why you didn't just use the existing kernel tracing facility
> for all of this?

No, it just seemed easier to use the debugfs.  Not a good reason, I 
know.  I'll take a closer look at the tracefs for this.

> This is the big issue I have with this change, sorry, it's an odd one.
>
> The use of "uintX_t" variable types belongs in userspace, these are not
> kernel data types (yes, they are used in places, but no, they do not
> make sense, see the many times Linus and I have talked about this in the
> past, wrong namespace, etc.)
>
> Can you change these all to the normal types of u32, u16, u8 and so on
> please?

Done.

>> +struct reg_queue {
>> +	uint32_t          read_idx;   /* first full (written) slot */
>> +	uint32_t          write_idx;  /* first empty (unwritten) slot */
>> +	struct reg_event *buf;        /* array to hold the data */
>> +	uint32_t          size;       /* array size (number of entries - must be power of 2) */
>> +	bool              wrap;       /* true if write_idx wrapped around and reached read_idx */
> If you use pahole on this structure, you will see you can get this a bit
> smaller.  Although I don't think you use this a lot, right?

I was using a 32-bit target and pahole didn't show any gaps. Does the 
pointer cause a gap on 64-bit targets?  In any case I moved the pointer 
to the top of the structure.

>> +
>> +struct uart_debug {
>> +	spinlock_t        lock;
>> +	struct mutex      mutex;
> Why 2 locks?  Please document these.

The spinlock protects the 'struct reg_queue' which can be accessed from 
interrupt context and normal context.  The mutex protects the outer data 
structure which only the user accesses so it doesn't need to disable 
interrupts.  I moved the spinlock to the reg_queue to make this more 
explicit.

>> +	char              line[64];  /* buffer to hold text of last item removed from queue */
> Why 64?

I changed it to 28 which is just enough to hold the 26-character 
register event string + newline + NUL.

>> +static ssize_t      all_read(struct file *filp, char __user *buf, size_t size, loff_t *ppos);
>> +static ssize_t      all_write(struct file *filp,
>> +			const char __user *buf, size_t size, loff_t *ppos);
>> +static ssize_t      buffer_read(struct file *filp, char __user *buf, size_t size, loff_t *ppos);
>> +static ssize_t      enable_read(struct file *filp, char __user *buf, size_t size, loff_t *ppos);
>> +static ssize_t      enable_write(struct file *filp,
>> +			const char __user *buf, size_t size, loff_t *ppos);
>> +static void         format_cycle(uint64_t cpu_cycles, char *buf, uint32_t size);
>> +static void         queue_add(struct uart_port *port, uint8_t reg, uint8_t data, bool write);
>> +static bool         queue_alloc(struct uart_port *port);
>> +static void         queue_free(struct uart_port *port, bool force);
>> +static void         queue_remove(struct uart_port *port, char *buf, uint32_t size);
>> +static unsigned int serial_in_wrapper(struct uart_port *port, int offset);
>> +static void         serial_out_wrapper(struct uart_port *port, int offset, int value);
>> +static ssize_t      size_read(struct file *filp, char __user *buf, size_t size, loff_t *ppos);
>> +static ssize_t      size_write(struct file *filp,
>> +			const char __user *buf, size_t size, loff_t *ppos);
> Any chance to reorginize the code to not need the forward declarations?

I generally keep functions in alphabetical order and choose names 
accordingly so they are grouped the way I want.  For example, the 
queue_xxx() functions are the only ones that touch the reg_queue 
structure.  I use forward declarations (whether needed or not) to avoid 
compiler errors regardless of the function order.  Is this a bad practice?

> Nice hack to make the overhead "zero" but now you have 2 function jumps
> per character, on some systems that can be a lot of overhead.  Why not
> just use the existing trace functionality for this instead?  If the
> feature is not enabled, it will not have any overhead, and if it is, it
> will only have the one call to your hook, saving you another function
> call jump (which on modern processors is VERY slow thanks to spectre
> issues...)

Can you clarify the functionality you are suggesting?  Is it the mcount 
call inserted by the compiler for function tracing?  I guess I need to 
get more familiar with the kernel tracing facility to make a comparison 
but maybe you could point me in the right direction?

>
> We do have at least 2 different ringbuffer structures in the kernel, why
> create another one?

Can you point me to the structures you have in mind?  One thought is 
that I have a 'wrap' flag which is a little paranoid but it ensures that 
a buffer overflow is detected.

> Anyway, again, cool feature, I like it, but if you can tie it into the
> existing trace framework better (either by using that entirely which
> might be best), or at the least, putting your hook into the data path
> with it, that would be best.
>
> thanks,
>
> greg k-h

Thanks for your review!  I've created another patch that incorporates 
most of your suggestions and I'll post that next. I'll also spend some 
more time looking at the tracefs to address your other suggestions.

Re: [PATCH] tty/serial: create debugfs interface for UART register tracing

[Dan Raymond]

On 8/23/2023 2:30 AM, Ilpo Järvinen wrote:

> Thanks, looks useful (although it might have challenge in tracing hw
> during early init).

I suppose there would need to be a mechanism to enable tracing by 
default (kernel cmd line?)  Is the UART driver even used very early in 
the boot process?

>> +struct reg_event {
>> +	uint32_t  cycle_lo;  /* CPU cycle count (lower 32-bits) */
>> +	uint16_t  cycle_hi;  /* CPU cycle count (upper 16-bits) */
>> +	uint8_t   access;    /* write flag + register number */
>> +	uint8_t   data;      /* register data */
> Some HW-specific registers are larger than 8 bits.

Not for 8250/16550?  Currently this feature only supports those and it 
also relies on the TSC which is an x86 thing.

>
>> +
>> +		ptr = uart_debug->line + uart_debug->offset;
>> +		len = strlen(ptr);
> Why you need to calculate length? Shouldn't queue_remove() be able to return
> this information?

Yes, we can return the string length from queue_remove() but we still 
need to call strlen() to accommodate all code paths.  The user might 
call read() with a very small buffer and that requires us to advance ptr 
past the beginning of the string on subsequent calls.

>
>> +		num_bytes = (size < len) ? size : len;
> min_t().

Done.

>
>> +	
>> +	if (error)
>> +		return total_bytes ? total_bytes : error;
>> +	return total_bytes;
> So this is same as:
> 	if (!total_bytes)
> 		return error;
>
> 	return total_bytes;

OK, I simplified this.

> For in-kernel interfaces, use u64 and u32, uintxx_t is for userspace
> interactions.

Done.

>> +	static uint64_t cpu_freq;  /* cycles per second */
>> +	uint32_t h, m, s, us;
>> +
>> +	if (cpu_freq == 0)
>> +		cpu_freq = arch_freq_get_on_cpu(0) * 1000ULL;
>> +
>> +	s = div64_u64_rem(cpu_cycles, cpu_freq, &cpu_cycles);
>> +	us = div64_u64(cpu_cycles * 1000 * 1000 + 500 * 1000, cpu_freq);
>> +
>> +	m = s / 60; s = s % 60;
>> +	h = m / 60; m = m % 60;
>> +
>> +	snprintf(buf, size, "%02d:%02d:%02d.%06u", h, m, s, us);
> seconds.us is enough. If some additional formatting is to happen, it
> should be done in userspace.

I can see your point.  If the user does want to reformat this it will be 
easier to start with the format you suggested.  Is this a general rule 
for kernel space?

>> +
>> +	cpu_cycle      = rdtsc();
>> +	event.cycle_lo = (uint32_t)cpu_cycle;
>> +	event.cycle_hi = (uint16_t)(cpu_cycle >> 32);
>> +	event.access   = (write ? 0x08 : 0x00) | reg;
> Use defines for these literals.
>
>> +static noinline void queue_free(struct uart_port *port, bool force)
>> +{
>> +	struct uart_debug *uart_debug = port->private_data;
>> +	struct reg_queue *queue = &uart_debug->register_queue;
>> +
>> +	if (force || queue->read_idx == queue->write_idx) {
> Why cannot the only place where force=true just reset the indexes before
> making the call so no force parameter is required? ...I think there's a
> bug anyway with the indexes not getting properly reset in that case.

Only the queue_xxx() functions read or write the queue structure.  The 
indices are reset below when we memset() the entire structure to 0.

>
>> +		vfree(queue->buf);
>> +		memset(queue, 0, sizeof(*queue));
>> +	}
>> ...
>> +	} else if (num_events) {
>> +		reg = event.access & 0x07;
>> +		sym = event.access & 0x08 ? out_regs[reg] : in_regs[reg];
> Some uarts have registers beyond 0x07 so this doesn't seem enough.
> It would be nice if the driver could provide alternative set of names for
> the registers.

I'll have to look into how difficult it would be to support other UARTs 
besides 8250/16550.

>> +	while (trace_size >>= 1)
>> +		rounded_size <<= 1;  /* round down to nearest power of 2 */
> Comment is certainly misplaces as it's the whole while loop which
> calculates that.

Fixed.

>> +/*
>> + *  Create the debugfs interface.  This should be called during port
>> registration after
>> + *  port->name, port->serial_in, and port->serial_out have been initialized.
>> We are
>> + *  using port->private_data to store a pointer to our data structure.  That
>> field appears
>> + *  to be otherwise unused.  If this is wrong we will need to create a new
>> field.
>> + */
>> +void uart_debug_create(struct uart_port *port)
>> +{
>> +	struct uart_debug *uart_debug;
>> +	struct dentry *dir;
>> +
>> +	uart_debug = port->private_data = kzalloc(sizeof(struct uart_debug),
>> GFP_KERNEL);
> How about the drivers which use port->private_data?

It didn't look like this field was used.  Was I wrong about this?

> It would make this look cleaner if you split the double assignment.

Done.

>> +
>> +	uart_debug->trace_size = 4096;
> SZ_4K

Done.

Thanks for looking at this.  I've created another patch that 
incorporates most of your suggestions.

Re: [PATCH] tty/serial: create debugfs interface for UART register tracing

[Ilpo Järvinen]

[-- Attachment #1: Type: text/plain, Size: 5136 bytes --]

On Thu, 24 Aug 2023, Dan Raymond wrote:
> On 8/23/2023 2:30 AM, Ilpo Järvinen wrote:
> 
> > Thanks, looks useful (although it might have challenge in tracing hw
> > during early init).
> 
> I suppose there would need to be a mechanism to enable tracing by default
> (kernel cmd line?)  Is the UART driver even used very early in the boot
> process?

I mainly meant the time when the driver is initialized, when moving from 
univ8250 -> the actual 8250 driver for the particular HW. It's one of the 
points of interest.

I don't know if the tracing side has something more "standard" for this 
already and since you're looking to that already, it's good to take 
notice if there's something.

> > > +struct reg_event {
> > > +	uint32_t  cycle_lo;  /* CPU cycle count (lower 32-bits) */
> > > +	uint16_t  cycle_hi;  /* CPU cycle count (upper 16-bits) */
> > > +	uint8_t   access;    /* write flag + register number */
> > > +	uint8_t   data;      /* register data */
> > Some HW-specific registers are larger than 8 bits.
> 
> Not for 8250/16550?

Some drivers for 8250 variants have such registers. Not that they're 
common so it's perhaps not a big deal.

> Currently this feature only supports those and it also
> relies on the TSC which is an x86 thing.

I wonder why you have to rely on that. Why e.g. ktime_get_boottime() is 
not enough for this usecase?

> > > +		ptr = uart_debug->line + uart_debug->offset;
> > > +		len = strlen(ptr);
> > Why you need to calculate length? Shouldn't queue_remove() be able to return
> > this information?
> 
> Yes, we can return the string length from queue_remove() but we still need to
> call strlen() to accommodate all code paths.  The user might call read() with
> a very small buffer and that requires us to advance ptr past the beginning of
> the string on subsequent calls.

I still find it hard to believe you could not keep track of it all 
without strlen(), snprintf() returns the number of chars it wrote to 
uart_debug->line so it should be that length - uart_debug->offset?

> > > +	static uint64_t cpu_freq;  /* cycles per second */
> > > +	uint32_t h, m, s, us;
> > > +
> > > +	if (cpu_freq == 0)
> > > +		cpu_freq = arch_freq_get_on_cpu(0) * 1000ULL;
> > > +
> > > +	s = div64_u64_rem(cpu_cycles, cpu_freq, &cpu_cycles);
> > > +	us = div64_u64(cpu_cycles * 1000 * 1000 + 500 * 1000, cpu_freq);
> > > +
> > > +	m = s / 60; s = s % 60;
> > > +	h = m / 60; m = m % 60;
> > > +
> > > +	snprintf(buf, size, "%02d:%02d:%02d.%06u", h, m, s, us);
> > seconds.us is enough. If some additional formatting is to happen, it
> > should be done in userspace.
> 
> I can see your point.  If the user does want to reformat this it will be
> easier to start with the format you suggested.  Is this a general rule for
> kernel space?

I don't know if there's a rule. But having had to parse those :: inputs 
way too many times in the past, I have very little love for that format 
being forced on user ;-).

> > > +static noinline void queue_free(struct uart_port *port, bool force)
> > > +{
> > > +	struct uart_debug *uart_debug = port->private_data;
> > > +	struct reg_queue *queue = &uart_debug->register_queue;
> > > +
> > > +	if (force || queue->read_idx == queue->write_idx) {
> > Why cannot the only place where force=true just reset the indexes before
> > making the call so no force parameter is required? ...I think there's a
> > bug anyway with the indexes not getting properly reset in that case.
> 
> Only the queue_xxx() functions read or write the queue structure.  The indices
> are reset below when we memset() the entire structure to 0.

Ah, I see.

> > > +		vfree(queue->buf);
> > > +		memset(queue, 0, sizeof(*queue));
> > > +	}
> > > ...
> > > +	} else if (num_events) {
> > > +		reg = event.access & 0x07;
> > > +		sym = event.access & 0x08 ? out_regs[reg] : in_regs[reg];
> > Some uarts have registers beyond 0x07 so this doesn't seem enough.
> > It would be nice if the driver could provide alternative set of names for
> > the registers.
> 
> I'll have to look into how difficult it would be to support other UARTs
> besides 8250/16550.
>
> > > +/*
> > > + *  Create the debugfs interface.  This should be called during port
> > > registration after
> > > + *  port->name, port->serial_in, and port->serial_out have been
> > > initialized.
> > > We are
> > > + *  using port->private_data to store a pointer to our data structure.
> > > That
> > > field appears
> > > + *  to be otherwise unused.  If this is wrong we will need to create a
> > > new
> > > field.
> > > + */
> > > +void uart_debug_create(struct uart_port *port)
> > > +{
> > > +	struct uart_debug *uart_debug;
> > > +	struct dentry *dir;
> > > +
> > > +	uart_debug = port->private_data = kzalloc(sizeof(struct uart_debug),
> > > GFP_KERNEL);
> > How about the drivers which use port->private_data?
> 
> It didn't look like this field was used.  Was I wrong about this?

~/linux/uart/drivers/tty/serial/8250$ git grep 'private_data =' | wc -l
20

There are multiple 8250 variant drivers using it.

Some also come with additional registers so it's all relevant also in 
serial/8250/ domain.


-- 
 i.

Re: [PATCH] tty/serial: create debugfs interface for UART register tracing

[Dan Raymond]

On 8/24/2023 6:13 AM, Ilpo Järvinen wrote:

>> Currently this feature only supports those and it also
>> relies on the TSC which is an x86 thing.
> 
> I wonder why you have to rely on that. Why e.g. ktime_get_boottime() is 
> not enough for this usecase?

I was motivated to make the tracing as unobtrusive as possible and it seemed
like the rdtsc instruction would be very fast and very precise.  I'll have to
profile ktime_get_boottime() to see how much overhead that adds.

>>>> +		ptr = uart_debug->line + uart_debug->offset;
>>>> +		len = strlen(ptr);
>>> Why you need to calculate length? Shouldn't queue_remove() be able to return
>>> this information?
>>
>> Yes, we can return the string length from queue_remove() but we still need to
>> call strlen() to accommodate all code paths.  The user might call read() with
>> a very small buffer and that requires us to advance ptr past the beginning of
>> the string on subsequent calls.
> 
> I still find it hard to believe you could not keep track of it all 
> without strlen(), snprintf() returns the number of chars it wrote to 
> uart_debug->line so it should be that length - uart_debug->offset?

True.  I could store the total string length and trade a little more memory and
a little more complexity for a little less CPU time.  Do you think it's a good
tradeoff?  The strlen() call should be pretty fast since the string is a maximum
of 27 characters.  Also, this is in the trace consumer path where performance
is not as important as the trace producer path.
 
>>>> +	static uint64_t cpu_freq;  /* cycles per second */
>>>> +	uint32_t h, m, s, us;
>>>> +
>>>> +	if (cpu_freq == 0)
>>>> +		cpu_freq = arch_freq_get_on_cpu(0) * 1000ULL;
>>>> +
>>>> +	s = div64_u64_rem(cpu_cycles, cpu_freq, &cpu_cycles);
>>>> +	us = div64_u64(cpu_cycles * 1000 * 1000 + 500 * 1000, cpu_freq);
>>>> +
>>>> +	m = s / 60; s = s % 60;
>>>> +	h = m / 60; m = m % 60;
>>>> +
>>>> +	snprintf(buf, size, "%02d:%02d:%02d.%06u", h, m, s, us);
>>> seconds.us is enough. If some additional formatting is to happen, it
>>> should be done in userspace.
>>
>> I can see your point.  If the user does want to reformat this it will be
>> easier to start with the format you suggested.  Is this a general rule for
>> kernel space?
> 
> I don't know if there's a rule. But having had to parse those :: inputs 
> way too many times in the past, I have very little love for that format 
> being forced on user ;-).

OK, I've changed the format from "hh:mm:ss:mmmuuu" to "ssssssss:mmmuuu".

>>>> +/*
>>>> + *  Create the debugfs interface.  This should be called during port
>>>> registration after
>>>> + *  port->name, port->serial_in, and port->serial_out have been
>>>> initialized.
>>>> We are
>>>> + *  using port->private_data to store a pointer to our data structure.
>>>> That
>>>> field appears
>>>> + *  to be otherwise unused.  If this is wrong we will need to create a
>>>> new
>>>> field.
>>>> + */
>>>> +void uart_debug_create(struct uart_port *port)
>>>> +{
>>>> +	struct uart_debug *uart_debug;
>>>> +	struct dentry *dir;
>>>> +
>>>> +	uart_debug = port->private_data = kzalloc(sizeof(struct uart_debug),
>>>> GFP_KERNEL);
>>> How about the drivers which use port->private_data?
>>
>> It didn't look like this field was used.  Was I wrong about this?
> 
> ~/linux/uart/drivers/tty/serial/8250$ git grep 'private_data =' | wc -l
> 20
> 
> There are multiple 8250 variant drivers using it.
> 
> Some also come with additional registers so it's all relevant also in 
> serial/8250/ domain.

OK, I've added a new field named 'debug_data' and I'll use that instead of
'private_data'.  My latest changes are in the v3 patch.