Skip to contentSkip to conversation

tracing: kdb: Fix ftdump to not sleep

PATCH In review Douglas Anderson 2 participants 5 messages Mar 8, 2019 – Mar 13, 2019

Subsystems (2)
lore
Share & tools
lore
#0 lore raw

PATCH v2 1/2 tracing: kdb: Fix ftdump to not sleep

As reported back in 2016-11 [1], the "ftdump" kdb command triggers a BUG for "sleeping function called from invalid context".

kdb's "ftdump" command wants to call ring_buffer_read_prepare() in atomic context. A very simple solution for this is to add allocation flags to ring_buffer_read_prepare() so kdb can call it without triggering the allocation error. This patch does that.

Note that in the original email thread about this, it was suggested that perhaps the solution for kdb was to either preallocate the buffer ahead of time or create our own iterator. I'm hoping that this alternative of adding allocation flags to ring_buffer_read_prepare() can be considered since it means I don't need to duplicate more of the core trace code into "trace_kdb.c" (for either creating my own iterator or re-preparing a ring allocator whose memory was already allocated).

NOTE: another option for kdb is to actually figure out how to make it reuse the existing ftrace_dump() function and totally eliminate the duplication. This sounds very appealing and actually works (the "sr z" command can be seen to properly dump the ftrace buffer). The downside here is that ftrace_dump() fully consumes the trace buffer. Unless that is changed I'd rather not use it because it means "ftdump | grep xyz" won't be very useful to search the ftrace buffer since it will throw away the whole trace on the first grep. A future patch to dump only the last few lines of the buffer will also be hard to implement.

[1] https://lkml.kernel.org/r/[email protected]

---

Changes in v2:
- Don't introduce _ring_buffer_read_prepare(), just change args

 include/linux/ring_buffer.h | 2 +-
 kernel/trace/ring_buffer.c  | 5 +++--
 kernel/trace/trace.c        | 6 ++++--
 kernel/trace/trace_kdb.c    | 6 ++++--
 4 files changed, 12 insertions(+), 7 deletions(-)
include/linux/ring_buffer.h +1 -1
index 5b9ae62272bb..503778920448 100644
@@ -128,7 +128,7 @@ ring_buffer_consume(struct ring_buffer *buffer, int cpu, u64 *ts,
 		    unsigned long *lost_events);
 
 struct ring_buffer_iter *
-ring_buffer_read_prepare(struct ring_buffer *buffer, int cpu);
+ring_buffer_read_prepare(struct ring_buffer *buffer, int cpu, gfp_t flags);
 void ring_buffer_read_prepare_sync(void);
 void ring_buffer_read_start(struct ring_buffer_iter *iter);
 void ring_buffer_read_finish(struct ring_buffer_iter *iter);
kernel/trace/ring_buffer.c +3 -2
index 06e864a334bb..b49affb4666b 100644
@@ -4205,6 +4205,7 @@ EXPORT_SYMBOL_GPL(ring_buffer_consume);
  * ring_buffer_read_prepare - Prepare for a non consuming read of the buffer
  * @buffer: The ring buffer to read from
  * @cpu: The cpu buffer to iterate over
+ * @flags: gfp flags to use for memory allocation
  *
  * This performs the initial preparations necessary to iterate
  * through the buffer.  Memory is allocated, buffer recording
@@ -4222,7 +4223,7 @@ EXPORT_SYMBOL_GPL(ring_buffer_consume);
  * This overall must be paired with ring_buffer_read_finish.
  */
 struct ring_buffer_iter *
