x86/nmi: Print all cpu stacks from NMI safely

From: "Steven Rostedt (Red Hat)" <[email protected]>

There's several locations in the kernel that open code the calculation of the next location in the trace_seq buffer. This is usually done with

p->buffer + p->len

Instead of having this open coded, supply a helper function in the header to do it for them. This function is called trace_seq_buffer_ptr().

Signed-off-by Steven Rostedt <[email protected]>

---
 arch/x86/kvm/mmutrace.h     |  2 +-
 drivers/scsi/scsi_trace.c   | 16 ++++++++--------
 include/linux/trace_seq.h   | 15 +++++++++++++++
 kernel/trace/trace_output.c | 14 +++++++-------
 4 files changed, 31 insertions(+), 16 deletions(-)

arch/x86/kvm/mmutrace.h +1 -1

index 9d2e0ffcb190..2e5652b62fd6 100644
@@ -22,7 +22,7 @@
 	__entry->unsync = sp->unsync;
 
 #define KVM_MMU_PAGE_PRINTK() ({				        \
-	const char *ret = p->buffer + p->len;				\
+	const char *ret = trace_seq_buffer_ptr(p);			\
 	static const char *access_str[] = {			        \
 		"---", "--x", "w--", "w-x", "-u-", "-ux", "wu-", "wux"  \
 	};							        \

drivers/scsi/scsi_trace.c +8 -8

