x86/nmi: Print all cpu stacks from NMI safely

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

The trace_seq functions are rather useful outside of tracing.

Quoted 3 lines · Steven Rostedt

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

The trace_seq functions are rather useful outside of tracing.

They are?

Why and where?

And why are they still called "trace_xyz()" then?

That commit message is useless and contains no actual information.

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

The trace_seq 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.

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

---
 include/linux/trace_seq.h   |  68 ++--------
 kernel/trace/trace.c        |  24 ----
 kernel/trace/trace_output.c | 268 ---------------------------------------
 kernel/trace/trace_output.h |  16 ---
 lib/Makefile                |   2 +-
 lib/trace_seq.c             | 303 ++++++++++++++++++++++++++++++++++++++++++++

#endif /* _LINUX_TRACE_SEQ_H */

...

lib/trace_seq.c new file +1 -0

@@ -0,0 +1,303 @@
+/*

lib/trace_seq.c new file +4 -0

+	 */
+	if (!ret)
+		trace_seq_init(s);
+

lib/trace_seq.c new file +8 -0

+ * Writes a ASCII representation of a bitmask string into @s.
+ */
+int
+trace_seq_bitmask(struct trace_seq *s, const unsigned long *maskp,
+		  int nmaskbits)
+{
+	int len = (PAGE_SIZE - 1) - s->len;
+	int ret;

lib/trace_seq.c new file +15 -0

+ * buffer (@s). Then the output may be either used by
+ * the sequencer or pulled into another buffer.
+ */
+int
+trace_seq_vprintf(struct trace_seq *s, const char *fmt, va_list args)
+{
+	int len = (PAGE_SIZE - 1) - s->len;
+	int ret;
+
+	if (s->full || !len)
+		return 0;
+
+	ret = vsnprintf(s->buffer + s->len, len, fmt, args);
+
+	/* If we can't write it all, don't bother writing anything */

lib/trace_seq.c new file +9 -0

+{
+	int len = (PAGE_SIZE - 1) - s->len;
+	int ret;
+
+	if (s->full || !len)
+		return 0;
+
+	ret = bstr_printf(s->buffer + s->len, len, fmt, binary);
+

lib/trace_seq.c new file +17 -0

+/**
+ * trace_seq_puts - trace sequence printing of simple string
+ * @s: trace sequence descriptor
+ * @str: simple string to record
+ *
+ * The tracer may use either the sequence operations or its own
+ * copy to user routines. This function records a simple string
+ * into a special buffer (@s) for later retrieval by a sequencer
+ * or other mechanism.
+ */
+int trace_seq_puts(struct trace_seq *s, const char *str)
+{
+	int len = strlen(str);
+
+	if (s->full)
+		return 0;
+

lib/trace_seq.c new file +5 -0

+int trace_seq_putc(struct trace_seq *s, unsigned char c)
+{
+	if (s->full)
+		return 0;
+

lib/trace_seq.c new file +6 -0

+int trace_seq_putmem(struct trace_seq *s, const void *mem, size_t len)
+{
+	if (s->full)
+		return 0;
+
+	if (len > ((PAGE_SIZE - 1) - s->len)) {

lib/trace_seq.c new file +6 -0

+{
+	void *ret;
+
+	if (s->full)
+		return NULL;
+

lib/trace_seq.c new file +17 -0

+int trace_seq_path(struct trace_seq *s, const struct path *path)
+{
+	unsigned char *p;
+
+	if (s->full)
+		return 0;
+
+	if (s->len >= (PAGE_SIZE - 1)) {
+		s->full = 1;
+		return 0;
+	}
+
+	p = d_path(path, s->buffer + s->len, PAGE_SIZE - s->len);
+	if (!IS_ERR(p)) {
+		p = mangle_path(s->buffer + s->len, p, "\n");
+		if (p) {
+			s->len = p - s->buffer;

lib/trace_seq.c new file +13 -0

+ssize_t trace_seq_to_user(struct trace_seq *s, char __user *ubuf, size_t cnt)
+{
+	int len;
+	int ret;
+
+	if (!cnt)
+		return 0;
+
+	if (s->len <= s->readpos)
+		return -EBUSY;
+
+	len = s->len - s->readpos;
+	if (cnt > len)

Quoted 6 lines · On Thu, 19 Jun 2014 17:33:30 -0400 Steven Rostedt <[email protected]> wrote:

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

The trace_seq 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.

What LT said. It's pileon time!

Quoted 8 lines

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

---
 include/linux/trace_seq.h   |  68 ++--------
 kernel/trace/trace.c        |  24 ----
 kernel/trace/trace_output.c | 268 ---------------------------------------
 kernel/trace/trace_output.h |  16 ---
 lib/Makefile                |   2 +-
 lib/trace_seq.c             | 303 ++++++++++++++++++++++++++++++++++++++++++++

Putting it in there makes me look at it ;)

include/linux/trace_seq.h extern int trace_seq_path(struct trace_seq *s, const struct path *path); · line 52

Quoted 9 lines

include/linux/trace_seq.h +3 -0

 
...
 
+#define SEQ_PUT_FIELD_RET(s, x)				\
+do {							\
+	if (!trace_seq_putmem(s, &(x), sizeof(x)))	\

hm, does sizeof(x++) increment x? I guess it does.

Quoted 7 lines

include/linux/trace_seq.h +2 -0

+		return TRACE_TYPE_PARTIAL_LINE;		\
+} while (0)
 
 
...

include/linux/trace_seq.h extern int trace_seq_path(struct trace_seq *s, const struct path *path); · line 61

Quoted 6 lines

include/linux/trace_seq.h +6 -0

+#define SEQ_PUT_HEX_FIELD_RET(s, x)			\
+do {							\
+	BUILD_BUG_ON(sizeof(x) > MAX_MEMHEX_BYTES);	\
+	if (!trace_seq_putmem_hex(s, &(x), sizeof(x)))	\
+		return TRACE_TYPE_PARTIAL_LINE;		\
+} while (0)

Also has side-effects.

Quoted 5 lines

#endif /* _LINUX_TRACE_SEQ_H */

...

Quoted 4 lines

lib/trace_seq.c new file +1 -0

@@ -0,0 +1,303 @@
+/*

lib/trace_seq.c line 11

Quoted 10 lines

lib/trace_seq.c new file +10 -0

+ * trace_seq.c
+ *
+ * Copyright (C) 2008-2014 Red Hat Inc, Steven Rostedt <[email protected]>
+ *
+ */
+#include <linux/uaccess.h>
+#include <linux/seq_file.h>
+#include <linux/trace_seq.h>
+
+int trace_print_seq(struct seq_file *m, struct trace_seq *s)

-ENODOC

lib/trace_seq.c line 13

Quoted 3 lines

lib/trace_seq.c new file +2 -0

+{
+	int len = s->len >= PAGE_SIZE ? PAGE_SIZE - 1 : s->len;

int = uint >= ulong ? ulog : uint

that's spastic. Can we choose a type and stick to it?

Also, min().

lib/trace_seq.c line 20

Quoted 8 lines

lib/trace_seq.c new file +7 -0

+	int ret;
+
+	ret = seq_write(m, s->buffer, len);
+
+	/*
+	 * Only reset this buffer if we successfully wrote to the
+	 * seq_file buffer.

why?

Quoted 5 lines

lib/trace_seq.c new file +4 -0

+	 */
+	if (!ret)
+		trace_seq_init(s);
+

lib/trace_seq.c line 34

Quoted 10 lines

lib/trace_seq.c new file +10 -0

+	return ret;
+}
+
+/**
+ * trace_seq_printf - sequence printing of trace information
+ * @s: trace sequence descriptor
+ * @fmt: printf format string
+ *
+ * It returns 0 if the trace oversizes the buffer's free
+ * space, 1 otherwise.

s/oversizes/would overrun/?

lib/trace_seq.c line 43

Quoted 9 lines

lib/trace_seq.c new file +8 -0

+ * The tracer may use either sequence operations or its own
+ * copy to user routines. To simplify formating of a trace
+ * trace_seq_printf is used to store strings into a special
+ * buffer (@s). Then the output may be either used by
+ * the sequencer or pulled into another buffer.
+ */
+int
+trace_seq_printf(struct trace_seq *s, const char *fmt, ...)

unneeded newline

lib/trace_seq.c line 44

Quoted 3 lines

lib/trace_seq.c new file +2 -0

+{
+	int len = (PAGE_SIZE - 1) - s->len;

	int = ulong - uint;

lib/trace_seq.c line 56

Quoted 12 lines

lib/trace_seq.c new file +11 -0

+	va_list ap;
+	int ret;
+
+	if (s->full || !len)
+		return 0;
+
+	va_start(ap, fmt);
+	ret = vsnprintf(s->buffer + s->len, len, fmt, ap);
+	va_end(ap);
+
+	/* If we can't write it all, don't bother writing anything */

This is somewhat unusual behavior for a write()-style thing. Comment should explain "why", not "what".

Quoted 4 lines

lib/trace_seq.c new file +3 -0

+	if (ret >= len) {
+		s->full = 1;
+		return 0;

lib/trace_seq.c line 69

Quoted 10 lines

lib/trace_seq.c new file +10 -0

+	}
+
+	s->len += ret;
+
+	return 1;
+}
+EXPORT_SYMBOL_GPL(trace_seq_printf);
+
+/**
+ * trace_seq_bitmask - put a list of longs as a bitmask print output

Is that grammatical?

lib/trace_seq.c line 75

Quoted 7 lines

lib/trace_seq.c new file +6 -0

+ * @s:		trace sequence descriptor
+ * @maskp:	points to an array of unsigned longs that represent a bitmask
+ * @nmaskbits:	The number of bits that are valid in @maskp
+ *
+ * It returns 0 if the trace oversizes the buffer's free
+ * space, 1 otherwise.

Ditto

Quoted 13 lines

lib/trace_seq.c new file +12 -0

+ * Writes a ASCII representation of a bitmask string into @s.
+ */
+int
+trace_seq_bitmask(struct trace_seq *s, const unsigned long *maskp,
+		  int nmaskbits)
+{
+	int len = (PAGE_SIZE - 1) - s->len;
+	int ret;
+
+	if (s->full || !len)
+		return 0;
+

lib/trace_seq.c line 94

Quoted 6 lines

lib/trace_seq.c new file +6 -0

+	ret = bitmap_scnprintf(s->buffer, len, maskp, nmaskbits);
+	s->len += ret;
+
+	return 1;
+}
+EXPORT_SYMBOL_GPL(trace_seq_bitmask);

More dittos.

lib/trace_seq.c line 103

Quoted 9 lines

lib/trace_seq.c new file +8 -0

+/**
+ * trace_seq_vprintf - sequence printing of trace information
+ * @s: trace sequence descriptor
+ * @fmt: printf format string
+ *
+ * The tracer may use either sequence operations or its own
+ * copy to user routines. To simplify formating of a trace
+ * trace_seq_printf is used to store strings into a special

"trace_seq_printf()". Apparently it makes the kerneldoc output come out right.

Quoted 20 lines

lib/trace_seq.c new file +19 -0

+ * buffer (@s). Then the output may be either used by
+ * the sequencer or pulled into another buffer.
+ */
+int
+trace_seq_vprintf(struct trace_seq *s, const char *fmt, va_list args)
+{
+	int len = (PAGE_SIZE - 1) - s->len;
+	int ret;
+
+	if (s->full || !len)
+		return 0;
+
+	ret = vsnprintf(s->buffer + s->len, len, fmt, args);
+
+	/* If we can't write it all, don't bother writing anything */
+	if (ret >= len) {
+		s->full = 1;
+		return 0;
+	}

lib/trace_seq.c line 128

Quoted 6 lines

lib/trace_seq.c new file +6 -0

+
+	s->len += ret;
+
+	return len;
+}
+EXPORT_SYMBOL_GPL(trace_seq_vprintf);

Several dittos.

lib/trace_seq.c line 130

Quoted 2 lines

lib/trace_seq.c new file +1 -0

+int trace_seq_bprintf(struct trace_seq *s, const char *fmt, const u32 *binary)

-ENODOC

Quoted 14 lines

lib/trace_seq.c new file +13 -0

+{
+	int len = (PAGE_SIZE - 1) - s->len;
+	int ret;
+
+	if (s->full || !len)
+		return 0;
+
+	ret = bstr_printf(s->buffer + s->len, len, fmt, binary);
+
+	/* If we can't write it all, don't bother writing anything */
+	if (ret >= len) {
+		s->full = 1;
+		return 0;

lib/trace_seq.c line 127

Quoted 6 lines

lib/trace_seq.c new file +6 -0

+	}
+
+	s->len += ret;
+
+	return len;
+}

Dittos.

Quoted 22 lines

lib/trace_seq.c new file +21 -0

+/**
+ * trace_seq_puts - trace sequence printing of simple string
+ * @s: trace sequence descriptor
+ * @str: simple string to record
+ *
+ * The tracer may use either the sequence operations or its own
+ * copy to user routines. This function records a simple string
+ * into a special buffer (@s) for later retrieval by a sequencer
+ * or other mechanism.
+ */
+int trace_seq_puts(struct trace_seq *s, const char *str)
+{
+	int len = strlen(str);
+
+	if (s->full)
+		return 0;
+
+	if (len > ((PAGE_SIZE - 1) - s->len)) {
+		s->full = 1;
+		return 0;
+	}

lib/trace_seq.c line 177

Quoted 6 lines

lib/trace_seq.c new file +6 -0

+
+	memcpy(s->buffer + s->len, str, len);
+	s->len += len;
+
+	return len;
+}

Missing EXPORT_SYMBOL?

Quoted 10 lines

lib/trace_seq.c new file +9 -0

+int trace_seq_putc(struct trace_seq *s, unsigned char c)
+{
+	if (s->full)
+		return 0;
+
+	if (s->len >= (PAGE_SIZE - 1)) {
+		s->full = 1;
+		return 0;
+	}

lib/trace_seq.c line 193

Quoted 6 lines

lib/trace_seq.c new file +6 -0

+
+	s->buffer[s->len++] = c;
+
+	return 1;
+}
+EXPORT_SYMBOL(trace_seq_putc);

Mix of EXPORT_SYMBOL() and EXPORT_SYMBOL_GPL()

Quoted 11 lines

lib/trace_seq.c new file +10 -0

+int trace_seq_putmem(struct trace_seq *s, const void *mem, size_t len)
+{
+	if (s->full)
+		return 0;
+
+	if (len > ((PAGE_SIZE - 1) - s->len)) {
+		s->full = 1;
+		return 0;
+	}
+

lib/trace_seq.c line 210

Quoted 6 lines

lib/trace_seq.c new file +6 -0

+	memcpy(s->buffer + s->len, mem, len);
+	s->len += len;
+
+	return len;
+}
+

Lotsa dittos

lib/trace_seq.c line 220

Quoted 11 lines

lib/trace_seq.c new file +10 -0

+#define HEX_CHARS		(MAX_MEMHEX_BYTES*2 + 1)
+
+int trace_seq_putmem_hex(struct trace_seq *s, const void *mem, size_t len)
+{
+	unsigned char hex[HEX_CHARS];
+	const unsigned char *data = mem;
+	int i, j;
+
+	if (s->full)
+		return 0;

What's this ->full thing all about anyway? Some central comment which explains the design is needed.

Is this test really needed? trace_seq_putmem() will handle this.

lib/trace_seq.c line 233

Quoted 13 lines

lib/trace_seq.c new file +12 -0

+#ifdef __BIG_ENDIAN
+	for (i = 0, j = 0; i < len; i++) {
+#else
+	for (i = len-1, j = 0; i >= 0; i--) {
+#endif
+		hex[j++] = hex_asc_hi(data[i]);
+		hex[j++] = hex_asc_lo(data[i]);
+	}
+	hex[j++] = ' ';
+
+	return trace_seq_putmem(s, hex, j);
+}

-ENODOC, missing EXPORT_SYMBOL.

lib/trace_seq.c line 235

Quoted 2 lines

lib/trace_seq.c new file +1 -0

+void *trace_seq_reserve(struct trace_seq *s, size_t len)

`len' is a size_t here, a uint in trace_seq and an int when it's a local.

Quoted 11 lines

lib/trace_seq.c new file +10 -0

+{
+	void *ret;
+
+	if (s->full)
+		return NULL;
+
+	if (len > ((PAGE_SIZE - 1) - s->len)) {
+		s->full = 1;
+		return NULL;
+	}

lib/trace_seq.c line 251

Quoted 6 lines

lib/trace_seq.c new file +6 -0

+
+	ret = s->buffer + s->len;
+	s->len += len;
+
+	return ret;
+}

Dittos

Quoted 22 lines

lib/trace_seq.c new file +21 -0

+int trace_seq_path(struct trace_seq *s, const struct path *path)
+{
+	unsigned char *p;
+
+	if (s->full)
+		return 0;
+
+	if (s->len >= (PAGE_SIZE - 1)) {
+		s->full = 1;
+		return 0;
+	}
+
+	p = d_path(path, s->buffer + s->len, PAGE_SIZE - s->len);
+	if (!IS_ERR(p)) {
+		p = mangle_path(s->buffer + s->len, p, "\n");
+		if (p) {
+			s->len = p - s->buffer;
+			return 1;
+		}
+	} else {
+		s->buffer[s->len++] = '?';

lib/trace_seq.c line 122

Quoted 6 lines

lib/trace_seq.c new file +6 -0

+		return 1;
+	}
+
+	s->full = 1;
+	return 0;
+}

Dittos

Quoted 18 lines

lib/trace_seq.c new file +17 -0

+ssize_t trace_seq_to_user(struct trace_seq *s, char __user *ubuf, size_t cnt)
+{
+	int len;
+	int ret;
+
+	if (!cnt)
+		return 0;
+
+	if (s->len <= s->readpos)
+		return -EBUSY;
+
+	len = s->len - s->readpos;
+	if (cnt > len)
+		cnt = len;
+	ret = copy_to_user(ubuf, s->buffer + s->readpos, cnt);
+	if (ret == cnt)
+		return -EFAULT;

lib/trace_seq.c line 303

Quoted 6 lines

lib/trace_seq.c new file +6 -0

+
+	cnt -= ret;
+
+	s->readpos += cnt;
+	return cnt;
+}

Dittos

...

Quoted 13 lines

Quoted 13 lines

+ * Writes a ASCII representation of a bitmask string into @s.
+ */

lib/trace_seq.c new file +10 -0

+int
+trace_seq_bitmask(struct trace_seq *s, const unsigned long *maskp,
+		  int nmaskbits)
+{
+	int len = (PAGE_SIZE - 1) - s->len;
+	int ret;
+
+	if (s->full || !len)
+		return 0;
+

Quoted 8 lines

lib/trace_seq.c line 94

Quoted 6 lines

lib/trace_seq.c new file +6 -0

+	ret = bitmap_scnprintf(s->buffer, len, maskp, nmaskbits);
+	s->len += ret;
+
+	return 1;
+}
+EXPORT_SYMBOL_GPL(trace_seq_bitmask);

More dittos.

Confused. What dittos is this dittoing?

...

Quoted 19 lines

Quoted 19 lines

+ * buffer (@s). Then the output may be either used by
+ * the sequencer or pulled into another buffer.
+ */

lib/trace_seq.c new file +16 -0

+int
+trace_seq_vprintf(struct trace_seq *s, const char *fmt, va_list args)
+{
+	int len = (PAGE_SIZE - 1) - s->len;
+	int ret;
+
+	if (s->full || !len)
+		return 0;
+
+	ret = vsnprintf(s->buffer + s->len, len, fmt, args);
+
+	/* If we can't write it all, don't bother writing anything */
+	if (ret >= len) {
+		s->full = 1;
+		return 0;
+	}

Quoted 8 lines

lib/trace_seq.c line 128

Quoted 6 lines

lib/trace_seq.c new file +6 -0

+
+	s->len += ret;
+
+	return len;
+}
+EXPORT_SYMBOL_GPL(trace_seq_vprintf);

Several dittos.

Oh, just on the function. You're not dittoing a comment about the EXPORT_SYMBOL_GPL() that you forgot to add, are you?

...

Quoted 14 lines

lib/trace_seq.c line 220

Quoted 11 lines

lib/trace_seq.c new file +10 -0

+#define HEX_CHARS		(MAX_MEMHEX_BYTES*2 + 1)
+
+int trace_seq_putmem_hex(struct trace_seq *s, const void *mem, size_t len)
+{
+	unsigned char hex[HEX_CHARS];
+	const unsigned char *data = mem;
+	int i, j;
+
+	if (s->full)
+		return 0;

What's this ->full thing all about anyway? Some central comment which explains the design is needed.

Comment? What? Git blame isn't good enough for ya? ;-)

...

Hey! Thanks for the review. Much appreciated. And maybe you should read those messages in your /dev/null folder that I cc you with. :-)

Quoted 1 line

Comment? What? Git blame isn't good enough for ya? ;-)

There's always that. There's also googling for the original list dicsussion. But it's a bit user-unfriendly, particularly when then code has aged was subsequently altered many times.

Quoted 7 lines

...

Hey! Thanks for the review. Much appreciated. And maybe you should read those messages in your /dev/null folder that I cc you with. :-)

I sometimes do.

Quoted 14 lines

Quoted 13 lines

lib/trace_seq.c line 220

Quoted 10 lines

lib/trace_seq.c new file +10 -0

+#define HEX_CHARS		(MAX_MEMHEX_BYTES*2 + 1)
+
+int trace_seq_putmem_hex(struct trace_seq *s, const void *mem, size_t len)
+{
+	unsigned char hex[HEX_CHARS];
+	const unsigned char *data = mem;
+	int i, j;
+
+	if (s->full)
+		return 0;

What's this ->full thing all about anyway? Some central comment which explains the design is needed.

Quoted 1 line

Comment? What? Git blame isn't good enough for ya? ;-)

There's always that. There's also googling for the original list dicsussion. But it's a bit user-unfriendly, particularly when then code has aged was subsequently altered many times.

Quoted 14 lines · On Fri, 20 Jun 2014 10:12:44 -0700 Andrew Morton <[email protected]>…

Quoted 14 lines

Quoted 13 lines

lib/trace_seq.c line 220

Quoted 10 lines

lib/trace_seq.c new file +10 -0

+#define HEX_CHARS		(MAX_MEMHEX_BYTES*2 + 1)
+
+int trace_seq_putmem_hex(struct trace_seq *s, const void *mem, size_t len)
+{
+	unsigned char hex[HEX_CHARS];
+	const unsigned char *data = mem;
+	int i, j;
+
+	if (s->full)
+		return 0;

What's this ->full thing all about anyway? Some central comment which explains the design is needed.

Quoted 5 lines

Quoted 1 line

Comment? What? Git blame isn't good enough for ya? ;-)

There's always that. There's also googling for the original list dicsussion. But it's a bit user-unfriendly, particularly when then code has aged was subsequently altered many times.

Although I did not address this because I'm waiting to hear back from Johannes Berg, I updated for your other comments. I hope I got them all.

Regardless of this patch series, I pulled out the code from trace_output.c and made a separate file for the trace_seq_*() functions in kernel/trace/trace_seq.c. I then updated the file with your comments. I found a bug or two and I will be dealing with them later as this will only be a clean up patch not a bug fix patch.

Anyway, here's the new file:

Quoted 27 lines · On Fri, 20 Jun 2014 16:28:45 -0400 Steven Rostedt <[email protected]> wrote:

Quoted 14 lines · On Fri, 20 Jun 2014 10:12:44 -0700 Andrew Morton <[email protected]>…

Quoted 14 lines

Quoted 13 lines

lib/trace_seq.c line 220

Quoted 10 lines

lib/trace_seq.c new file +10 -0

+#define HEX_CHARS		(MAX_MEMHEX_BYTES*2 + 1)
+
+int trace_seq_putmem_hex(struct trace_seq *s, const void *mem, size_t len)
+{
+	unsigned char hex[HEX_CHARS];
+	const unsigned char *data = mem;
+	int i, j;
+
+	if (s->full)
+		return 0;

What's this ->full thing all about anyway? Some central comment which explains the design is needed.

Quoted 5 lines

Quoted 1 line

Comment? What? Git blame isn't good enough for ya? ;-)

There's always that. There's also googling for the original list dicsussion. But it's a bit user-unfriendly, particularly when then code has aged was subsequently altered many times.

Although I did not address this because I'm waiting to hear back from Johannes Berg, I updated for your other comments. I hope I got them all.

Quoted 7 lines

Regardless of this patch series, I pulled out the code from trace_output.c and made a separate file for the trace_seq_*() functions in kernel/trace/trace_seq.c. I then updated the file with your comments. I found a bug or two and I will be dealing with them later as this will only be a clean up patch not a bug fix patch.

Anyway, here's the new file:

Would be helpful if I compiled it before posting it :-)

Also, I missed a few EXPORT_SYMBOL_GPL()s along the way.

New update:

-- Steve

/*
* trace_seq.c
*
* Copyright (C) 2008-2014 Red Hat Inc, Steven Rostedt <[email protected]> *
* The trace_seq 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 trace_seq must be initialized with trace_seq_init().
* This will set up the counters within the descriptor. You can call
* trace_seq_init() more than once to reset the trace_seq to start
* from scratch.
*

* The buffer size is currently PAGE_SIZE, although it may become dynamic
* in the future.
*
* A write to the buffer will either succed or fail. That is, unlike
* sprintf() there will not be a partial write (well it may write into
* the buffer but it wont update the pointers). This allows users to
* try to write something into the trace_seq buffer and if it fails
* they can flush it and try again.

*/
#include <linux/uaccess.h>
#include <linux/seq_file.h>
#include <linux/trace_seq.h>

/* How much buffer is left on the trace_seq? */ #define TRACE_SEQ_BUF_LEFT(s) ((PAGE_SIZE - 1) - (s)->len)

/* How much buffer is written? */
#define TRACE_SEQ_BUF_USED(s) min((s)->len, (unsigned int)(PAGE_SIZE - 1))

/**
* trace_seq_printf - sequence printing of trace information
* @s: trace sequence descriptor
* @fmt: printf format string
*
* The tracer may use either sequence operations or its own
* copy to user routines. To simplify formating of a trace
* trace_seq_printf() is used to store strings into a special
* buffer (@s). Then the output may be either used by
* the sequencer or pulled into another buffer.
*
* Returns 1 if we successfully written all the contents to
* the buffer.
* Returns 0 if we the length to write is bigger than the
* reserved buffer space. In this case, nothing gets written.
*/
int trace_seq_printf(struct trace_seq *s, const char *fmt, ...)

{
	unsigned int len = TRACE_SEQ_BUF_LEFT(s);
	va_list ap;
	int ret;

	if (s->full || !len)
		return 0;

	va_start(ap, fmt);
	ret = vsnprintf(s->buffer + s->len, len, fmt, ap);
	va_end(ap);

	/* If we can't write it all, don't bother writing anything */
	if (ret >= len) {
		s->full = 1;
		return 0;
	}

	s->len += ret;

	return 1;
}

EXPORT_SYMBOL_GPL(trace_seq_printf);

/**
* trace_seq_bitmask - write a bitmask array in its ASCII representation
* @s: trace sequence descriptor
* @maskp: points to an array of unsigned longs that represent a bitmask
* @nmaskbits: The number of bits that are valid in @maskp
*
* Writes a ASCII representation of a bitmask string into @s. *
* Returns 1 if we successfully written all the contents to
* the buffer.
* Returns 0 if we the length to write is bigger than the
* reserved buffer space. In this case, nothing gets written.
*/
int trace_seq_bitmask(struct trace_seq *s, const unsigned long *maskp,
int nmaskbits)

{
	unsigned int len = TRACE_SEQ_BUF_LEFT(s);
	int ret;

	if (s->full || !len)
		return 0;

	ret = bitmap_scnprintf(s->buffer, len, maskp, nmaskbits);

	s->len += ret;

	return 1;
}

EXPORT_SYMBOL_GPL(trace_seq_bitmask);

/**
* trace_seq_putmem_hex - write raw memory into the buffer in ASCII hex
* @s: trace sequence 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 trace_seq_putmem() except instead of just copying the
* raw memory into the buffer it writes its ASCII representation of it
* in hex characters.
*
* Returns 1 if we successfully written all the contents to
* the buffer.
* Returns 0 if we the length to write is bigger than the
* reserved buffer space. In this case, nothing gets written.
*/
int trace_seq_putmem_hex(struct trace_seq *s, const void *mem,
unsigned int len)

{
	unsigned char hex[HEX_CHARS];
	const unsigned char *data = mem;
	int i, j;

	if (s->full)
		return 0;

#ifdef __BIG_ENDIAN
	for (i = 0, j = 0; i < len; i++) {
#else
	for (i = len-1, j = 0; i >= 0; i--) {

#endif

		hex[j++] = hex_asc_hi(data[i]);
		hex[j++] = hex_asc_lo(data[i]);
	}
	hex[j++] = ' ';

	return trace_seq_putmem(s, hex, j);
}

EXPORT_SYMBOL_GPL(trace_seq_putmem_hex);

/**
* trace_seq_reserve - reserve space on the sequence buffer
* @s: trace sequence descriptor
* @len: The amount to reserver.
*
* If for some reason there is a need to save some space on the
* buffer to fill in later, this function is used for that purpose.
* The given length will be reserved and the pointer to that
* location on the buffer is returned, unless there is not enough
* buffer left to hold the given length then NULL is returned. */
void *trace_seq_reserve(struct trace_seq *s, unsigned int len)

{
	void *ret;

	if (s->full)
		return NULL;

	if (len > TRACE_SEQ_BUF_LEFT(s)) {
		s->full = 1;
		return NULL;
	}

	ret = s->buffer + s->len;
	s->len += len;

	return ret;
}

EXPORT_SYMBOL_GPL(trace_seq_reserve);

Quoted 5 lines

* A write to the buffer will either succed or fail. That is, unlike
* sprintf() there will not be a partial write (well it may write into
* the buffer but it wont update the pointers). This allows users to
* try to write something into the trace_seq buffer and if it fails
* they can flush it and try again.

We might want to write as much as possible to the buffer if it is used for the backtrace.

Well, if I understand it correctly, this is only about the last line. If the trace does not fit, we are in troubles anyway. We might solve this later when needed.

Quoted 10 lines

*/
#include <linux/uaccess.h>
#include <linux/seq_file.h>
#include <linux/trace_seq.h>

/* How much buffer is left on the trace_seq? */ #define TRACE_SEQ_BUF_LEFT(s) ((PAGE_SIZE - 1) - (s)->len)

/* How much buffer is written? */
#define TRACE_SEQ_BUF_USED(s) min((s)->len, (unsigned int)(PAGE_SIZE - 1))

[...]

Quoted 60 lines

/**
* trace_seq_printf - sequence printing of trace information
* @s: trace sequence descriptor
* @fmt: printf format string
*
* The tracer may use either sequence operations or its own
* copy to user routines. To simplify formating of a trace
* trace_seq_printf() is used to store strings into a special
* buffer (@s). Then the output may be either used by
* the sequencer or pulled into another buffer.
*
* Returns 1 if we successfully written all the contents to
* the buffer.
* Returns 0 if we the length to write is bigger than the
* reserved buffer space. In this case, nothing gets written.
*/
int trace_seq_printf(struct trace_seq *s, const char *fmt, ...)

{
	unsigned int len = TRACE_SEQ_BUF_LEFT(s);
	va_list ap;
	int ret;

	if (s->full || !len)
		return 0;

	va_start(ap, fmt);
	ret = vsnprintf(s->buffer + s->len, len, fmt, ap);
	va_end(ap);

	/* If we can't write it all, don't bother writing anything */
	if (ret >= len) {
		s->full = 1;
		return 0;
	}

	s->len += ret;

	return 1;
}

EXPORT_SYMBOL_GPL(trace_seq_printf);

/**
* trace_seq_bitmask - write a bitmask array in its ASCII representation
* @s: trace sequence descriptor
* @maskp: points to an array of unsigned longs that represent a bitmask
* @nmaskbits: The number of bits that are valid in @maskp
*
* Writes a ASCII representation of a bitmask string into @s. *
* Returns 1 if we successfully written all the contents to
* the buffer.
* Returns 0 if we the length to write is bigger than the
* reserved buffer space. In this case, nothing gets written.
*/
int trace_seq_bitmask(struct trace_seq *s, const unsigned long *maskp,
int nmaskbits)

{
	unsigned int len = TRACE_SEQ_BUF_LEFT(s);
	int ret;

Quoted 4 lines

	if (s->full || !len)
		return 0;

	ret = bitmap_scnprintf(s->buffer, len, maskp, nmaskbits);

We do not detect here if the whole bitmap is written. Hmm, the perfect solution is not easy. What about using the following workaround?

If we wrote until the end of the buffer, the write was most likely incomplete:

	if (ret == len) {
		s->full = 1;
		return 0;
	}

It is more consistent with what we do in the other functions.

Quoted 4 lines

	s->len += ret;

	return 1;
}

Quoted 2 lines

EXPORT_SYMBOL_GPL(trace_seq_bitmask);

[...]

Quoted 25 lines

/**
* trace_seq_putmem_hex - write raw memory into the buffer in ASCII hex
* @s: trace sequence 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 trace_seq_putmem() except instead of just copying the
* raw memory into the buffer it writes its ASCII representation of it
* in hex characters.
*
* Returns 1 if we successfully written all the contents to
* the buffer.
* Returns 0 if we the length to write is bigger than the
* reserved buffer space. In this case, nothing gets written.
*/
int trace_seq_putmem_hex(struct trace_seq *s, const void *mem,
unsigned int len)

{
	unsigned char hex[HEX_CHARS];
	const unsigned char *data = mem;
	int i, j;

	if (s->full)
		return 0;

Quoted 5 lines

#ifdef __BIG_ENDIAN
	for (i = 0, j = 0; i < len; i++) {
#else
	for (i = len-1, j = 0; i >= 0; i--) {

#endif

This might overflow when "len" > (HEX_CHARS-1)/2.

I think that we should either limit "len" or make it in two cycles.

Hmm, if we use two cycles, it might be problem how to solve the endianity. IMHO, it depends on what type of data is written into the buffer (single vs. set of values).

Quoted 35 lines

		hex[j++] = hex_asc_hi(data[i]);
		hex[j++] = hex_asc_lo(data[i]);
	}
	hex[j++] = ' ';

	return trace_seq_putmem(s, hex, j);
}

EXPORT_SYMBOL_GPL(trace_seq_putmem_hex);

/**
* trace_seq_reserve - reserve space on the sequence buffer
* @s: trace sequence descriptor
* @len: The amount to reserver.
*
* If for some reason there is a need to save some space on the
* buffer to fill in later, this function is used for that purpose.
* The given length will be reserved and the pointer to that
* location on the buffer is returned, unless there is not enough
* buffer left to hold the given length then NULL is returned. */
void *trace_seq_reserve(struct trace_seq *s, unsigned int len)

{
	void *ret;

	if (s->full)
		return NULL;

	if (len > TRACE_SEQ_BUF_LEFT(s)) {
		s->full = 1;
		return NULL;
	}

	ret = s->buffer + s->len;
	s->len += len;

Quoted 3 lines

	return ret;
}

EXPORT_SYMBOL_GPL(trace_seq_reserve);

This sounds like a slightly dangerous operation. The reserve is valid only until the buffer is re-initialized. Is this really intended?

Do we really want to export it?

Well, the whole buffer need to be used carefully. IMHO, it can't be accessed in parallel without extra locks. So, this might be fine after all. We could only warn about this in the function description.

[...]

The rest looks fine to me.

Also the proposed name "seq_buf" sounds fine to me.

Best Regards,
Petr

Quoted 5 lines

Quoted 5 lines

lib/trace_seq.c new file +5 -0

+#define HEX_CHARS		(MAX_MEMHEX_BYTES*2 + 1)
+
+int trace_seq_putmem_hex(struct trace_seq *s, const void *mem, size_t len)
+{
+	unsigned char hex[HEX_CHARS];

Quoted 8 lines

lib/trace_seq.c line 220

Quoted 5 lines

lib/trace_seq.c new file +5 -0

+	const unsigned char *data = mem;
+	int i, j;
+
+	if (s->full)
+		return 0;

What's this ->full thing all about anyway? Some central comment which explains the design is needed.

Comment? What? Git blame isn't good enough for ya? ;-)

Quoted 2 lines

Is this test really needed? trace_seq_putmem() will handle this.

It was added as an optimization, because once it filled up, you could still have multiple calls to the trace_seq() functions that would waste time trying to write the buffer.

It seemed like a good idea at the time. I Cc'd Johannes Berg as he's the one that implemented.

Johannes, is this really needed, should we bother keeping it?

Looking at the code though, I'm not sure it's a pure optimisation - if you do say putc() after a failed puts(), without this code the putc() would succeed? I can't tell right now if that's really a problem, but it seems you could get some odd behaviour out of it.

Quoted 4 lines · On Sun, 22 Jun 2014 09:38:05 +0200 Johannes Berg <[email protected]>…

Looking at the code though, I'm not sure it's a pure optimisation - if you do say putc() after a failed puts(), without this code the putc() would succeed? I can't tell right now if that's really a problem, but it seems you could get some odd behaviour out of it.

How would putc() still succeed? We're just talking about the "full" field. It would still do the length check:

	if (s->len >= (PAGE_SIZE - 1))
		return 0;

Quoted 9 lines · Steven Rostedt

Quoted 4 lines · On Sun, 22 Jun 2014 09:38:05 +0200 Johannes Berg <[email protected]>…

Looking at the code though, I'm not sure it's a pure optimisation - if you do say putc() after a failed puts(), without this code the putc() would succeed? I can't tell right now if that's really a problem, but it seems you could get some odd behaviour out of it.

Quoted 5 lines

How would putc() still succeed? We're just talking about the "full" field. It would still do the length check:

	if (s->len >= (PAGE_SIZE - 1))
		return 0;

Right, but the puts() could fail if not all of the string fits, and a subsequent putc() might fit.

Ah! I see what you are saying. You are saying that once you are full you need to flush. Honestly, the trace_puts() should check the return. Perhaps it wants to try again with a shorter string?

The full flag means that once we hit full, we are done, no more can be written till the buffer is flushed.

Is that what we would want from this utility? Or do we want to allow the user to try again with a smaller string?

I was thinking of reversing the error code and have the trace_seq_*() return 0 as success and the remaining buffer size on error.

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().

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 +29 -9

index ea2d5f6962ed..d019ccd10d4c 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
-	if (unlikely(kdb_trap_printk)) {
-		va_start(args, fmt);
-		r = vkdb_printf(fmt, args);
-		va_end(args);
-		return r;
-	}
-#endif
 	va_start(args, fmt);
-	r = vprintk_emit(0, -1, NULL, 0, fmt, args);
+	preempt_disable();
+	vprintk_func = this_cpu_read(printk_func);
+	r = vprintk_func(fmt, args);
+	preempt_enable();
 	va_end(args);
 
 	return r;

Signature · 8 lines

2.0.0.rc2


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

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 trace_seq descriptor. After all NMIs have finished recording its data, the trace_seqs are printed in a safe context.

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

---
 arch/x86/kernel/apic/hw_nmi.c | 66 ++++++++++++++++++++++++++++++++++++++++---
 1 file changed, 62 insertions(+), 4 deletions(-)

arch/x86/kernel/apic/hw_nmi.c +62 -4

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

@@ -30,11 +31,30 @@ 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;
 
+/* Safe printing in NMI context */
+static DEFINE_PER_CPU(struct trace_seq, nmi_print_seq);
+
 /* "in progress" flag of arch_trigger_all_cpu_backtrace */
 static unsigned long backtrace_flag;
 
+static void print_seq_line(struct trace_seq *s, int last, int pos)
+{
+	const char *buf = s->buffer + last;
+
+	/* Chop off the saved log level and update the length */
+	if (printk_get_level(buf)) {
+		buf += 2;
+		last += 2;
+	}
+
+	pr_emerg("%.*s", (pos - last) + 1, buf);
+}
+
 void arch_trigger_all_cpu_backtrace(void)
 {
+	struct trace_seq *s;
+	int len;
+	int cpu;
 	int i;
 
 	if (test_and_set_bit(0, &backtrace_flag))

@@ -44,6 +64,11 @@ void arch_trigger_all_cpu_backtrace(void)
 		 */
 		return;
 
+	for_each_possible_cpu(i) {
+		s = &per_cpu(nmi_print_seq, i);
+		trace_seq_init(s);
+	}
+
 	cpumask_copy(to_cpumask(backtrace_mask), cpu_online_mask);
 
 	printk(KERN_INFO "sending NMI to all CPUs:\n");

@@ -56,8 +81,39 @@ void arch_trigger_all_cpu_backtrace(void)
 		mdelay(1);
 	}
 
+	for_each_possible_cpu(cpu) {
+		int last_i = 0;
+
+		s = &per_cpu(nmi_print_seq, cpu);
+		len = s->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();
+	return true;
+}
+
+static int nmi_vprintk(const char *fmt, va_list args)
+{
+	struct trace_seq *s = this_cpu_ptr(&nmi_print_seq);
+	int len = s->len;
+
+	trace_seq_vprintf(s, fmt, args);
+	return s->len - len;
 }
 
 static int

@@ -68,12 +124,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);
-		printk(KERN_WARNING "NMI backtrace for cpu %d\n", cpu);
+		/* Replace printk to write into the NMI seq */
+		this_cpu_write(printk_func, nmi_vprintk);
+		printk("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 · 8 lines

2.0.0.rc2


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Quoted 10 lines · Steven Rostedt

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 trace_seq descriptor. After all NMIs have finished recording its data, the trace_seqs are printed in a safe context.

Ah, if there is other places that need to call a printk from an NMI context, do we have to copy and paste this code there too? That would seem a little much. :-) I guess my only concern really is the seq_init and seq print stuff. The handler seems relatively simple.

Can we isolate this to a pr_nmi() routine or something? Or maybe a pr_nmi_queue and pr_nmi_dump or something?

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 trace_seq descriptor. After all NMIs have finished recording its data, the trace_seqs are printed in a safe context.

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

---
 arch/x86/kernel/apic/hw_nmi.c | 66 ++++++++++++++++++++++++++++++++++++++++---
 1 file changed, 62 insertions(+), 4 deletions(-)

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

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

@@ -30,11 +31,30 @@ 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;
 
+/* Safe printing in NMI context */
+static DEFINE_PER_CPU(struct trace_seq, nmi_print_seq);
+
 /* "in progress" flag of arch_trigger_all_cpu_backtrace */
 static unsigned long backtrace_flag;
 
+static void print_seq_line(struct trace_seq *s, int last, int pos)

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

+}
+
 void arch_trigger_all_cpu_backtrace(void)
 {
+	struct trace_seq *s;
+	int len;
+	int cpu;
 	int i;
 
 	if (test_and_set_bit(0, &backtrace_flag))

@@ -44,6 +64,11 @@ void arch_trigger_all_cpu_backtrace(void)
 		 */
 		return;
 
+	for_each_possible_cpu(i) {
+		s = &per_cpu(nmi_print_seq, i);
+		trace_seq_init(s);
+	}
+
 	cpumask_copy(to_cpumask(backtrace_mask), cpu_online_mask);
 
 	printk(KERN_INFO "sending NMI to all CPUs:\n");

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

+	for_each_possible_cpu(cpu) {
+		int last_i = 0;
+
+		s = &per_cpu(nmi_print_seq, cpu);
+		len = s->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;
+			}

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

+}
+
+static int nmi_vprintk(const char *fmt, va_list args)
+{
+	struct trace_seq *s = this_cpu_ptr(&nmi_print_seq);
+	int len = s->len;
+
+	trace_seq_vprintf(s, fmt, args);
+	return s->len - len;
 }
 
 static int

@@ -68,12 +124,14 @@ arch_trigger_all_cpu_backtrace_handler(unsigned int cmd, struct pt_regs *regs)
 	cpu = smp_processor_id();

arch/x86/kernel/apic/hw_nmi.c +2 -1

 		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.rc2

Quoted 48 lines · Steven Rostedt

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 trace_seq descriptor. After all NMIs have finished recording its data, the trace_seqs are printed in a safe context.

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

---
 arch/x86/kernel/apic/hw_nmi.c | 66 ++++++++++++++++++++++++++++++++++++++++---
 1 file changed, 62 insertions(+), 4 deletions(-)

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

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

@@ -30,11 +31,30 @@ 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;
 
+/* Safe printing in NMI context */
+static DEFINE_PER_CPU(struct trace_seq, nmi_print_seq);
+
 /* "in progress" flag of arch_trigger_all_cpu_backtrace */
 static unsigned long backtrace_flag;
 
+static void print_seq_line(struct trace_seq *s, int last, int pos)
+{
+	const char *buf = s->buffer + last;
+
+	/* Chop off the saved log level and update the length */
+	if (printk_get_level(buf)) {
+		buf += 2;
+		last += 2;
+	}
 

arch/x86/kernel/apic/hw_nmi.c u64 hw_nmi_get_sample_period(int watchdog_thresh) · line 50

Quoted 1 line

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

+	pr_emerg("%.*s", (pos - last) + 1, buf);

I wonder why you chop off the log level and force the emergency one. I think that this should be better set by the caller. For example, drivers/tty/sysrq.c when it wants to push the output on console.

Quoted 24 lines

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

+}
+
 void arch_trigger_all_cpu_backtrace(void)
 {
+	struct trace_seq *s;
+	int len;
+	int cpu;
 	int i;
 
 	if (test_and_set_bit(0, &backtrace_flag))

@@ -44,6 +64,11 @@ void arch_trigger_all_cpu_backtrace(void)
 		 */
 		return;
 
+	for_each_possible_cpu(i) {
+		s = &per_cpu(nmi_print_seq, i);
+		trace_seq_init(s);
+	}
+
 	cpumask_copy(to_cpumask(backtrace_mask), cpu_online_mask);
 
 	printk(KERN_INFO "sending NMI to all CPUs:\n");

arch/x86/kernel/apic/hw_nmi.c void arch_trigger_all_cpu_backtrace(void) · line 82

Quoted 2 lines

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

@@ -56,8 +81,39 @@ void arch_trigger_all_cpu_backtrace(void)
 		mdelay(1);
 	}

I would add a comment here. e.g.

/*
* Finally, copy the backtraces to the main ring buffer in a safe
* context, outside NMI.

	 */

Quoted 18 lines

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

+	for_each_possible_cpu(cpu) {
+		int last_i = 0;
+
+		s = &per_cpu(nmi_print_seq, cpu);
+		len = s->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");

arch/x86/kernel/apic/hw_nmi.c void arch_trigger_all_cpu_backtrace(void) · line 107

Quoted 6 lines

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

+		}
+	}
+
 	clear_bit(0, &backtrace_flag);
 	smp_mb__after_atomic();
+	return true;

This function returns void ;-)

Quoted 20 lines

arch/x86/kernel/apic/hw_nmi.c +10 -1

+}
+
+static int nmi_vprintk(const char *fmt, va_list args)
+{
+	struct trace_seq *s = this_cpu_ptr(&nmi_print_seq);
+	int len = s->len;
+
+	trace_seq_vprintf(s, fmt, args);
+	return s->len - len;
 }
 
 static int

@@ -68,12 +124,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/x86/kernel/apic/hw_nmi.c arch_trigger_all_cpu_backtrace_handler(unsigned int cmd, struct pt_regs *regs) · line 131

Quoted 5 lines

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

-		arch_spin_lock(&lock);
-		printk(KERN_WARNING "NMI backtrace for cpu %d\n", cpu);
+		/* Replace printk to write into the NMI seq */
+		this_cpu_write(printk_func, nmi_vprintk);
+		printk("NMI backtrace for cpu %d\n", cpu);

I would leave the log level as is.

Quoted 10 lines

arch/x86/kernel/apic/hw_nmi.c +2 -1

 		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.rc2

Otherwise, I basically like the approach.

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 trace_seq descriptor. After all NMIs have finished recording its data, the trace_seqs are printed in a safe context.

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

---
 arch/x86/kernel/apic/hw_nmi.c | 66 ++++++++++++++++++++++++++++++++++++++++---
 1 file changed, 62 insertions(+), 4 deletions(-)

arch/x86/kernel/apic/hw_nmi.c +62 -4

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

@@ -30,11 +31,30 @@ 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;
 
+/* Safe printing in NMI context */
+static DEFINE_PER_CPU(struct trace_seq, nmi_print_seq);
+
 /* "in progress" flag of arch_trigger_all_cpu_backtrace */
 static unsigned long backtrace_flag;
 
+static void print_seq_line(struct trace_seq *s, int last, int pos)
+{
+	const char *buf = s->buffer + last;
+
+	/* Chop off the saved log level and update the length */
+	if (printk_get_level(buf)) {
+		buf += 2;
+		last += 2;
+	}
+
+	pr_emerg("%.*s", (pos - last) + 1, buf);
+}
+
 void arch_trigger_all_cpu_backtrace(void)
 {
+	struct trace_seq *s;
+	int len;
+	int cpu;
 	int i;
 
 	if (test_and_set_bit(0, &backtrace_flag))

@@ -44,6 +64,11 @@ void arch_trigger_all_cpu_backtrace(void)
 		 */
 		return;
 
+	for_each_possible_cpu(i) {
+		s = &per_cpu(nmi_print_seq, i);
+		trace_seq_init(s);
+	}
+
 	cpumask_copy(to_cpumask(backtrace_mask), cpu_online_mask);
 
 	printk(KERN_INFO "sending NMI to all CPUs:\n");

@@ -56,8 +81,39 @@ void arch_trigger_all_cpu_backtrace(void)
 		mdelay(1);
 	}
 
+	for_each_possible_cpu(cpu) {
+		int last_i = 0;
+
+		s = &per_cpu(nmi_print_seq, cpu);
+		len = s->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();
+	return true;
+}
+
+static int nmi_vprintk(const char *fmt, va_list args)
+{
+	struct trace_seq *s = this_cpu_ptr(&nmi_print_seq);
+	int len = s->len;
+
+	trace_seq_vprintf(s, fmt, args);
+	return s->len - len;
 }
 
 static int

@@ -68,12 +124,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);
-		printk(KERN_WARNING "NMI backtrace for cpu %d\n", cpu);
+		/* Replace printk to write into the NMI seq */
+		this_cpu_write(printk_func, nmi_vprintk);
+		printk("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 · 8 lines

2.0.0.rc2


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

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

Patch 1: move the trace_seq out of the tracing code. It's useful for other
purposes too. Like writing from an NMI context.

Patch 2: Add a per_cpu "printk_func" that printk calls. By default it calls
vprintk_def() which does what it has always done. This allows us to override what printk() calls normally on a per cpu basis.

Patch 3: Have the NMI handler that dumps the stack trace just change the
printk_func to call a NMI safe printk function that writes to a per cpu trace_seq. When all NMI handlers chimed in, the original caller prints out the trace_seqs for each CPU from a printk safe context.

This is much less intrusive than the other versions out there.

I agree this is less intrusive than having printk() use two versions of the buffers and perform merging, OTOH, it doesn't really seem to be fully clean and systematic solution either.

I had a different idea earlier today, and Petr seems to have implemented it already; I guess he'll be sending it out as RFC tomorrow for comparision.

The idea basically is to *switch* what arch_trigger_all_cpu_backtrace() and arch_trigger_all_cpu_backtrace_handler() are doing; i.e. use the NMI as a way to stop all the CPUs (one by one), and let the CPU that is sending the NMIs around to actually walk and dump the stacks of the CPUs receiving the NMI IPI.

It's the most trivial aproach I've been able to come up with, and should be usable for everybody (RCU stall detector and sysrq). The only tricky part is: if we want pt_regs to be part of the dump as well, how to pass those cleanly between the 'stopped' CPU and the CPU that is doing the printing. Other than that, it's just moving a few lines of code around, I believe.

Quoted 5 lines

The idea basically is to *switch* what arch_trigger_all_cpu_backtrace() and arch_trigger_all_cpu_backtrace_handler() are doing; i.e. use the NMI as a way to stop all the CPUs (one by one), and let the CPU that is sending the NMIs around to actually walk and dump the stacks of the CPUs receiving the NMI IPI.

And this is cleaner? Stopping a CPU via NMI and then what happens if something else goes wrong and that CPU never starts back up? This sounds like something that can cause more problems than it was reporting on.

Then you also need to print out the data while the NMIs still spin.

Quoted 10 lines · Steven Rostedt

Quoted 5 lines

The idea basically is to *switch* what arch_trigger_all_cpu_backtrace() and arch_trigger_all_cpu_backtrace_handler() are doing; i.e. use the NMI as a way to stop all the CPUs (one by one), and let the CPU that is sending the NMIs around to actually walk and dump the stacks of the CPUs receiving the NMI IPI.

And this is cleaner? Stopping a CPU via NMI and then what happens if something else goes wrong and that CPU never starts back up? This sounds like something that can cause more problems than it was reporting on.

It's going to get NMI in exactly the same situations it does with the current arch_trigger_all_cpu_backtrace(), the only difference being that it doesn't try to invoke printk() from inside NMI. The IPI-NMI is used solely as a point of synchronization for the stack dumping.

Quoted 2 lines

Then you also need to print out the data while the NMIs still spin.

Exactly, that's actually the whole point.

Quoted 11 lines

Quoted 10 lines

Quoted 5 lines

The idea basically is to *switch* what arch_trigger_all_cpu_backtrace() and arch_trigger_all_cpu_backtrace_handler() are doing; i.e. use the NMI as a way to stop all the CPUs (one by one), and let the CPU that is sending the NMIs around to actually walk and dump the stacks of the CPUs receiving the NMI IPI.

And this is cleaner? Stopping a CPU via NMI and then what happens if something else goes wrong and that CPU never starts back up? This sounds like something that can cause more problems than it was reporting on.

Quoted 4 lines

It's going to get NMI in exactly the same situations it does with the current arch_trigger_all_cpu_backtrace(), the only difference being that it doesn't try to invoke printk() from inside NMI. The IPI-NMI is used solely as a point of synchronization for the stack dumping.

Well, all CPUs are going to be spinning until the main CPU prints everything out. That's not quite the same thing as what it use to do.

I don't think there is a need for a global stop_machine()-like synchronization here. The printing CPU will be sending IPI to the CPU N+1 only after it has finished printing CPU N stacktrace.

Quoted 3 lines

I don't think there is a need for a global stop_machine()-like synchronization here. The printing CPU will be sending IPI to the CPU N+1 only after it has finished printing CPU N stacktrace.

So you plan on sending an IPI to a CPU then wait for it to acknowledge that it is spinning, and then print out the data and then tell the CPU it can stop spinning?

Quoted 4 lines · Steven Rostedt

Quoted 3 lines

I don't think there is a need for a global stop_machine()-like synchronization here. The printing CPU will be sending IPI to the CPU N+1 only after it has finished printing CPU N stacktrace.

Quoted 3 lines

So you plan on sending an IPI to a CPU then wait for it to acknowledge that it is spinning, and then print out the data and then tell the CPU it can stop spinning?

Yes, that was exactly my idea. You have to be synchronized with the CPU receiving the NMI anyway in case you'd like to get its pt_regs and dump those as part of the dump.

Quoted 6 lines · Jiri Kosina

Quoted 4 lines · Steven Rostedt

Quoted 3 lines

I don't think there is a need for a global stop_machine()-like synchronization here. The printing CPU will be sending IPI to the CPU N+1 only after it has finished printing CPU N stacktrace.

Quoted 7 lines

Quoted 3 lines

So you plan on sending an IPI to a CPU then wait for it to acknowledge that it is spinning, and then print out the data and then tell the CPU it can stop spinning?

Yes, that was exactly my idea. You have to be synchronized with the CPU receiving the NMI anyway in case you'd like to get its pt_regs and dump those as part of the dump.

This approach did not work after all. There was still the same race. If we stop a CPU in the middle of printk(), it does not help to move the printing task to another CPU ;-) We would need to make a copy of regs and all the stacks to unblock the CPU.

Hmm, in general, if we want a consistent snapshot, we need to temporary store the information in NMI context and put it into the main ring buffer in normal context. We either need to copy stacks or copy the printed text.

I start to like Steven's solution with the trace_seq buffer. I see the following advantages:

+ the snapshot is pretty good;
+ we still send NMI to all CPUs at the "same" time

+ only minimal time is spent in NMI context;
+ CPUs are not blocked by each other to get sequential output

+ minimum of new code
+ trace_seq buffer is already implemented and used
+ it might be even better after getting attention from new users

Of course, it has also some disadvantages:

+ needs quite big per-CPU buffer;
+ but we would need some extra space to copy the data anyway

+ trace might be shrunken;
+ but 1 page should be enough in most cases;
+ we could make it configurable

+ delay until the message appears in the ringbuffer and console
+ better than freezing
+ still saved in core file
+ crash tool could get improved to find the traces

Note that the above solution solves only printing of the stack. There are still other locations when printk is called in NMI context. IMHO, some of them are helpful:

    ./arch/x86/kernel/nmi.c:                        WARN(in_nmi(),
    ./arch/x86/mm/kmemcheck/kmemcheck.c:    WARN_ON_ONCE(in_nmi());
    ./arch/x86/mm/fault.c:  WARN_ON_ONCE(in_nmi());
    ./arch/x86/mm/fault.c:  WARN_ON_ONCE(in_nmi());

    ./mm/vmalloc.c: BUG_ON(in_nmi());
    ./lib/genalloc.c:       BUG_ON(in_nmi());
    ./lib/genalloc.c:       BUG_ON(in_nmi());
    ./include/linux/hardirq.h:              BUG_ON(in_nmi());

And some are probably less important:

./arch/x86/platform/uv/uv_nmi.c several locations here
./arch/m68k/mac/macints.c- printk("... pausing, press NMI to resume ...");

Well, there are only few. Maybe, we could share the trace_seq buffer here.

Of course, there is still the possibility to implement a lockless buffer. But it will be much more complicated than the current one. I am not sure that we really want it.

Best Regards,
Petr
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Originally I thought that seizing all cpus one by one and printing from the initiator is a best approach and I've started preparing arguments against over-engineered printk...

Quoted 3 lines · Konstantin Khlebnikov

Originally I thought that seizing all cpus one by one and printing from the initiator is a best approach and I've started preparing arguments against over-engineered printk...

By "seizing" I guess you mean sending IPI, right?

What do you do if you'd interrupt it in the middle of printk() in order not to deadlock by trying to take the buffer lock on the initiator CPU?

--
Jiri Kosina
SUSE Labs

Quoted 1 line · Jiri Kosina

On Tue, 24 Jun 2014, Konstantin Khlebnikov wrote:

I like that context-depend printk routing from this patchset. I'm just not quite happy with this straight forward implementation. Rerouting flow into different buffers might serve different purposes, it must make code simpler instead of adding yet another knot. For example printk continuation might use it too.

Instead of per-cpu buffers printk might use part of existing ring buffer -- initiator cpu allocates space for
target cpu and flushes it into common stream after it finish printing. Probably this kind of transactional model might be used on single cpu for multi-line KERN_CONT.