-ring_buffer_read_prepare(struct ring_buffer *buffer, int cpu)
+ring_buffer_read_prepare(struct ring_buffer *buffer, int cpu, gfp_t flags)
 {
 	struct ring_buffer_per_cpu *cpu_buffer;
 	struct ring_buffer_iter *iter;
@@ -4230,7 +4231,7 @@ ring_buffer_read_prepare(struct ring_buffer *buffer, int cpu)
 	if (!cpumask_test_cpu(cpu, buffer->cpumask))
 		return NULL;
 
-	iter = kmalloc(sizeof(*iter), GFP_KERNEL);
+	iter = kmalloc(sizeof(*iter), flags);
 	if (!iter)
 		return NULL;
 
kernel/trace/trace.c +4 -2
index c4238b441624..8867a93246d6 100644
@@ -3904,7 +3904,8 @@ __tracing_open(struct inode *inode, struct file *file, bool snapshot)
 	if (iter->cpu_file == RING_BUFFER_ALL_CPUS) {
 		for_each_tracing_cpu(cpu) {
 			iter->buffer_iter[cpu] =
-				ring_buffer_read_prepare(iter->trace_buffer->buffer, cpu);
+				ring_buffer_read_prepare(iter->trace_buffer->buffer,
+							 cpu, GFP_KERNEL);
 		}
 		ring_buffer_read_prepare_sync();
 		for_each_tracing_cpu(cpu) {
@@ -3914,7 +3915,8 @@ __tracing_open(struct inode *inode, struct file *file, bool snapshot)
 	} else {
 		cpu = iter->cpu_file;
 		iter->buffer_iter[cpu] =
-			ring_buffer_read_prepare(iter->trace_buffer->buffer, cpu);
+			ring_buffer_read_prepare(iter->trace_buffer->buffer,
+						 cpu, GFP_KERNEL);
 		ring_buffer_read_prepare_sync();
 		ring_buffer_read_start(iter->buffer_iter[cpu]);
 		tracing_iter_reset(iter, cpu);
kernel/trace/trace_kdb.c +4 -2
index d953c163a079..810d78a8d14c 100644
@@ -51,14 +51,16 @@ static void ftrace_dump_buf(int skip_lines, long cpu_file)
 	if (cpu_file == RING_BUFFER_ALL_CPUS) {
 		for_each_tracing_cpu(cpu) {
 			iter.buffer_iter[cpu] =
-			ring_buffer_read_prepare(iter.trace_buffer->buffer, cpu);
+			ring_buffer_read_prepare(iter.trace_buffer->buffer,
+						 cpu, GFP_ATOMIC);
 			ring_buffer_read_start(iter.buffer_iter[cpu]);
 			tracing_iter_reset(&iter, cpu);
 		}
 	} else {
 		iter.cpu_file = cpu_file;
 		iter.buffer_iter[cpu_file] =
-			ring_buffer_read_prepare(iter.trace_buffer->buffer, cpu_file);
+			ring_buffer_read_prepare(iter.trace_buffer->buffer,
+						 cpu_file, GFP_ATOMIC);
 		ring_buffer_read_start(iter.buffer_iter[cpu_file]);
 		tracing_iter_reset(&iter, cpu_file);
 	}
Signature · 1 line
2.21.0.360.g471c308f928-goog
#1 lore raw

PATCH v2 2/2 tracing: kdb: Allow ftdump to skip all but the last few lines

The 'ftdump' command in kdb is currently a bit of a last resort, at least if you have lots of traces turned on. It's going to print a whole boatload of lines out your serial port which is probably running at 115200. This could easily take many, many minutes.

Usually you're most interested in what's at the _end_ of the ftrace buffer, AKA what happened most recently. That means you've got to wait the full time for the dump. The 'ftdump' command does attempt to help you a little bit by allowing you to skip a fixed number of lines. Unfortunately it provides no way for you to know how many lines you should skip.

Let's do similar to python and allow you to use a negative number to indicate that you want to skip all lines except the last few. This allows you to quickly see what you want.

---

Changes in v2: None

 kernel/trace/trace_kdb.c | 51 ++++++++++++++++++++++++++--------------
 1 file changed, 34 insertions(+), 17 deletions(-)
kernel/trace/trace_kdb.c +34 -17
index 810d78a8d14c..7614b5c529f6 100644
@@ -17,7 +17,7 @@
 #include "trace.h"
 #include "trace_output.h"
 
-static void ftrace_dump_buf(int skip_lines, long cpu_file)
+static int ftrace_dump_buf(int skip_lines, long cpu_file, bool quiet)
 {
 	/* use static because iter can be a bit big for the stack */
 	static struct trace_iterator iter;
@@ -39,7 +39,9 @@ static void ftrace_dump_buf(int skip_lines, long cpu_file)
 	/* don't look at user memory in panic mode */
 	tr->trace_flags &= ~TRACE_ITER_SYM_USEROBJ;
 
-	kdb_printf("Dumping ftrace buffer:\n");
+	if (!quiet)
+		kdb_printf("Dumping ftrace buffer (skipping %d lines):\n",
+			   skip_lines);
 
 	/* reset all but tr, trace, and overruns */
 	memset(&iter.seq, 0,
@@ -66,25 +68,29 @@ static void ftrace_dump_buf(int skip_lines, long cpu_file)
 	}
 
 	while (trace_find_next_entry_inc(&iter)) {
-		if (!cnt)
-			kdb_printf("---------------------------------\n");
-		cnt++;
-
-		if (!skip_lines) {
-			print_trace_line(&iter);
-			trace_printk_seq(&iter.seq);
-		} else {
-			skip_lines--;
+		if (!quiet) {
+			if (!cnt)
+				kdb_printf("---------------------------------\n");
+
+			if (!skip_lines) {
+				print_trace_line(&iter);
+				trace_printk_seq(&iter.seq);
+			} else {
+				skip_lines--;
+			}
 		}
+		cnt++;
 
 		if (KDB_FLAG(CMD_INTERRUPT))
 			goto out;
 	}
 
-	if (!cnt)
-		kdb_printf("   (ftrace buffer empty)\n");
-	else
-		kdb_printf("---------------------------------\n");
+	if (!quiet) {
+		if (!cnt)
+			kdb_printf("   (ftrace buffer empty)\n");
+		else
+			kdb_printf("---------------------------------\n");
+	}
 
 out:
 	tr->trace_flags = old_userobj;
@@ -99,6 +105,8 @@ static void ftrace_dump_buf(int skip_lines, long cpu_file)
 			iter.buffer_iter[cpu] = NULL;
 		}
 	}
+
+	return cnt;
 }
 
 /*
@@ -109,6 +117,7 @@ static int kdb_ftdump(int argc, const char **argv)
 	int skip_lines = 0;
 	long cpu_file;
 	char *cp;
+	int count;
 
 	if (argc > 2)
 		return KDB_ARGCOUNT;
@@ -129,7 +138,14 @@ static int kdb_ftdump(int argc, const char **argv)
 	}
 
 	kdb_trap_printk++;
-	ftrace_dump_buf(skip_lines, cpu_file);
+
+	/* A negative skip_lines means skip all but the last lines */
+	if (skip_lines < 0) {
+		count = ftrace_dump_buf(0, cpu_file, true);
+		skip_lines = max(count + skip_lines, 0);
+	}
+
+	count = ftrace_dump_buf(skip_lines, cpu_file, false);
 	kdb_trap_printk--;
 
 	return 0;
@@ -138,7 +154,8 @@ static int kdb_ftdump(int argc, const char **argv)
 static __init int kdb_ftrace_register(void)
 {
 	kdb_register_flags("ftdump", kdb_ftdump, "[skip_#lines] [cpu]",
-			    "Dump ftrace log", 0, KDB_ENABLE_ALWAYS_SAFE);
+			    "Dump ftrace log; -skip dumps last #lines", 0,
+			    KDB_ENABLE_ALWAYS_SAFE);
 	return 0;
 }
 
Signature · 1 line
2.21.0.360.g471c308f928-goog
maintainer
#2 lore raw

Re: [PATCH v2 2/2] tracing: kdb: Allow ftdump to skip all but the last few lines

Quoted 12 lines · On Fri, 8 Mar 2019 11:32:05 -0800 Douglas Anderson <[email protected]>…

The 'ftdump' command in kdb is currently a bit of a last resort, at least if you have lots of traces turned on. It's going to print a whole boatload of lines out your serial port which is probably running at 115200. This could easily take many, many minutes.

Usually you're most interested in what's at the _end_ of the ftrace buffer, AKA what happened most recently. That means you've got to wait the full time for the dump. The 'ftdump' command does attempt to help you a little bit by allowing you to skip a fixed number of lines. Unfortunately it provides no way for you to know how many lines you should skip.

Quoted 3 lines

Let's do similar to python and allow you to use a negative number to indicate that you want to skip all lines except the last few. This allows you to quickly see what you want.

Why not just read how many entries are in the ring buffer and return that?

	cnt = 0;
	for_each_cpu(cpu, tr->tracing_cpumask)
		cnt += ring_buffer_entries_cpu(tr->trace_buffer, cpu);
	return cnt;

The output will print out one entry per line.

-- Steve

Quoted 4 lines

---

maintainer
#3 lore raw

Re: [PATCH v2 2/2] tracing: kdb: Allow ftdump to skip all but the last few lines

Quoted 19 lines · On Tue, 12 Mar 2019 23:25:28 -0400 Steven Rostedt <[email protected]> wrote:
Quoted 12 lines · On Fri, 8 Mar 2019 11:32:05 -0800 Douglas Anderson <[email protected]>…

The 'ftdump' command in kdb is currently a bit of a last resort, at least if you have lots of traces turned on. It's going to print a whole boatload of lines out your serial port which is probably running at 115200. This could easily take many, many minutes.

Usually you're most interested in what's at the _end_ of the ftrace buffer, AKA what happened most recently. That means you've got to wait the full time for the dump. The 'ftdump' command does attempt to help you a little bit by allowing you to skip a fixed number of lines. Unfortunately it provides no way for you to know how many lines you should skip.

Quoted 3 lines

Let's do similar to python and allow you to use a negative number to indicate that you want to skip all lines except the last few. This allows you to quickly see what you want.

Quoted 9 lines

Why not just read how many entries are in the ring buffer and return that?

	cnt = 0;
	for_each_cpu(cpu, tr->tracing_cpumask)
		cnt += ring_buffer_entries_cpu(tr->trace_buffer, cpu);
	return cnt;

The output will print out one entry per line.

Note, I pulled in patch 1 into my queue. So you only need to resend this patch.

-- Steve

maintainer
#4 lore raw
In reply to Douglas Anderson
Quoted 28 lines · On Fri, 8 Mar 2019 11:32:04 -0800 Douglas Anderson <[email protected]>…

As reported back in 2016-11 [1], the "ftdump" kdb command triggers a BUG for "sleeping function called from invalid context".

kdb's "ftdump" command wants to call ring_buffer_read_prepare() in atomic context. A very simple solution for this is to add allocation flags to ring_buffer_read_prepare() so kdb can call it without triggering the allocation error. This patch does that.

Note that in the original email thread about this, it was suggested that perhaps the solution for kdb was to either preallocate the buffer ahead of time or create our own iterator. I'm hoping that this alternative of adding allocation flags to ring_buffer_read_prepare() can be considered since it means I don't need to duplicate more of the core trace code into "trace_kdb.c" (for either creating my own iterator or re-preparing a ring allocator whose memory was already allocated).

NOTE: another option for kdb is to actually figure out how to make it reuse the existing ftrace_dump() function and totally eliminate the duplication. This sounds very appealing and actually works (the "sr z" command can be seen to properly dump the ftrace buffer). The downside here is that ftrace_dump() fully consumes the trace buffer. Unless that is changed I'd rather not use it because it means "ftdump | grep xyz" won't be very useful to search the ftrace buffer since it will throw away the whole trace on the first grep. A future patch to dump only the last few lines of the buffer will also be hard to implement.

Quoted 6 lines

[1] https://lkml.kernel.org/r/[email protected]

---

Thanks for sending this. I'm currently traveling and also have to get the merge window patches out, I wont be able to get to these till I have that settled. If you don't hear from me in a week, please send me a reminder.

Thanks!

-- Steve