index 2bea4f0b684a..503594e5f76d 100644
@@ -28,7 +28,7 @@ scsi_trace_misc(struct trace_seq *, unsigned char *, int);
 static const char *
 scsi_trace_rw6(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	sector_t lba = 0, txlen = 0;
 
 	lba |= ((cdb[1] & 0x1F) << 16);

@@ -46,7 +46,7 @@ scsi_trace_rw6(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_rw10(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	sector_t lba = 0, txlen = 0;
 
 	lba |= (cdb[2] << 24);

@@ -71,7 +71,7 @@ scsi_trace_rw10(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_rw12(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	sector_t lba = 0, txlen = 0;
 
 	lba |= (cdb[2] << 24);

@@ -94,7 +94,7 @@ scsi_trace_rw12(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_rw16(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	sector_t lba = 0, txlen = 0;
 
 	lba |= ((u64)cdb[2] << 56);

@@ -125,7 +125,7 @@ scsi_trace_rw16(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_rw32(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len, *cmd;
+	const char *ret = trace_seq_buffer_ptr(p), *cmd;
 	sector_t lba = 0, txlen = 0;
 	u32 ei_lbrt = 0;
 

@@ -180,7 +180,7 @@ out:
 static const char *
 scsi_trace_unmap(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	unsigned int regions = cdb[7] << 8 | cdb[8];
 
 	trace_seq_printf(p, "regions=%u", (regions - 8) / 16);

@@ -192,7 +192,7 @@ scsi_trace_unmap(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_service_action_in(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len, *cmd;
+	const char *ret = trace_seq_buffer_ptr(p), *cmd;
 	sector_t lba = 0;
 	u32 alloc_len = 0;
 

@@ -247,7 +247,7 @@ scsi_trace_varlen(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_misc(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 
 	trace_seq_printf(p, "-");
 	trace_seq_putc(p, 0);

include/linux/trace_seq.h +15 -0

index dd85753e1bb0..ea6c9dea79e3 100644
@@ -25,6 +25,21 @@ trace_seq_init(struct trace_seq *s)
 	s->full = 0;
 }
 
+/**
+ * trace_seq_buffer_ptr - return pointer to next location in buffer
+ * @s: trace sequence descriptor
+ *
+ * Returns the pointer to the buffer where the next write to
+ * the buffer will happen. This is useful to save the location
+ * that is about to be written to and then return the result
+ * of that write.
+ */
+static inline unsigned char *
+trace_seq_buffer_ptr(struct trace_seq *s)
+{
+	return s->buffer + s->len;
+}
+
 /*
  * Currently only defined when tracing is enabled.
  */

kernel/trace/trace_output.c +7 -7

index b8930f79a04b..c6977d5a9b12 100644
@@ -75,7 +75,7 @@ ftrace_print_flags_seq(struct trace_seq *p, const char *delim,
 {
 	unsigned long mask;
 	const char *str;
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	int i, first = 1;
 
 	for (i = 0;  flag_array[i].name && flags; i++) {

@@ -111,7 +111,7 @@ ftrace_print_symbols_seq(struct trace_seq *p, unsigned long val,
 			 const struct trace_print_flags *symbol_array)
 {
 	int i;
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 
 	for (i = 0;  symbol_array[i].name; i++) {
 

@@ -122,7 +122,7 @@ ftrace_print_symbols_seq(struct trace_seq *p, unsigned long val,
 		break;
 	}
 
-	if (ret == (const char *)(p->buffer + p->len))
+	if (ret == (const char *)(trace_seq_buffer_ptr(p)))
 		trace_seq_printf(p, "0x%lx", val);
 
 	trace_seq_putc(p, 0);

@@ -137,7 +137,7 @@ ftrace_print_symbols_seq_u64(struct trace_seq *p, unsigned long long val,
 			 const struct trace_print_flags_u64 *symbol_array)
 {
 	int i;
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 
 	for (i = 0;  symbol_array[i].name; i++) {
 

@@ -148,7 +148,7 @@ ftrace_print_symbols_seq_u64(struct trace_seq *p, unsigned long long val,
 		break;
 	}
 
-	if (ret == (const char *)(p->buffer + p->len))
+	if (ret == (const char *)(trace_seq_buffer_ptr(p)))
 		trace_seq_printf(p, "0x%llx", val);
 
 	trace_seq_putc(p, 0);

@@ -162,7 +162,7 @@ const char *
 ftrace_print_bitmask_seq(struct trace_seq *p, void *bitmask_ptr,
 			 unsigned int bitmask_size)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 
 	trace_seq_bitmask(p, bitmask_ptr, bitmask_size * 8);
 	trace_seq_putc(p, 0);

@@ -175,7 +175,7 @@ const char *
 ftrace_print_hex_seq(struct trace_seq *p, const unsigned char *buf, int buf_len)
 {
 	int i;
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 
 	for (i = 0; i < buf_len; i++)
 		trace_seq_printf(p, "%s%2.2x", i == 0 ? "" : " ", buf[i]);

As this patch is in my 3.17 queue and it touches the kvm and scsi tracepoint code, I figured I should at least do the courtesy of notifying the maintainers of those subsystems.

Do you have any issues with this going through my tree? If not, please give me an Acked-by.

Thanks!

-- Steve

Quoted 200 lines · On Thu, 26 Jun 2014 17:49:02 -0400 Steven Rostedt <[email protected]> wrote:

From: "Steven Rostedt (Red Hat)" <[email protected]>

There's several locations in the kernel that open code the calculation of the next location in the trace_seq buffer. This is usually done with

p->buffer + p->len

Instead of having this open coded, supply a helper function in the header to do it for them. This function is called trace_seq_buffer_ptr().

Signed-off-by Steven Rostedt <[email protected]>

---
 arch/x86/kvm/mmutrace.h     |  2 +-
 drivers/scsi/scsi_trace.c   | 16 ++++++++--------
 include/linux/trace_seq.h   | 15 +++++++++++++++
 kernel/trace/trace_output.c | 14 +++++++-------
 4 files changed, 31 insertions(+), 16 deletions(-)

arch/x86/kvm/mmutrace.h +1 -1

index 9d2e0ffcb190..2e5652b62fd6 100644
@@ -22,7 +22,7 @@
 	__entry->unsync = sp->unsync;
 
 #define KVM_MMU_PAGE_PRINTK() ({				        \
-	const char *ret = p->buffer + p->len;				\
+	const char *ret = trace_seq_buffer_ptr(p);			\
 	static const char *access_str[] = {			        \
 		"---", "--x", "w--", "w-x", "-u-", "-ux", "wu-", "wux"  \
 	};							        \

drivers/scsi/scsi_trace.c +8 -8

index 2bea4f0b684a..503594e5f76d 100644
@@ -28,7 +28,7 @@ scsi_trace_misc(struct trace_seq *, unsigned char *, int);
 static const char *
 scsi_trace_rw6(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	sector_t lba = 0, txlen = 0;
 
 	lba |= ((cdb[1] & 0x1F) << 16);

@@ -46,7 +46,7 @@ scsi_trace_rw6(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_rw10(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	sector_t lba = 0, txlen = 0;
 
 	lba |= (cdb[2] << 24);

@@ -71,7 +71,7 @@ scsi_trace_rw10(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_rw12(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	sector_t lba = 0, txlen = 0;
 
 	lba |= (cdb[2] << 24);

@@ -94,7 +94,7 @@ scsi_trace_rw12(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_rw16(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	sector_t lba = 0, txlen = 0;
 
 	lba |= ((u64)cdb[2] << 56);

@@ -125,7 +125,7 @@ scsi_trace_rw16(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_rw32(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len, *cmd;
+	const char *ret = trace_seq_buffer_ptr(p), *cmd;
 	sector_t lba = 0, txlen = 0;
 	u32 ei_lbrt = 0;
 

@@ -180,7 +180,7 @@ out:
 static const char *
 scsi_trace_unmap(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	unsigned int regions = cdb[7] << 8 | cdb[8];
 
 	trace_seq_printf(p, "regions=%u", (regions - 8) / 16);

@@ -192,7 +192,7 @@ scsi_trace_unmap(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_service_action_in(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len, *cmd;
+	const char *ret = trace_seq_buffer_ptr(p), *cmd;
 	sector_t lba = 0;
 	u32 alloc_len = 0;
 

@@ -247,7 +247,7 @@ scsi_trace_varlen(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_misc(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 
 	trace_seq_printf(p, "-");
 	trace_seq_putc(p, 0);

include/linux/trace_seq.h +15 -0

index dd85753e1bb0..ea6c9dea79e3 100644
@@ -25,6 +25,21 @@ trace_seq_init(struct trace_seq *s)
 	s->full = 0;
 }
 
+/**
+ * trace_seq_buffer_ptr - return pointer to next location in buffer
+ * @s: trace sequence descriptor
+ *
+ * Returns the pointer to the buffer where the next write to
+ * the buffer will happen. This is useful to save the location
+ * that is about to be written to and then return the result
+ * of that write.
+ */
+static inline unsigned char *
+trace_seq_buffer_ptr(struct trace_seq *s)
+{
+	return s->buffer + s->len;
+}
+
 /*
  * Currently only defined when tracing is enabled.
  */

kernel/trace/trace_output.c +7 -7

index b8930f79a04b..c6977d5a9b12 100644
@@ -75,7 +75,7 @@ ftrace_print_flags_seq(struct trace_seq *p, const char *delim,
 {
 	unsigned long mask;
 	const char *str;
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	int i, first = 1;
 
 	for (i = 0;  flag_array[i].name && flags; i++) {

@@ -111,7 +111,7 @@ ftrace_print_symbols_seq(struct trace_seq *p, unsigned long val,
 			 const struct trace_print_flags *symbol_array)
 {
 	int i;
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 
 	for (i = 0;  symbol_array[i].name; i++) {
 

@@ -122,7 +122,7 @@ ftrace_print_symbols_seq(struct trace_seq *p, unsigned long val,
 		break;
 	}
 
-	if (ret == (const char *)(p->buffer + p->len))
+	if (ret == (const char *)(trace_seq_buffer_ptr(p)))
 		trace_seq_printf(p, "0x%lx", val);
 
 	trace_seq_putc(p, 0);

@@ -137,7 +137,7 @@ ftrace_print_symbols_seq_u64(struct trace_seq *p, unsigned long long val,
 			 const struct trace_print_flags_u64 *symbol_array)
 {
 	int i;
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 
 	for (i = 0;  symbol_array[i].name; i++) {
 

@@ -148,7 +148,7 @@ ftrace_print_symbols_seq_u64(struct trace_seq *p, unsigned long long val,
 		break;
 	}
 
-	if (ret == (const char *)(p->buffer + p->len))
+	if (ret == (const char *)(trace_seq_buffer_ptr(p)))
 		trace_seq_printf(p, "0x%llx", val);
 
 	trace_seq_putc(p, 0);

@@ -162,7 +162,7 @@ const char *
 ftrace_print_bitmask_seq(struct trace_seq *p, void *bitmask_ptr,
 			 unsigned int bitmask_size)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 
 	trace_seq_bitmask(p, bitmask_ptr, bitmask_size * 8);
 	trace_seq_putc(p, 0);

@@ -175,7 +175,7 @@ const char *
 ftrace_print_hex_seq(struct trace_seq *p, const unsigned char *buf, int buf_len)
 {
 	int i;
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 
 	for (i = 0; i < buf_len; i++)
 		trace_seq_printf(p, "%s%2.2x", i == 0 ? "" : " ", buf[i]);

Quoted 4 lines · Steven Rostedt

As this patch is in my 3.17 queue and it touches the kvm and scsi tracepoint code, I figured I should at least do the courtesy of notifying the maintainers of those subsystems.

Quoted 2 lines

Do you have any issues with this going through my tree? If not, please give me an Acked-by.

Missing cc to linux-scsi added.

Hannes has a set of patches to move logging to trace points. I don't think there's a clash but I'd like him to comment before you do this.

James

Quoted 207 lines

Thanks!

-- Steve

Quoted 200 lines · On Thu, 26 Jun 2014 17:49:02 -0400 Steven Rostedt <[email protected]> wrote:

From: "Steven Rostedt (Red Hat)" <[email protected]>

There's several locations in the kernel that open code the calculation of the next location in the trace_seq buffer. This is usually done with

p->buffer + p->len

Instead of having this open coded, supply a helper function in the header to do it for them. This function is called trace_seq_buffer_ptr().

Signed-off-by Steven Rostedt <[email protected]>

---
 arch/x86/kvm/mmutrace.h     |  2 +-
 drivers/scsi/scsi_trace.c   | 16 ++++++++--------
 include/linux/trace_seq.h   | 15 +++++++++++++++
 kernel/trace/trace_output.c | 14 +++++++-------
 4 files changed, 31 insertions(+), 16 deletions(-)

arch/x86/kvm/mmutrace.h +1 -1

index 9d2e0ffcb190..2e5652b62fd6 100644
@@ -22,7 +22,7 @@
 	__entry->unsync = sp->unsync;
 
 #define KVM_MMU_PAGE_PRINTK() ({				        \
-	const char *ret = p->buffer + p->len;				\
+	const char *ret = trace_seq_buffer_ptr(p);			\
 	static const char *access_str[] = {			        \
 		"---", "--x", "w--", "w-x", "-u-", "-ux", "wu-", "wux"  \
 	};							        \

drivers/scsi/scsi_trace.c +8 -8

index 2bea4f0b684a..503594e5f76d 100644
@@ -28,7 +28,7 @@ scsi_trace_misc(struct trace_seq *, unsigned char *, int);
 static const char *
 scsi_trace_rw6(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	sector_t lba = 0, txlen = 0;
 
 	lba |= ((cdb[1] & 0x1F) << 16);

@@ -46,7 +46,7 @@ scsi_trace_rw6(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_rw10(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	sector_t lba = 0, txlen = 0;
 
 	lba |= (cdb[2] << 24);

@@ -71,7 +71,7 @@ scsi_trace_rw10(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_rw12(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	sector_t lba = 0, txlen = 0;
 
 	lba |= (cdb[2] << 24);

@@ -94,7 +94,7 @@ scsi_trace_rw12(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_rw16(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	sector_t lba = 0, txlen = 0;
 
 	lba |= ((u64)cdb[2] << 56);

@@ -125,7 +125,7 @@ scsi_trace_rw16(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_rw32(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len, *cmd;
+	const char *ret = trace_seq_buffer_ptr(p), *cmd;
 	sector_t lba = 0, txlen = 0;
 	u32 ei_lbrt = 0;
 

@@ -180,7 +180,7 @@ out:
 static const char *
 scsi_trace_unmap(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	unsigned int regions = cdb[7] << 8 | cdb[8];
 
 	trace_seq_printf(p, "regions=%u", (regions - 8) / 16);

@@ -192,7 +192,7 @@ scsi_trace_unmap(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_service_action_in(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len, *cmd;
+	const char *ret = trace_seq_buffer_ptr(p), *cmd;
 	sector_t lba = 0;
 	u32 alloc_len = 0;
 

@@ -247,7 +247,7 @@ scsi_trace_varlen(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_misc(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 
 	trace_seq_printf(p, "-");
 	trace_seq_putc(p, 0);

include/linux/trace_seq.h +15 -0

index dd85753e1bb0..ea6c9dea79e3 100644
@@ -25,6 +25,21 @@ trace_seq_init(struct trace_seq *s)
 	s->full = 0;
 }
 
+/**
+ * trace_seq_buffer_ptr - return pointer to next location in buffer
+ * @s: trace sequence descriptor
+ *
+ * Returns the pointer to the buffer where the next write to
+ * the buffer will happen. This is useful to save the location
+ * that is about to be written to and then return the result
+ * of that write.
+ */
+static inline unsigned char *
+trace_seq_buffer_ptr(struct trace_seq *s)
+{
+	return s->buffer + s->len;
+}
+
 /*
  * Currently only defined when tracing is enabled.
  */

kernel/trace/trace_output.c +7 -7

index b8930f79a04b..c6977d5a9b12 100644
@@ -75,7 +75,7 @@ ftrace_print_flags_seq(struct trace_seq *p, const char *delim,
 {
 	unsigned long mask;
 	const char *str;
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	int i, first = 1;
 
 	for (i = 0;  flag_array[i].name && flags; i++) {

@@ -111,7 +111,7 @@ ftrace_print_symbols_seq(struct trace_seq *p, unsigned long val,
 			 const struct trace_print_flags *symbol_array)
 {
 	int i;
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 
 	for (i = 0;  symbol_array[i].name; i++) {
 

@@ -122,7 +122,7 @@ ftrace_print_symbols_seq(struct trace_seq *p, unsigned long val,
 		break;
 	}
 
-	if (ret == (const char *)(p->buffer + p->len))
+	if (ret == (const char *)(trace_seq_buffer_ptr(p)))
 		trace_seq_printf(p, "0x%lx", val);
 
 	trace_seq_putc(p, 0);

@@ -137,7 +137,7 @@ ftrace_print_symbols_seq_u64(struct trace_seq *p, unsigned long long val,
 			 const struct trace_print_flags_u64 *symbol_array)
 {
 	int i;
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 
 	for (i = 0;  symbol_array[i].name; i++) {
 

@@ -148,7 +148,7 @@ ftrace_print_symbols_seq_u64(struct trace_seq *p, unsigned long long val,
 		break;
 	}
 
-	if (ret == (const char *)(p->buffer + p->len))
+	if (ret == (const char *)(trace_seq_buffer_ptr(p)))
 		trace_seq_printf(p, "0x%llx", val);
 
 	trace_seq_putc(p, 0);

@@ -162,7 +162,7 @@ const char *
 ftrace_print_bitmask_seq(struct trace_seq *p, void *bitmask_ptr,
 			 unsigned int bitmask_size)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 
 	trace_seq_bitmask(p, bitmask_ptr, bitmask_size * 8);
 	trace_seq_putc(p, 0);

@@ -175,7 +175,7 @@ const char *
 ftrace_print_hex_seq(struct trace_seq *p, const unsigned char *buf, int buf_len)
 {
 	int i;
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 
 	for (i = 0; i < buf_len; i++)
 		trace_seq_printf(p, "%s%2.2x", i == 0 ? "" : " ", buf[i]);

As this patch is in my 3.17 queue and it touches the kvm and scsi tracepoint code, I figured I should at least do the courtesy of notifying the maintainers of those subsystems.

Do you have any issues with this going through my tree? If not, please give me an Acked-by.

Thanks!

-- Steve

Quoted 200 lines · On Thu, 26 Jun 2014 17:49:02 -0400 Steven Rostedt <[email protected]> wrote:

From: "Steven Rostedt (Red Hat)" <[email protected]>

There's several locations in the kernel that open code the calculation of the next location in the trace_seq buffer. This is usually done with

p->buffer + p->len

Instead of having this open coded, supply a helper function in the header to do it for them. This function is called trace_seq_buffer_ptr().

Signed-off-by Steven Rostedt <[email protected]>

---
 arch/x86/kvm/mmutrace.h     |  2 +-
 drivers/scsi/scsi_trace.c   | 16 ++++++++--------
 include/linux/trace_seq.h   | 15 +++++++++++++++
 kernel/trace/trace_output.c | 14 +++++++-------
 4 files changed, 31 insertions(+), 16 deletions(-)

arch/x86/kvm/mmutrace.h +1 -1

index 9d2e0ffcb190..2e5652b62fd6 100644
@@ -22,7 +22,7 @@
 	__entry->unsync = sp->unsync;
 
 #define KVM_MMU_PAGE_PRINTK() ({				        \
-	const char *ret = p->buffer + p->len;				\
+	const char *ret = trace_seq_buffer_ptr(p);			\
 	static const char *access_str[] = {			        \
 		"---", "--x", "w--", "w-x", "-u-", "-ux", "wu-", "wux"  \
 	};							        \

drivers/scsi/scsi_trace.c +8 -8

index 2bea4f0b684a..503594e5f76d 100644
@@ -28,7 +28,7 @@ scsi_trace_misc(struct trace_seq *, unsigned char *, int);
 static const char *
 scsi_trace_rw6(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	sector_t lba = 0, txlen = 0;
 
 	lba |= ((cdb[1] & 0x1F) << 16);

@@ -46,7 +46,7 @@ scsi_trace_rw6(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_rw10(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	sector_t lba = 0, txlen = 0;
 
 	lba |= (cdb[2] << 24);

@@ -71,7 +71,7 @@ scsi_trace_rw10(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_rw12(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	sector_t lba = 0, txlen = 0;
 
 	lba |= (cdb[2] << 24);

@@ -94,7 +94,7 @@ scsi_trace_rw12(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_rw16(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	sector_t lba = 0, txlen = 0;
 
 	lba |= ((u64)cdb[2] << 56);

@@ -125,7 +125,7 @@ scsi_trace_rw16(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_rw32(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len, *cmd;
+	const char *ret = trace_seq_buffer_ptr(p), *cmd;
 	sector_t lba = 0, txlen = 0;
 	u32 ei_lbrt = 0;
 

@@ -180,7 +180,7 @@ out:
 static const char *
 scsi_trace_unmap(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	unsigned int regions = cdb[7] << 8 | cdb[8];
 
 	trace_seq_printf(p, "regions=%u", (regions - 8) / 16);

@@ -192,7 +192,7 @@ scsi_trace_unmap(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_service_action_in(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len, *cmd;
+	const char *ret = trace_seq_buffer_ptr(p), *cmd;
 	sector_t lba = 0;
 	u32 alloc_len = 0;
 

@@ -247,7 +247,7 @@ scsi_trace_varlen(struct trace_seq *p, unsigned char *cdb, int len)
 static const char *
 scsi_trace_misc(struct trace_seq *p, unsigned char *cdb, int len)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 
 	trace_seq_printf(p, "-");
 	trace_seq_putc(p, 0);

include/linux/trace_seq.h +15 -0

index dd85753e1bb0..ea6c9dea79e3 100644
@@ -25,6 +25,21 @@ trace_seq_init(struct trace_seq *s)
 	s->full = 0;
 }
 
+/**
+ * trace_seq_buffer_ptr - return pointer to next location in buffer
+ * @s: trace sequence descriptor
+ *
+ * Returns the pointer to the buffer where the next write to
+ * the buffer will happen. This is useful to save the location
+ * that is about to be written to and then return the result
+ * of that write.
+ */
+static inline unsigned char *
+trace_seq_buffer_ptr(struct trace_seq *s)
+{
+	return s->buffer + s->len;
+}
+
 /*
  * Currently only defined when tracing is enabled.
  */

kernel/trace/trace_output.c +7 -7

index b8930f79a04b..c6977d5a9b12 100644
@@ -75,7 +75,7 @@ ftrace_print_flags_seq(struct trace_seq *p, const char *delim,
 {
 	unsigned long mask;
 	const char *str;
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 	int i, first = 1;
 
 	for (i = 0;  flag_array[i].name && flags; i++) {

@@ -111,7 +111,7 @@ ftrace_print_symbols_seq(struct trace_seq *p, unsigned long val,
 			 const struct trace_print_flags *symbol_array)
 {
 	int i;
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 
 	for (i = 0;  symbol_array[i].name; i++) {
 

@@ -122,7 +122,7 @@ ftrace_print_symbols_seq(struct trace_seq *p, unsigned long val,
 		break;
 	}
 
-	if (ret == (const char *)(p->buffer + p->len))
+	if (ret == (const char *)(trace_seq_buffer_ptr(p)))
 		trace_seq_printf(p, "0x%lx", val);
 
 	trace_seq_putc(p, 0);

@@ -137,7 +137,7 @@ ftrace_print_symbols_seq_u64(struct trace_seq *p, unsigned long long val,
 			 const struct trace_print_flags_u64 *symbol_array)
 {
 	int i;
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 
 	for (i = 0;  symbol_array[i].name; i++) {
 

@@ -148,7 +148,7 @@ ftrace_print_symbols_seq_u64(struct trace_seq *p, unsigned long long val,
 		break;
 	}
 
-	if (ret == (const char *)(p->buffer + p->len))
+	if (ret == (const char *)(trace_seq_buffer_ptr(p)))
 		trace_seq_printf(p, "0x%llx", val);
 
 	trace_seq_putc(p, 0);

@@ -162,7 +162,7 @@ const char *
 ftrace_print_bitmask_seq(struct trace_seq *p, void *bitmask_ptr,
 			 unsigned int bitmask_size)
 {
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 
 	trace_seq_bitmask(p, bitmask_ptr, bitmask_size * 8);
 	trace_seq_putc(p, 0);

@@ -175,7 +175,7 @@ const char *
 ftrace_print_hex_seq(struct trace_seq *p, const unsigned char *buf, int buf_len)
 {
 	int i;
-	const char *ret = p->buffer + p->len;
+	const char *ret = trace_seq_buffer_ptr(p);
 
 	for (i = 0; i < buf_len; i++)
 		trace_seq_printf(p, "%s%2.2x", i == 0 ? "" : " ", buf[i]);

From: "Steven Rostedt (Red Hat)" <[email protected]>

Create a seq_buf layer that trace_seq sits on. The seq_buf will not be limited to page size. This will allow other usages of seq_buf instead of a hard set PAGE_SIZE one that trace_seq has.

Signed-off-by Steven Rostedt <[email protected]>

---
 include/linux/seq_buf.h              |  58 ++++++
 include/linux/trace_seq.h            |  10 +-
 kernel/trace/Makefile                |   1 +
 kernel/trace/seq_buf.c               | 348 +++++++++++++++++++++++++++++++++++
 kernel/trace/trace.c                 |  39 ++--
 kernel/trace/trace_events.c          |   6 +-
 kernel/trace/trace_functions_graph.c |   6 +-
 kernel/trace/trace_seq.c             | 184 +++++++++---------
 8 files changed, 527 insertions(+), 125 deletions(-)
 create mode 100644 include/linux/seq_buf.h
 create mode 100644 kernel/trace/seq_buf.c

kernel/trace/seq_buf.c new file +18 -0

@@ -0,0 +1,348 @@
+/*
+ * seq_buf.c
+ *
+ * Copyright (C) 2014 Red Hat Inc, Steven Rostedt <[email protected]>
+ *
+ * The seq_buf is a handy tool that allows you to pass a descriptor around
+ * to a buffer that other functions can write to. It is similar to the
+ * seq_file functionality but has some differences.
+ *
+ * To use it, the seq_buf must be initialized with seq_buf_init().
+ * This will set up the counters within the descriptor. You can call
+ * seq_buf_init() more than once to reset the seq_buf to start
+ * from scratch.
+ * 
+ */
+#include <linux/uaccess.h>
+#include <linux/seq_file.h>
+#include <linux/seq_buf.h>

kernel/trace/seq_buf.c new file +5 -0

+		s->len = s->size - 1;
+		s->overflow = 1;
+	}
+}
+

kernel/trace/seq_buf.c new file +16 -0

+#define MAX_MEMHEX_BYTES	8U
+#define HEX_CHARS		(MAX_MEMHEX_BYTES*2 + 1)
+
+/**
+ * seq_buf_putmem_hex - write raw memory into the buffer in ASCII hex
+ * @s: seq_buf descriptor
+ * @mem: The raw memory to write its hex ASCII representation of
+ * @len: The length of the raw memory to copy (in bytes)
+ *
+ * This is similar to seq_buf_putmem() except instead of just copying the
+ * raw memory into the buffer it writes its ASCII representation of it
+ * in hex characters.
+ *
+ * Returns how much it wrote to the buffer.
+ */
+int seq_buf_putmem_hex(struct seq_buf *s, const void *mem,

kernel/trace/seq_buf.c new file +32 -0

+#ifdef __BIG_ENDIAN
+		for (i = 0, j = 0; i < start_len; i++) {
+#else
+		for (i = start_len-1, j = 0; i >= 0; i--) {
+#endif
+			hex[j++] = hex_asc_hi(data[i]);
+			hex[j++] = hex_asc_lo(data[i]);
+		}
+		if (WARN_ON_ONCE(j == 0 || j/2 > len))
+			break;
+
+		/* j increments twice per loop */
+		len -= j / 2;
+		hex[j++] = ' ';
+
+		cnt += seq_buf_putmem(s, hex, j);
+	}
+	return cnt;
+}
+
+/**
+ * seq_buf_path - copy a path into the sequence buffer
+ * @s: seq_buf descriptor
+ * @path: path to write into the sequence buffer.
+ *
+ * Write a path name into the sequence buffer.
+ *
+ * Returns the number of bytes written into the buffer.
+ */
+int seq_buf_path(struct seq_buf *s, const struct path *path)
+{
+	unsigned int len = SEQ_BUF_LEFT(s);

Quoted 7 lines · Steven Rostedt

From: "Steven Rostedt (Red Hat)" <[email protected]>

Create a seq_buf layer that trace_seq sits on. The seq_buf will not be limited to page size. This will allow other usages of seq_buf instead of a hard set PAGE_SIZE one that trace_seq has.

Signed-off-by Steven Rostedt <[email protected]>

Quoted 12 lines

---
 include/linux/seq_buf.h              |  58 ++++++
 include/linux/trace_seq.h            |  10 +-
 kernel/trace/Makefile                |   1 +
 kernel/trace/seq_buf.c               | 348 +++++++++++++++++++++++++++++++++++
 kernel/trace/trace.c                 |  39 ++--
 kernel/trace/trace_events.c          |   6 +-
 kernel/trace/trace_functions_graph.c |   6 +-
 kernel/trace/trace_seq.c             | 184 +++++++++---------
 8 files changed, 527 insertions(+), 125 deletions(-)
 create mode 100644 include/linux/seq_buf.h
 create mode 100644 kernel/trace/seq_buf.c

There is a lot of similar code in the two layers. Do you have any plans to transform the trace stuff to seq_buf and get rid of the trace_seq layer in long term?

If I get it correctly, the two layers are needed because:

1. seq_buf works with any buffer but
trace_seq with static buffer

2. seq_buf writes even part of the message until the buffer is full but trace_buf writes only full messages or nothing

3. seq_buf returns the number of written characters but trace_seq returns 1 on success and 0 on failure

4. seq_buf sets "overflow" flag when an operation failed but trace_seq sets "full" when this happens

I wounder if we could get a compromise and use only one layer.

ad 1st:

I have checked many locations and it seems that trace_seq_init() is called before the other functions as used. There is the WARN_ON() in the generic seq_buf() functions, so they would not crash. If there is some init missing, we could fix it later.

But I haven't really tested it yet.

ad 2nd and 3rd:

These are connected.

On solution is to disable writing part of the text even in the generic seq_buf functions. I think that it is perfectly fine. If we do not print the entire line, we are in troubles anyway. Note that we could not allocate another buffer in NMI, so we will lose part of the message anyway.

Another solution would be to live with incomplete lines in tracing. I wonder if any of the functions tries to write the line again when the write failed.

IMHO, the most important thing is that both functions return 0 on failure.

ad 4th:

Both "full" and "overflow" flags seems to have the same meaning. For example, trace_seq_printf() sets "full" on failure even when s->seq.len != s->size.

Quoted 42 lines · On Fri, 27 Jun 2014 15:45:38 +0200 Petr Mládek <[email protected]> wrote:

Quoted 7 lines · Steven Rostedt

From: "Steven Rostedt (Red Hat)" <[email protected]>

Create a seq_buf layer that trace_seq sits on. The seq_buf will not be limited to page size. This will allow other usages of seq_buf instead of a hard set PAGE_SIZE one that trace_seq has.

Signed-off-by Steven Rostedt <[email protected]>

Quoted 12 lines

---
 include/linux/seq_buf.h              |  58 ++++++
 include/linux/trace_seq.h            |  10 +-
 kernel/trace/Makefile                |   1 +
 kernel/trace/seq_buf.c               | 348 +++++++++++++++++++++++++++++++++++
 kernel/trace/trace.c                 |  39 ++--
 kernel/trace/trace_events.c          |   6 +-
 kernel/trace/trace_functions_graph.c |   6 +-
 kernel/trace/trace_seq.c             | 184 +++++++++---------
 8 files changed, 527 insertions(+), 125 deletions(-)
 create mode 100644 include/linux/seq_buf.h
 create mode 100644 kernel/trace/seq_buf.c

There is a lot of similar code in the two layers. Do you have any plans to transform the trace stuff to seq_buf and get rid of the trace_seq layer in long term?

If I get it correctly, the two layers are needed because:

1. seq_buf works with any buffer but
trace_seq with static buffer

2. seq_buf writes even part of the message until the buffer is full but trace_buf writes only full messages or nothing

3. seq_buf returns the number of written characters but trace_seq returns 1 on success and 0 on failure

4. seq_buf sets "overflow" flag when an operation failed but trace_seq sets "full" when this happens

I wounder if we could get a compromise and use only one layer.

Quoted 8 lines

ad 1st:

I have checked many locations and it seems that trace_seq_init() is called before the other functions as used. There is the WARN_ON() in the generic seq_buf() functions, so they would not crash. If there is some init missing, we could fix it later.

But I haven't really tested it yet.

Actually, there's a few hidden places that initialize a struct with kzalloc that contains a trace_seq. I started fixing them but there were more and more to find that I decided to give up and just add the check to see if it needed to be initialized at each call.

Not that pretty, but not that critical to be worth crashing something we missed. Maybe in the future this can change, but not now.

Quoted 5 lines

ad 2nd and 3rd:

These are connected.

Quoted 5 lines

On solution is to disable writing part of the text even in the generic seq_buf functions. I think that it is perfectly fine. If we do not print the entire line, we are in troubles anyway. Note that we could not allocate another buffer in NMI, so we will lose part of the message anyway.

This patch uses seq_buf for the NMI code so it will fill to the end of the buffer and just truncate what can't fit.

trace_pipe depends on the trace_seq behavior.

Quoted 4 lines

Another solution would be to live with incomplete lines in tracing. I wonder if any of the functions tries to write the line again when the write failed.

This may break trace_pipe. Although there looks to be redundant behavior in that the pipe code also resets the seq.len on partial line, so maybe it's not an issue.

Quoted 1 line

Quoted 2 lines

IMHO, the most important thing is that both functions return 0 on failure.

Note, I'm not sure how tightly these two need to be. I'm actually trying to get trace_seq to be specific to tracing and nothing more. Have seq_buf be used for all other instances.

Quoted 6 lines

ad 4th:

Both "full" and "overflow" flags seems to have the same meaning. For example, trace_seq_printf() sets "full" on failure even when s->seq.len != s->size.

The difference is that the overflow flag is just used for info letting the user know that it did not fit. The full flag in trace_seq lets you know that you can not add anything else, even though the new stuff may fit.

Quoted 2 lines

This patch uses seq_buf for the NMI code so it will fill to the end of the buffer and just truncate what can't fit.

I think that NMI code could live with the trace_seq behavior. The lines are short. If we miss few characters it is not that big difference.

Quoted 16 lines

trace_pipe depends on the trace_seq behavior.

Quoted 4 lines

Another solution would be to live with incomplete lines in tracing. I wonder if any of the functions tries to write the line again when the write failed.

This may break trace_pipe. Although there looks to be redundant behavior in that the pipe code also resets the seq.len on partial line, so maybe it's not an issue.

Quoted 3 lines

IMHO, the most important thing is that both functions return 0 on failure.

Quoted 3 lines

Note, I'm not sure how tightly these two need to be. I'm actually trying to get trace_seq to be specific to tracing and nothing more. Have seq_buf be used for all other instances.

If the two layers make your life easier then they might make sense. I just saw many similarities and wanted to help. IMHO, if anyone breaks seq_buf, it will break trace_seq anyway. So, they are not really separated.

Quoted 4 lines

Quoted 4 lines

ad 4th:

Quoted 8 lines

Quoted 3 lines

Both "full" and "overflow" flags seems to have the same meaning. For example, trace_seq_printf() sets "full" on failure even when s->seq.len != s->size.

The difference is that the overflow flag is just used for info letting the user know that it did not fit. The full flag in trace_seq lets you know that you can not add anything else, even though the new stuff may fit.

I see. They have another meaning but they are set at the same time:

	if (s->seq.overflow) {
		...
		s->full = 1;
		return 0;
	}

In fact, both names are slightly misleading. seq.overflow is set when the buffer is full even when all characters were written. s->full is set even when there is still some space :-)

I suggest to rename "overflow" to "full" and have it only in the struct "seq_buf". Then it has the right meaning in "seq_buf" and is still backward compatible with "trace_seq".

Best Regards,
Petr

Quoted 5 lines · On Fri, 27 Jun 2014 17:18:04 +0200 Petr Mládek <[email protected]> wrote:

Quoted 2 lines

This patch uses seq_buf for the NMI code so it will fill to the end of the buffer and just truncate what can't fit.

I think that NMI code could live with the trace_seq behavior. The lines are short. If we miss few characters it is not that big difference.

True, but I'm trying to keep trace_seq more tracing specific.

Quoted 20 lines

Quoted 19 lines

trace_pipe depends on the trace_seq behavior.

Quoted 4 lines

Another solution would be to live with incomplete lines in tracing. I wonder if any of the functions tries to write the line again when the write failed.

This may break trace_pipe. Although there looks to be redundant behavior in that the pipe code also resets the seq.len on partial line, so maybe it's not an issue.

Quoted 3 lines

IMHO, the most important thing is that both functions return 0 on failure.

Note, I'm not sure how tightly these two need to be. I'm actually trying to get trace_seq to be specific to tracing and nothing more. Have seq_buf be used for all other instances.

Quoted 3 lines

If the two layers make your life easier then they might make sense. I just saw many similarities and wanted to help. IMHO, if anyone breaks seq_buf, it will break trace_seq anyway. So, they are not really separated.

There's actually things I want to do with the seq_buf behavior that I can't do with the trace_seq behavior. That's more about having a dynamic way to create seq_buf buffers and resize them if need be. Although, perhaps an all or nothing approach will help in that.

Quoted 21 lines

Quoted 4 lines

Quoted 4 lines

ad 4th:

Quoted 8 lines

Quoted 3 lines

Both "full" and "overflow" flags seems to have the same meaning. For example, trace_seq_printf() sets "full" on failure even when s->seq.len != s->size.

The difference is that the overflow flag is just used for info letting the user know that it did not fit. The full flag in trace_seq lets you know that you can not add anything else, even though the new stuff may fit.

I see. They have another meaning but they are set at the same time:

	if (s->seq.overflow) {
		...
		s->full = 1;
		return 0;
	}

Quoted 3 lines

In fact, both names are slightly misleading. seq.overflow is set when the buffer is full even when all characters were written. s->full is set even when there is still some space :-)

I actually disagree. overflow means that you wrote more than what was there. In this case, it was cropped.

Full suggests that you can't add anymore because it wont allow you.

The difference is that you are looking at a implementation point of view. I'm looking at a usage point of view. With trace_seq, there is no space left, you can't add any more. seq_buf, you can add more but it wont be saved because it was overflowed.

What I should do is change overflow from being a flag to the number of characters that it overflowed by. That would be useful information, and would make more sense. It lets the user know what wasn't written.

Quoted 7 lines · Steven Rostedt

Quoted 3 lines · On Fri, 27 Jun 2014 17:18:04 +0200 Petr Mládek <[email protected]> wrote:

Quoted 2 lines

This patch uses seq_buf for the NMI code so it will fill to the end of the buffer and just truncate what can't fit.

Quoted 4 lines

Quoted 2 lines

I think that NMI code could live with the trace_seq behavior. The lines are short. If we miss few characters it is not that big difference.

True, but I'm trying to keep trace_seq more tracing specific.

It is true that most writing functions write as much as possible. On the other hand, I do not think that refusing to write, if there is not enough space, is specific to tracing. It might be useful also for others.

In the worst case, we could add a flag into the "struct seq_buf" that might define the behavior. Well, I am not sure if we want to add this complexity when there are no users. As I said, the backtraces might live with trace_seq behavior.

Quoted 24 lines

Quoted 23 lines

Quoted 13 lines

trace_pipe depends on the trace_seq behavior.

Quoted 4 lines

Another solution would be to live with incomplete lines in tracing. I wonder if any of the functions tries to write the line again when the write failed.

This may break trace_pipe. Although there looks to be redundant behavior in that the pipe code also resets the seq.len on partial line, so maybe it's not an issue.

Quoted 1 line

Quoted 6 lines

Quoted 2 lines

IMHO, the most important thing is that both functions return 0 on failure.

Note, I'm not sure how tightly these two need to be. I'm actually trying to get trace_seq to be specific to tracing and nothing more. Have seq_buf be used for all other instances.

If the two layers make your life easier then they might make sense. I just saw many similarities and wanted to help. IMHO, if anyone breaks seq_buf, it will break trace_seq anyway. So, they are not really separated.

Quoted 4 lines

There's actually things I want to do with the seq_buf behavior that I can't do with the trace_seq behavior. That's more about having a dynamic way to create seq_buf buffers and resize them if need be. Although, perhaps an all or nothing approach will help in that.

Note that we should not allocate in NMI context, especially when there is a softlock. So, we might need to define the behavior anyway.

Quoted 15 lines

Quoted 15 lines

Quoted 14 lines

Quoted 9 lines

ad 4th:

Both "full" and "overflow" flags seems to have the same meaning. For example, trace_seq_printf() sets "full" on failure even when s->seq.len != s->size.

The difference is that the overflow flag is just used for info letting the user know that it did not fit. The full flag in trace_seq lets you know that you can not add anything else, even though the new stuff may fit.

Quoted 7 lines

Quoted 7 lines

I see. They have another meaning but they are set at the same time:

	if (s->seq.overflow) {
		...
		s->full = 1;
		return 0;
	}

Quoted 7 lines

Quoted 4 lines

In fact, both names are slightly misleading. seq.overflow is set when the buffer is full even when all characters were written. s->full is set even when there is still some space :-)

I actually disagree. overflow means that you wrote more than what was there. In this case, it was cropped.

The problem is that we do not know that it was cropped.

The "overflow" flag is set when (s->len > (s->size - 1)). In most cases it will be set when (s->len == s->size).

For example, seq_buf_printf() calls vsnprintf(). It will never write over the buffer. We do not know if the message was cropped or if we were lucky and the message was exactly as long as the free space.

Quoted 7 lines

Full suggests that you can't add anymore because it wont allow you.

The difference is that you are looking at a implementation point of view. I'm looking at a usage point of view. With trace_seq, there is no space left, you can't add any more. seq_buf, you can add more but it wont be saved because it was overflowed.

I know that there is some difference but I am not sure if users are really interested into such details. In both cases, they are unable to write more data. From they point of view, the buffer is simply full. Honestly, I think that the two flags and the two point of view cause more confusion than win.

Note that I do not want to change the meaning for trace_buf. I want to change the meaning for "seq_buf" that has no users yet.

Quoted 5 lines

What I should do is change overflow from being a flag to the number of characters that it overflowed by. That would be useful information, and would make more sense. It lets the user know what wasn't written.

I am afraid that we do not have this information. See above for the example with vsnprintf().

In each case, I do not want to block this patch. The generic "seq_buf" API looks reasonable. The tracing code is your area and it is your decision. You know much more about it than me and the extra complexity might be needed.

As people are asking for this patch series to be added, I'm going back through your comments. I never replied to this email (at least my email client says I did not).

Quoted 8 lines · On Fri, 27 Jun 2014 18:52:04 +0200 Petr Mládek <[email protected]> wrote:

Quoted 7 lines · Steven Rostedt

Quoted 3 lines · On Fri, 27 Jun 2014 17:18:04 +0200 Petr Mládek <[email protected]> wrote:

Quoted 2 lines

This patch uses seq_buf for the NMI code so it will fill to the end of the buffer and just truncate what can't fit.

Quoted 8 lines

Quoted 4 lines

Quoted 2 lines

I think that NMI code could live with the trace_seq behavior. The lines are short. If we miss few characters it is not that big difference.

True, but I'm trying to keep trace_seq more tracing specific.

It is true that most writing functions write as much as possible. On the other hand, I do not think that refusing to write, if there is not enough space, is specific to tracing. It might be useful also for others.

Looking at what seq_file does, for example seq_printf(), it fills the buffer to the max size. If the printf is truncated, it sets the count to the size of the buffer. Then in traverse(), it detects that an overflow happened and stops reading, frees the buffer, increases the size of the buffer (by power of two), and then tries again with the bigger buffer.

Really, it doesn't matter if seq_printf() didn't write anything or if it truncated, the result would be the same. Perhaps then I can keep seq_buf doing a all or nothing approach like trace_seq does. I think it was Andrew (akpm) that criticized this behavior.

Quoted 16 lines

Quoted 16 lines

Quoted 16 lines

Quoted 15 lines

Quoted 10 lines

ad 4th:

Both "full" and "overflow" flags seems to have the same meaning. For example, trace_seq_printf() sets "full" on failure even when s->seq.len != s->size.

The difference is that the overflow flag is just used for info letting the user know that it did not fit. The full flag in trace_seq lets you know that you can not add anything else, even though the new stuff may fit.

Quoted 7 lines

Quoted 7 lines

Quoted 7 lines

I see. They have another meaning but they are set at the same time:

	if (s->seq.overflow) {
		...
		s->full = 1;
		return 0;
	}

Well, if it is overflowed, it can't write anymore ;-)

But notice that the seq.len is still the same. Hmm, I need to zero that as well. As tools are allowed to print s->buffer with it. We don't want added data to it.

Quoted 8 lines

Quoted 7 lines

Quoted 4 lines

In fact, both names are slightly misleading. seq.overflow is set when the buffer is full even when all characters were written. s->full is set even when there is still some space :-)

I actually disagree. overflow means that you wrote more than what was there. In this case, it was cropped.

Quoted 9 lines

The problem is that we do not know that it was cropped.

The "overflow" flag is set when (s->len > (s->size - 1)). In most cases it will be set when (s->len == s->size).

For example, seq_buf_printf() calls vsnprintf(). It will never write over the buffer. We do not know if the message was cropped or if we were lucky and the message was exactly as long as the free space.

Again, I was doing this because of what was suggested before. I'll try to find the email. I may work to have seq_buf() be used for seq_file first, and then make trace_seq() use it. That might make even more sense.

Quoted 4 lines

In each case, I do not want to block this patch. The generic "seq_buf" API looks reasonable. The tracing code is your area and it is your decision. You know much more about it than me and the extra complexity might be needed.

Yeah, we can always change it later. It's not an interface into userspace, thus it's not set in stone. But I still want something that is reasonable before pushing further. I'll go find those comments from Andrew and see where things can be figured out. Perhaps writing a patch that makes seq_file() use seq_buf might show what is needed better.

ad 4th:

Both "full" and "overflow" flags seems to have the same meaning. For example, trace_seq_printf() sets "full" on failure even when s->seq.len != s->size.

Best Regards,
Petr

[...]

Quoted 21 lines

kernel/trace/seq_buf.c new file +18 -0

@@ -0,0 +1,348 @@
+/*
+ * seq_buf.c
+ *
+ * Copyright (C) 2014 Red Hat Inc, Steven Rostedt <[email protected]>
+ *
+ * The seq_buf is a handy tool that allows you to pass a descriptor around
+ * to a buffer that other functions can write to. It is similar to the
+ * seq_file functionality but has some differences.
+ *
+ * To use it, the seq_buf must be initialized with seq_buf_init().
+ * This will set up the counters within the descriptor. You can call
+ * seq_buf_init() more than once to reset the seq_buf to start
+ * from scratch.
+ * 
+ */
+#include <linux/uaccess.h>
+#include <linux/seq_file.h>
+#include <linux/seq_buf.h>

kernel/trace/seq_buf.c line 28

Quoted 10 lines

kernel/trace/seq_buf.c new file +10 -0

+
+/* How much buffer is left on the seq_buf? */
+#define SEQ_BUF_LEFT(s) (((s)->size - 1) - (s)->len)
+
+/* How much buffer is written? */
+#define SEQ_BUF_USED(s) min((s)->len, (s)->size - 1)
+
+static inline void seq_buf_check_len(struct seq_buf *s)
+{
+	if (unlikely(s->len > (s->size - 1))) {

I would create macro for this check. It is repeated many times. I mean

#define SEQ_BUF_OVERFLOW(s) (s->len > (s->size - 1))

if (unlikely(SEQ_BUF_OVERFLOW))

Quoted 6 lines

kernel/trace/seq_buf.c new file +5 -0

+		s->len = s->size - 1;
+		s->overflow = 1;
+	}
+}
+

[...]

Quoted 16 lines

kernel/trace/seq_buf.c new file +16 -0

+#define MAX_MEMHEX_BYTES	8U
+#define HEX_CHARS		(MAX_MEMHEX_BYTES*2 + 1)
+
+/**
+ * seq_buf_putmem_hex - write raw memory into the buffer in ASCII hex
+ * @s: seq_buf descriptor
+ * @mem: The raw memory to write its hex ASCII representation of
+ * @len: The length of the raw memory to copy (in bytes)
+ *
+ * This is similar to seq_buf_putmem() except instead of just copying the
+ * raw memory into the buffer it writes its ASCII representation of it
+ * in hex characters.
+ *
+ * Returns how much it wrote to the buffer.
+ */
+int seq_buf_putmem_hex(struct seq_buf *s, const void *mem,

kernel/trace/seq_buf.c line 251

Quoted 10 lines

kernel/trace/seq_buf.c new file +10 -0

+		       unsigned int len)
+{
+	unsigned char hex[HEX_CHARS];
+	const unsigned char *data = mem;
+	unsigned int start_len;
+	int i, j;
+	int cnt = 0;
+
+	while (len) {
+		start_len = min(len, HEX_CHARS - 1);

I would do s/start_len/end_len/

I know that it depends on the point of view. But iteration between "0" and "end" is better understandable for me :-)

Quoted 33 lines

kernel/trace/seq_buf.c new file +32 -0

+#ifdef __BIG_ENDIAN
+		for (i = 0, j = 0; i < start_len; i++) {
+#else
+		for (i = start_len-1, j = 0; i >= 0; i--) {
+#endif
+			hex[j++] = hex_asc_hi(data[i]);
+			hex[j++] = hex_asc_lo(data[i]);
+		}
+		if (WARN_ON_ONCE(j == 0 || j/2 > len))
+			break;
+
+		/* j increments twice per loop */
+		len -= j / 2;
+		hex[j++] = ' ';
+
+		cnt += seq_buf_putmem(s, hex, j);
+	}
+	return cnt;
+}
+
+/**
+ * seq_buf_path - copy a path into the sequence buffer
+ * @s: seq_buf descriptor
+ * @path: path to write into the sequence buffer.
+ *
+ * Write a path name into the sequence buffer.
+ *
+ * Returns the number of bytes written into the buffer.
+ */
+int seq_buf_path(struct seq_buf *s, const struct path *path)
+{
+	unsigned int len = SEQ_BUF_LEFT(s);

kernel/trace/seq_buf.c line 293

Quoted 10 lines

kernel/trace/seq_buf.c new file +10 -0

+	unsigned char *p;
+	unsigned int start = s->len;
+
+	WARN_ON((int)len < 0);
+	p = d_path(path, s->buffer + s->len, len);
+	if (!IS_ERR(p)) {
+		p = mangle_path(s->buffer + s->len, p, "\n");
+		if (p) {
+			s->len = p - s->buffer;
+	WARN_ON(s->len > (s->size - 1));

strange indentation

kernel/trace/seq_buf.c line 298

Quoted 5 lines

kernel/trace/seq_buf.c new file +5 -0

+			return s->len - start;
+		}
+	} else {
+		s->buffer[s->len++] = '?';
+	WARN_ON(s->len > (s->size - 1));

same here

kernel/trace/seq_buf.c line 305

Quoted 8 lines

kernel/trace/seq_buf.c new file +7 -0

+		return s->len - start;
+	}
+
+	s->overflow = 1;
+	return 0;
+}
+

Best Regards,
Petr

Quoted 10 lines · On Fri, 27 Jun 2014 15:45:38 +0200 Petr Mládek <[email protected]> wrote:

ad 4th:

Both "full" and "overflow" flags seems to have the same meaning. For example, trace_seq_printf() sets "full" on failure even when s->seq.len != s->size.

Best Regards,
Petr

Quoted 1 line

[...]

BTW, you shouldn't sign off if you have more comments, I usually stop reading when I see someone's signature. Or at the very least, state that you have more comments below.

Quoted 30 lines

Quoted 17 lines

kernel/trace/seq_buf.c new file +16 -0

+#define MAX_MEMHEX_BYTES	8U
+#define HEX_CHARS		(MAX_MEMHEX_BYTES*2 + 1)
+
+/**
+ * seq_buf_putmem_hex - write raw memory into the buffer in ASCII hex
+ * @s: seq_buf descriptor
+ * @mem: The raw memory to write its hex ASCII representation of
+ * @len: The length of the raw memory to copy (in bytes)
+ *
+ * This is similar to seq_buf_putmem() except instead of just copying the
+ * raw memory into the buffer it writes its ASCII representation of it
+ * in hex characters.
+ *
+ * Returns how much it wrote to the buffer.
+ */
+int seq_buf_putmem_hex(struct seq_buf *s, const void *mem,

kernel/trace/seq_buf.c line 251

Quoted 10 lines

kernel/trace/seq_buf.c new file +10 -0

+		       unsigned int len)
+{
+	unsigned char hex[HEX_CHARS];
+	const unsigned char *data = mem;
+	unsigned int start_len;
+	int i, j;
+	int cnt = 0;
+
+	while (len) {
+		start_len = min(len, HEX_CHARS - 1);

I would do s/start_len/end_len/

Quoted 2 lines

I know that it depends on the point of view. But iteration between "0" and "end" is better understandable for me :-)

Yeah, I didn't like the name of that variable. I guess end_len is better, but still not exactly what I want to call it. Unfortunately, I don't know what exactly I want to call it ;-)

From: "Steven Rostedt (Red Hat)" <[email protected]>

The seq_buf functions are rather useful outside of tracing. Instead of having it be dependent on CONFIG_TRACING, move the code into lib/ and allow other users to have access to it even when tracing is not configured.

The seq_buf utility is similar to the seq_file utility, but instead of writing sending data back up to userland, it writes it into a buffer defined at seq_buf_init(). This allows us to send a descriptor around that writes printf() formatted strings into it that can be retrieved later.

It is currently used by the tracing facility for such things like trace events to convert its binary saved data in the ring buffer into an ASCII human readable context to be displayed in /sys/kernel/debug/trace.

It can also be used for doing NMI prints safely from NMI context into the seq_buf and retrieved later and dumped to printk() safely. Doing printk() from an NMI context is dangerous because an NMI can preempt a current printk() and deadlock on it.

Link http://lkml.kernel.org/p/[email protected] open here

Signed-off-by Steven Rostedt <[email protected]>

---
 kernel/trace/seq_buf.c | 348 -------------------------------------------------
 lib/Makefile           |   2 +-
 lib/seq_buf.c          | 348 +++++++++++++++++++++++++++++++++++++++++++++++++
 lib/trace_seq.c        | 303 ++++++++++++++++++++++++++++++++++++++++++

 4 files changed, 652 insertions(+), 349 deletions(-)
 delete mode 100644 kernel/trace/seq_buf.c
 create mode 100644 lib/seq_buf.c
 create mode 100644 lib/trace_seq.c

lib/Makefile +0 -0

index ba967a19edba..6007194082c6 100644

Quoted 24 lines · Steven Rostedt

From: "Steven Rostedt (Red Hat)" <[email protected]>

The seq_buf functions are rather useful outside of tracing. Instead of having it be dependent on CONFIG_TRACING, move the code into lib/ and allow other users to have access to it even when tracing is not configured.

The seq_buf utility is similar to the seq_file utility, but instead of writing sending data back up to userland, it writes it into a buffer defined at seq_buf_init(). This allows us to send a descriptor around that writes printf() formatted strings into it that can be retrieved later.

It is currently used by the tracing facility for such things like trace events to convert its binary saved data in the ring buffer into an ASCII human readable context to be displayed in /sys/kernel/debug/trace.

It can also be used for doing NMI prints safely from NMI context into the seq_buf and retrieved later and dumped to printk() safely. Doing printk() from an NMI context is dangerous because an NMI can preempt a current printk() and deadlock on it.

Link http://lkml.kernel.org/p/[email protected] open here

Quoted 6 lines

Signed-off-by Steven Rostedt <[email protected]>

---
 kernel/trace/seq_buf.c | 348 -------------------------------------------------
 lib/Makefile           |   2 +-
 lib/seq_buf.c          | 348 +++++++++++++++++++++++++++++++++++++++++++++++++
 lib/trace_seq.c        | 303 ++++++++++++++++++++++++++++++++++++++++++

I guess that lib/trace_seq.c was copied by mistake.

Quoted 17 lines

 4 files changed, 652 insertions(+), 349 deletions(-)
 delete mode 100644 kernel/trace/seq_buf.c
 create mode 100644 lib/seq_buf.c
 create mode 100644 lib/trace_seq.c

lib/Makefile +1 -1

index ba967a19edba..6007194082c6 100644
@@ -13,7 +13,7 @@ lib-y := ctype.o string.o vsprintf.o cmdline.o \
 	 sha1.o md5.o irq_regs.o reciprocal_div.o argv_split.o \
 	 proportions.o flex_proportions.o prio_heap.o ratelimit.o show_mem.o \
 	 is_single_threaded.o plist.o decompress.o kobject_uevent.o \
-	 earlycpio.o
+	 earlycpio.o seq_buf.o
 

lib/Makefile lib-y := ctype.o string.o vsprintf.o cmdline.o \ · line 19

Quoted 2 lines

lib/Makefile +0 -0

 obj-$(CONFIG_ARCH_HAS_DEBUG_STRICT_USER_COPY_CHECKS) += usercopy.o
 lib-$(CONFIG_MMU) += ioremap.o

There is missing:

kernel/trace/Makefile +0 -1

index edc98c72a634..67d6369ddf83 100644
@@ -29,7 +29,6 @@ obj-$(CONFIG_RING_BUFFER_BENCHMARK) += ring_buffer_benchmark.o
 obj-$(CONFIG_TRACING) += trace.o
 obj-$(CONFIG_TRACING) += trace_output.o
 obj-$(CONFIG_TRACING) += trace_seq.o
-obj-$(CONFIG_TRACING) += seq_buf.o
 obj-$(CONFIG_TRACING) += trace_stat.o
 obj-$(CONFIG_TRACING) += trace_printk.o
 obj-$(CONFIG_CONTEXT_SWITCH_TRACER) += trace_sched_switch.o

Best Regards,
Petr

Quoted 25 lines · On Fri, 27 Jun 2014 15:48:10 +0200 Petr Mládek <[email protected]> wrote:

Quoted 24 lines · Steven Rostedt

From: "Steven Rostedt (Red Hat)" <[email protected]>

The seq_buf functions are rather useful outside of tracing. Instead of having it be dependent on CONFIG_TRACING, move the code into lib/ and allow other users to have access to it even when tracing is not configured.

The seq_buf utility is similar to the seq_file utility, but instead of writing sending data back up to userland, it writes it into a buffer defined at seq_buf_init(). This allows us to send a descriptor around that writes printf() formatted strings into it that can be retrieved later.

It is currently used by the tracing facility for such things like trace events to convert its binary saved data in the ring buffer into an ASCII human readable context to be displayed in /sys/kernel/debug/trace.

It can also be used for doing NMI prints safely from NMI context into the seq_buf and retrieved later and dumped to printk() safely. Doing printk() from an NMI context is dangerous because an NMI can preempt a current printk() and deadlock on it.

Link http://lkml.kernel.org/p/[email protected] open here

Quoted 8 lines

Quoted 6 lines

Signed-off-by Steven Rostedt <[email protected]>

---
 kernel/trace/seq_buf.c | 348 -------------------------------------------------
 lib/Makefile           |   2 +-
 lib/seq_buf.c          | 348 +++++++++++++++++++++++++++++++++++++++++++++++++
 lib/trace_seq.c        | 303 ++++++++++++++++++++++++++++++++++++++++++

I guess that lib/trace_seq.c was copied by mistake.

Heh, that's what I get for using both quilt and git :-)

To start with what I had before (and use my scripts for the Link tag), I pulled the old patch from my email and pulled it into a quilt queue. Did a "quilt push -f" and then started from there. I removed all the trace_seq.c updates but forgot that quilt push -f would create the file in lib/.

When done with all my updates, I just did a git am of the patch in my quilt queue, which pulled in the old copy of trace_seq.c in lib/ :-p

I'll remove it.

Quoted 17 lines

Quoted 17 lines

 4 files changed, 652 insertions(+), 349 deletions(-)
 delete mode 100644 kernel/trace/seq_buf.c
 create mode 100644 lib/seq_buf.c
 create mode 100644 lib/trace_seq.c

lib/Makefile +1 -1

index ba967a19edba..6007194082c6 100644
@@ -13,7 +13,7 @@ lib-y := ctype.o string.o vsprintf.o cmdline.o \
 	 sha1.o md5.o irq_regs.o reciprocal_div.o argv_split.o \
 	 proportions.o flex_proportions.o prio_heap.o ratelimit.o show_mem.o \
 	 is_single_threaded.o plist.o decompress.o kobject_uevent.o \
-	 earlycpio.o
+	 earlycpio.o seq_buf.o
 

Quoted 4 lines

lib/Makefile lib-y := ctype.o string.o vsprintf.o cmdline.o \ · line 19

Quoted 2 lines

lib/Makefile +0 -0

 obj-$(CONFIG_ARCH_HAS_DEBUG_STRICT_USER_COPY_CHECKS) += usercopy.o
 lib-$(CONFIG_MMU) += ioremap.o

There is missing:

Nope, it just was copied by mistake. It only added dead code, it didn't move it.

-- Steve

Quoted 17 lines

kernel/trace/Makefile +0 -1

index edc98c72a634..67d6369ddf83 100644
@@ -29,7 +29,6 @@ obj-$(CONFIG_RING_BUFFER_BENCHMARK) += ring_buffer_benchmark.o
 obj-$(CONFIG_TRACING) += trace.o
 obj-$(CONFIG_TRACING) += trace_output.o
 obj-$(CONFIG_TRACING) += trace_seq.o
-obj-$(CONFIG_TRACING) += seq_buf.o
 obj-$(CONFIG_TRACING) += trace_stat.o
 obj-$(CONFIG_TRACING) += trace_printk.o
 obj-$(CONFIG_CONTEXT_SWITCH_TRACER) += trace_sched_switch.o

Best Regards,
Petr

Quoted 2 lines

Nope, it just was copied by mistake. It only added dead code, it didn't move it.

It is really missing! You removed kernel/trace/seq_buf.c and you have to remove it also from kernel/trace/Makefile. :-)

Best Regards,
Petr

Quoted 20 lines

-- Steve

Quoted 17 lines

kernel/trace/Makefile +0 -1

index edc98c72a634..67d6369ddf83 100644
@@ -29,7 +29,6 @@ obj-$(CONFIG_RING_BUFFER_BENCHMARK) += ring_buffer_benchmark.o
 obj-$(CONFIG_TRACING) += trace.o
 obj-$(CONFIG_TRACING) += trace_output.o
 obj-$(CONFIG_TRACING) += trace_seq.o
-obj-$(CONFIG_TRACING) += seq_buf.o
 obj-$(CONFIG_TRACING) += trace_stat.o
 obj-$(CONFIG_TRACING) += trace_printk.o
 obj-$(CONFIG_CONTEXT_SWITCH_TRACER) += trace_sched_switch.o

Best Regards,
Petr

From: "Steven Rostedt (Red Hat)" <[email protected]>

Being able to divert printk to call another function besides the normal logging is useful for such things like NMI handling. If some functions are to be called from NMI that does printk() it is possible to lock up the box if the nmi handler triggers when another printk is happening.

One example of this use is to perform a stack trace on all CPUs via NMI. But if the NMI is to do the printk() it can cause the system to lock up. By allowing the printk to be diverted to another function that can safely record the printk output and then print it when it in a safe context then NMIs will be safe to call these functions like show_regs().

Link http://lkml.kernel.org/p/[email protected] open here

Acked-by Paul E. McKenney <[email protected]>

Signed-off-by Steven Rostedt <[email protected]>

---
 include/linux/percpu.h |  3 +++
 include/linux/printk.h |  2 ++
 kernel/printk/printk.c | 38 +++++++++++++++++++++++++++++---------
 3 files changed, 34 insertions(+), 9 deletions(-)

include/linux/percpu.h +3 -0

index 8419053d0f2e..9997c92ce3bd 100644
@@ -802,4 +802,7 @@ do { __this_cpu_preempt_check("or");					\
 	(__this_cpu_preempt_check("cmpxchg_double"),__pcpu_double_call_return_bool(raw_cpu_cmpxchg_double_, (pcp1), (pcp2), (oval1), (oval2), (nval1), (nval2)))
 #endif
 
+/* To avoid include hell, as printk can not declare this, we declare it here */
+DECLARE_PER_CPU(printk_func_t, printk_func);
+
 #endif /* __LINUX_PERCPU_H */

include/linux/printk.h +2 -0

index 319ff7e53efb..e26310b2d2fd 100644
@@ -159,6 +159,8 @@ extern int kptr_restrict;
 
 extern void wake_up_klogd(void);
 
+typedef int(*printk_func_t)(const char *fmt, va_list args);
+
 void log_buf_kexec_setup(void);
 void __init setup_log_buf(int early);
 void dump_stack_set_arch_desc(const char *fmt, ...);

kernel/printk/printk.c +25 -1

index ea2d5f6962ed..e3581f95ba5c 100644
@@ -1764,6 +1764,30 @@ asmlinkage int printk_emit(int facility, int level,
 }
 EXPORT_SYMBOL(printk_emit);
 
+int vprintk_default(const char *fmt, va_list args)
+{
+	int r;
+
+#ifdef CONFIG_KGDB_KDB
+	if (unlikely(kdb_trap_printk)) {
+		r = vkdb_printf(fmt, args);
+		return r;
+	}
+#endif
+	r = vprintk_emit(0, -1, NULL, 0, fmt, args);
+
+	return r;
+}
+EXPORT_SYMBOL_GPL(vprintk_default);
+
+/*
+ * This allows printk to be diverted to another function per cpu.
+ * This is useful for calling printk functions from within NMI
+ * without worrying about race conditions that can lock up the
+ * box.
+ */
+DEFINE_PER_CPU(printk_func_t, printk_func) = vprintk_default;
+
 /**
  * printk - print a kernel message
  * @fmt: format string

@@ -1787,19 +1811,15 @@ EXPORT_SYMBOL(printk_emit);
  */
 asmlinkage __visible int printk(const char *fmt, ...)
 {
+	printk_func_t vprintk_func;
 	va_list args;
 	int r;
 
-#ifdef CONFIG_KGDB_KDB

kernel/printk/printk.c EXPORT_SYMBOL(printk_emit); · line 1819

Quoted 3 lines

kernel/printk/printk.c +1 -1

 	va_start(args, fmt);
-	r = vprintk_emit(0, -1, NULL, 0, fmt, args);
+	preempt_disable();

I think that it is too late to disable the preemption here. It has to be done by the printk() caller if it wants to be sure that the requested function is used.

kernel/printk/printk.c EXPORT_SYMBOL(printk_emit); · line 1825

Quoted 7 lines

kernel/printk/printk.c +3 -0

+	vprintk_func = this_cpu_read(printk_func);
+	r = vprintk_func(fmt, args);
+	preempt_enable();
 	va_end(args);
 
 	return r;

Best Regards,
Petr

Quoted 7 lines · On Fri, 27 Jun 2014 16:20:25 +0200 Petr Mládek <[email protected]> wrote:

kernel/printk/printk.c EXPORT_SYMBOL(printk_emit); · line 1819

Quoted 3 lines

kernel/printk/printk.c +1 -1

 	va_start(args, fmt);
-	r = vprintk_emit(0, -1, NULL, 0, fmt, args);
+	preempt_disable();

I think that it is too late to disable the preemption here. It has to be done by the printk() caller if it wants to be sure that the requested function is used.

That's only if the printk() caller cares. But it would be nice that we run the printk_func for the CPU that vprintk_func() is on, thus the preempt_disable() is required. (in -rt, this would turn into a migrate_disable()).

-- Steve

Quoted 10 lines

kernel/printk/printk.c EXPORT_SYMBOL(printk_emit); · line 1825

Quoted 7 lines

kernel/printk/printk.c +3 -0

+	vprintk_func = this_cpu_read(printk_func);
+	r = vprintk_func(fmt, args);
+	preempt_enable();
 	va_end(args);
 
 	return r;

Best Regards,
Petr

Quoted 1 line

Quoted 1 line

[email protected] (reading confirmation): 550 5.7.1 Content-Policy reject msg: Wrong MIME labeling on 8-bit character texts. BF:<H 0>; S1751405AbaFZWBb

From: "Steven Rostedt (Red Hat)" <[email protected]>

When trigger_all_cpu_backtrace() is called on x86, it will trigger an NMI on each CPU and call show_regs(). But this can lead to a hard lock up if the NMI comes in on another printk().

In order to avoid this, when the NMI triggers, it switches the printk routine for that CPU to call a NMI safe printk function that records the printk in a per_cpu seq_buf descriptor. After all NMIs have finished recording its data, the trace_seqs are printed in a safe context.

Link http://lkml.kernel.org/p/[email protected] open here

Acked-by Paul E. McKenney <[email protected]>

Signed-off-by Steven Rostedt <[email protected]>

---
V2 - updated to use seq_buf instead of trace_seq.
- Keep original printk loglevel, do not strip it, but use it. (suggested by Petr Mladek)
- Updated comments
- Removed return of true (noticed by Petr Mladek)

---
 arch/x86/kernel/apic/hw_nmi.c | 84 +++++++++++++++++++++++++++++++++++++++++--
 1 file changed, 81 insertions(+), 3 deletions(-)

arch/x86/kernel/apic/hw_nmi.c +81 -3

index c3fcb5de5083..91ddba672839 100644
@@ -18,6 +18,7 @@
 #include <linux/nmi.h>
 #include <linux/module.h>
 #include <linux/delay.h>
+#include <linux/seq_buf.h>
 
 #ifdef CONFIG_HARDLOCKUP_DETECTOR
 u64 hw_nmi_get_sample_period(int watchdog_thresh)

@@ -30,11 +31,31 @@ u64 hw_nmi_get_sample_period(int watchdog_thresh)
 /* For reliability, we're prepared to waste bits here. */
 static DECLARE_BITMAP(backtrace_mask, NR_CPUS) __read_mostly;
 
+#define NMI_BUF_SIZE		4096
+
+struct nmi_seq_buf {
+	unsigned char		buffer[NMI_BUF_SIZE];
+	struct seq_buf		seq;
+};
+
+/* Safe printing in NMI context */
+static DEFINE_PER_CPU(struct nmi_seq_buf, nmi_print_seq);
+
 /* "in progress" flag of arch_trigger_all_cpu_backtrace */
 static unsigned long backtrace_flag;
 
+static void print_seq_line(struct nmi_seq_buf *s, int last, int pos)
+{
+	const char *buf = s->buffer + last;
+
+	printk("%.*s", (pos - last) + 1, buf);
+}
+
 void arch_trigger_all_cpu_backtrace(void)
 {
+	struct nmi_seq_buf *s;
+	int len;
+	int cpu;
 	int i;
 
 	if (test_and_set_bit(0, &backtrace_flag))

@@ -44,6 +65,15 @@ void arch_trigger_all_cpu_backtrace(void)
 		 */
 		return;
 
+	/*
+	 * Set up per_cpu seq_buf buffers that the NMIs running on the other
+	 * CPUs will write to.
+	 */
+	for_each_possible_cpu(cpu) {
+		s = &per_cpu(nmi_print_seq, cpu);
+		seq_buf_init(&s->seq, s->buffer, NMI_BUF_SIZE);
+	}
+
 	cpumask_copy(to_cpumask(backtrace_mask), cpu_online_mask);
 
 	printk(KERN_INFO "sending NMI to all CPUs:\n");

@@ -56,10 +86,56 @@ void arch_trigger_all_cpu_backtrace(void)
 		mdelay(1);
 	}
 
+	/*
+	 * Now that all the NMIs have triggered, we can dump out their
+	 * back traces safely to the console.
+	 */
+	for_each_possible_cpu(cpu) {
+		int last_i = 0;
+
+		s = &per_cpu(nmi_print_seq, cpu);
+		len = s->seq.len;
+		if (!len)
+			continue;
+
+		/* Print line by line. */
+		for (i = 0; i < len; i++) {
+			if (s->buffer[i] == '\n') {
+				print_seq_line(s, last_i, i);
+				last_i = i + 1;
+			}
+		}
+		if (last_i < i - 1) {
+			print_seq_line(s, last_i, i);
+			pr_cont("\n");
+		}
+	}
+
 	clear_bit(0, &backtrace_flag);
 	smp_mb__after_atomic();
 }
 
+/*
+ * It is not safe to call printk() directly from NMI handlers.
+ * It may be fine if the NMI detected a lock up and we have no choice
+ * but to do so, but doing a NMI on all other CPUs to get a back trace
+ * can be done with a sysrq-l. We don't want that to lock up, which
+ * can happen if the NMI interrupts a printk in progress.
+ *
+ * Instead, we redirect the vprintk() to this nmi_vprintk() that writes
+ * the content into a per cpu seq_buf buffer. Then when the NMIs are
+ * all done, we can safely dump the contents of the seq_buf to a printk()
+ * from a non NMI context.
+ */
+static int nmi_vprintk(const char *fmt, va_list args)
+{
+	struct nmi_seq_buf *s = this_cpu_ptr(&nmi_print_seq);
+	unsigned int len = s->seq.len;
+
+	seq_buf_vprintf(&s->seq, fmt, args);
+	return s->seq.len - len;
+}
+
 static int
 arch_trigger_all_cpu_backtrace_handler(unsigned int cmd, struct pt_regs *regs)
 {

@@ -68,12 +144,14 @@ arch_trigger_all_cpu_backtrace_handler(unsigned int cmd, struct pt_regs *regs)
 	cpu = smp_processor_id();
 
 	if (cpumask_test_cpu(cpu, to_cpumask(backtrace_mask))) {
-		static arch_spinlock_t lock = __ARCH_SPIN_LOCK_UNLOCKED;
+		printk_func_t printk_func_save = this_cpu_read(printk_func);
 
-		arch_spin_lock(&lock);
+		/* Replace printk to write into the NMI seq */
+		this_cpu_write(printk_func, nmi_vprintk);
 		printk(KERN_WARNING "NMI backtrace for cpu %d\n", cpu);
 		show_regs(regs);
-		arch_spin_unlock(&lock);
+		this_cpu_write(printk_func, printk_func_save);
+
 		cpumask_clear_cpu(cpu, to_cpumask(backtrace_mask));
 		return NMI_HANDLED;
 	}

From: "Steven Rostedt (Red Hat)" <[email protected]>

When trigger_all_cpu_backtrace() is called on x86, it will trigger an NMI on each CPU and call show_regs(). But this can lead to a hard lock up if the NMI comes in on another printk().

In order to avoid this, when the NMI triggers, it switches the printk routine for that CPU to call a NMI safe printk function that records the printk in a per_cpu seq_buf descriptor. After all NMIs have finished recording its data, the trace_seqs are printed in a safe context.

Link http://lkml.kernel.org/p/[email protected] open here

Acked-by Paul E. McKenney <[email protected]>

Signed-off-by Steven Rostedt <[email protected]>

---
V2 - updated to use seq_buf instead of trace_seq.
- Keep original printk loglevel, do not strip it, but use it. (suggested by Petr Mládek)
- Updated comments
- Removed return of true (noticed by Petr Mládek)

---
 arch/x86/kernel/apic/hw_nmi.c | 84 +++++++++++++++++++++++++++++++++++++++++--
 1 file changed, 81 insertions(+), 3 deletions(-)

arch/x86/kernel/apic/hw_nmi.c +57 -0

index c3fcb5de5083..91ddba672839 100644
@@ -18,6 +18,7 @@
 #include <linux/nmi.h>
 #include <linux/module.h>
 #include <linux/delay.h>
+#include <linux/seq_buf.h>
 
 #ifdef CONFIG_HARDLOCKUP_DETECTOR
 u64 hw_nmi_get_sample_period(int watchdog_thresh)

@@ -30,11 +31,31 @@ u64 hw_nmi_get_sample_period(int watchdog_thresh)
 /* For reliability, we're prepared to waste bits here. */
 static DECLARE_BITMAP(backtrace_mask, NR_CPUS) __read_mostly;
 
+#define NMI_BUF_SIZE		4096
+
+struct nmi_seq_buf {
+	unsigned char		buffer[NMI_BUF_SIZE];
+	struct seq_buf		seq;
+};
+
+/* Safe printing in NMI context */
+static DEFINE_PER_CPU(struct nmi_seq_buf, nmi_print_seq);
+
 /* "in progress" flag of arch_trigger_all_cpu_backtrace */
 static unsigned long backtrace_flag;
 
+static void print_seq_line(struct nmi_seq_buf *s, int last, int pos)
+{
+	const char *buf = s->buffer + last;
+
+	printk("%.*s", (pos - last) + 1, buf);
+}
+
 void arch_trigger_all_cpu_backtrace(void)
 {
+	struct nmi_seq_buf *s;
+	int len;
+	int cpu;
 	int i;
 
 	if (test_and_set_bit(0, &backtrace_flag))

@@ -44,6 +65,15 @@ void arch_trigger_all_cpu_backtrace(void)
 		 */
 		return;
 
+	/*
+	 * Set up per_cpu seq_buf buffers that the NMIs running on the other
+	 * CPUs will write to.
+	 */
+	for_each_possible_cpu(cpu) {
+		s = &per_cpu(nmi_print_seq, cpu);
+		seq_buf_init(&s->seq, s->buffer, NMI_BUF_SIZE);
+	}
+
 	cpumask_copy(to_cpumask(backtrace_mask), cpu_online_mask);
 
 	printk(KERN_INFO "sending NMI to all CPUs:\n");

@@ -56,10 +86,56 @@ void arch_trigger_all_cpu_backtrace(void)
 		mdelay(1);
 	}
 
+	/*
+	 * Now that all the NMIs have triggered, we can dump out their
+	 * back traces safely to the console.
+	 */
+	for_each_possible_cpu(cpu) {
+		int last_i = 0;
+
+		s = &per_cpu(nmi_print_seq, cpu);
+		len = s->seq.len;
+		if (!len)
+			continue;
+
+		/* Print line by line. */
+		for (i = 0; i < len; i++) {
+			if (s->buffer[i] == '\n') {
+				print_seq_line(s, last_i, i);
+				last_i = i + 1;
+			}
+		}
+		if (last_i < i - 1) {
+			print_seq_line(s, last_i, i);
+			pr_cont("\n");
+		}
+	}
+
 	clear_bit(0, &backtrace_flag);
 	smp_mb__after_atomic();
 }
 
+/*
+ * It is not safe to call printk() directly from NMI handlers.

arch/x86/kernel/apic/hw_nmi.c +14 -3

+static int nmi_vprintk(const char *fmt, va_list args)
+{
+	struct nmi_seq_buf *s = this_cpu_ptr(&nmi_print_seq);
+	unsigned int len = s->seq.len;
+
+	seq_buf_vprintf(&s->seq, fmt, args);
+	return s->seq.len - len;
+}
+
 static int
 arch_trigger_all_cpu_backtrace_handler(unsigned int cmd, struct pt_regs *regs)
 {

@@ -68,12 +144,14 @@ arch_trigger_all_cpu_backtrace_handler(unsigned int cmd, struct pt_regs *regs)
 	cpu = smp_processor_id();
 
 	if (cpumask_test_cpu(cpu, to_cpumask(backtrace_mask))) {
-		static arch_spinlock_t lock = __ARCH_SPIN_LOCK_UNLOCKED;
+		printk_func_t printk_func_save = this_cpu_read(printk_func);
 
-		arch_spin_lock(&lock);
+		/* Replace printk to write into the NMI seq */
+		this_cpu_write(printk_func, nmi_vprintk);
 		printk(KERN_WARNING "NMI backtrace for cpu %d\n", cpu);
 		show_regs(regs);
-		arch_spin_unlock(&lock);
+		this_cpu_write(printk_func, printk_func_save);
+
 		cpumask_clear_cpu(cpu, to_cpumask(backtrace_mask));
 		return NMI_HANDLED;
 	}

Signature · 1 line

2.0.0

Quoted 4 lines

+/*
+ * It is not safe to call printk() directly from NMI handlers.
+ * It may be fine if the NMI detected a lock up and we have no choice
+ * but to do so, but doing a NMI on all other CPUs to get a back trace

Quoted 8 lines

+ * can be done with a sysrq-l. We don't want that to lock up, which
+ * can happen if the NMI interrupts a printk in progress.
+ *
+ * Instead, we redirect the vprintk() to this nmi_vprintk() that writes
+ * the content into a per cpu seq_buf buffer. Then when the NMIs are
+ * all done, we can safely dump the contents of the seq_buf to a printk()
+ * from a non NMI context.
+ */

I would move this comment above #define NMI_BUF_SIZE
It should be on top because it helps to understand many other tricks that are used above.

This is version 2:

This is my proposal to print the NMI stack traces from an RCU stall safely. Here's the gist of it.

Quoted 4 lines · Steven Rostedt

This is version 2:

This is my proposal to print the NMI stack traces from an RCU stall safely. Here's the gist of it.

Steven, what's your plan with this patchset please?

It has been tested by Petr here on the systems under the loads that are able to trigger the hangs.

It'd be nice to have this in 3.17, so that we can then start working on fixing all the remaining printk() calls in NMI context once this biggest offender (stack dumping) is done.

Quoted 6 lines

Quoted 4 lines

This is version 2:

This is my proposal to print the NMI stack traces from an RCU stall safely. Here's the gist of it.

Steven, what's your plan with this patchset please?

Has there been consensus on this approach?