[PATCH v4 1/3] tracing: kdb: The skip_lines parameter should have been skip_entries

[PATCH v4 1/3] tracing: kdb: The skip_lines parameter should have been skip_entries

[Douglas Anderson]

The things skipped by kdb's "ftdump" command when you pass it a
parameter has always been entries, not lines.  The difference usually
doesn't matter but when the trace buffer has multi-line entries (like
a stack dump) it can matter.

Let's fix this both in the help text for ftdump and also in the local
variable names.

Signed-off-by: Douglas Anderson <dianders@chromium.org>
---

Changes in v4:
- skip_lines => skip_entries new for v4.

Changes in v3: None

 kernel/trace/trace_kdb.c | 16 ++++++++--------
 1 file changed, 8 insertions(+), 8 deletions(-)

diff --git a/kernel/trace/trace_kdb.c b/kernel/trace/trace_kdb.c
index 810d78a8d14c..4b666643d69f 100644
--- a/kernel/trace/trace_kdb.c
+++ b/kernel/trace/trace_kdb.c
@@ -17,7 +17,7 @@
 #include "trace.h"
 #include "trace_output.h"
 
-static void ftrace_dump_buf(int skip_lines, long cpu_file)
+static void ftrace_dump_buf(int skip_entries, long cpu_file)
 {
 	/* use static because iter can be a bit big for the stack */
 	static struct trace_iterator iter;
@@ -70,11 +70,11 @@ static void ftrace_dump_buf(int skip_lines, long cpu_file)
 			kdb_printf("---------------------------------\n");
 		cnt++;
 
-		if (!skip_lines) {
+		if (!skip_entries) {
 			print_trace_line(&iter);
 			trace_printk_seq(&iter.seq);
 		} else {
-			skip_lines--;
+			skip_entries--;
 		}
 
 		if (KDB_FLAG(CMD_INTERRUPT))
@@ -106,7 +106,7 @@ static void ftrace_dump_buf(int skip_lines, long cpu_file)
  */
 static int kdb_ftdump(int argc, const char **argv)
 {
-	int skip_lines = 0;
+	int skip_entries = 0;
 	long cpu_file;
 	char *cp;
 
@@ -114,9 +114,9 @@ static int kdb_ftdump(int argc, const char **argv)
 		return KDB_ARGCOUNT;
 
 	if (argc) {
-		skip_lines = simple_strtol(argv[1], &cp, 0);
+		skip_entries = simple_strtol(argv[1], &cp, 0);
 		if (*cp)
-			skip_lines = 0;
+			skip_entries = 0;
 	}
 
 	if (argc == 2) {
@@ -129,7 +129,7 @@ static int kdb_ftdump(int argc, const char **argv)
 	}
 
 	kdb_trap_printk++;
-	ftrace_dump_buf(skip_lines, cpu_file);
+	ftrace_dump_buf(skip_entries, cpu_file);
 	kdb_trap_printk--;
 
 	return 0;
@@ -137,7 +137,7 @@ 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]",
+	kdb_register_flags("ftdump", kdb_ftdump, "[skip_#entries] [cpu]",
 			    "Dump ftrace log", 0, KDB_ENABLE_ALWAYS_SAFE);
 	return 0;
 }
-- 
2.21.0.360.g471c308f928-goog

[PATCH v4 2/3] tracing: Add trace_total_entries() / trace_total_entries_cpu()

[Douglas Anderson]

These two new exported functions will be used in a future patch by
kdb_ftdump() to quickly skip all but the last few trace entries.

Suggested-by: Steven Rostedt <rostedt@goodmis.org>
Signed-off-by: Douglas Anderson <dianders@chromium.org>
---

Changes in v4:
- trace_total_entries() / trace_total_entries_cpu() new for v4

Changes in v3: None

 kernel/trace/trace.c | 65 ++++++++++++++++++++++++++++++++++----------
 kernel/trace/trace.h |  3 ++
 2 files changed, 53 insertions(+), 15 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index ccd759eaad79..7afc90f82e53 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3490,34 +3490,69 @@ static void s_stop(struct seq_file *m, void *p)
 	trace_event_read_unlock();
 }
 
+static void
+get_total_entries_cpu(struct trace_buffer *buf, unsigned long *total,
+		      unsigned long *entries, int cpu)
+{
+	unsigned long count;
+
+	count = ring_buffer_entries_cpu(buf->buffer, cpu);
+	/*
+	 * If this buffer has skipped entries, then we hold all
+	 * entries for the trace and we need to ignore the
+	 * ones before the time stamp.
+	 */
+	if (per_cpu_ptr(buf->data, cpu)->skipped_entries) {
+		count -= per_cpu_ptr(buf->data, cpu)->skipped_entries;
+		/* total is the same as the entries */
+		*total = count;
+	} else
+		*total = count +
+			ring_buffer_overrun_cpu(buf->buffer, cpu);
+	*entries = count;
+}
+
 static void
 get_total_entries(struct trace_buffer *buf,
 		  unsigned long *total, unsigned long *entries)
 {
-	unsigned long count;
+	unsigned long t, e;
 	int cpu;
 
 	*total = 0;
 	*entries = 0;
 
 	for_each_tracing_cpu(cpu) {
-		count = ring_buffer_entries_cpu(buf->buffer, cpu);
-		/*
-		 * If this buffer has skipped entries, then we hold all
-		 * entries for the trace and we need to ignore the
-		 * ones before the time stamp.
-		 */
-		if (per_cpu_ptr(buf->data, cpu)->skipped_entries) {
-			count -= per_cpu_ptr(buf->data, cpu)->skipped_entries;
-			/* total is the same as the entries */
-			*total += count;
-		} else
-			*total += count +
-				ring_buffer_overrun_cpu(buf->buffer, cpu);
-		*entries += count;
+		get_total_entries_cpu(buf, &t, &e, cpu);
+		*total += t;
+		*entries += e;
 	}
 }
 
+unsigned long trace_total_entries_cpu(struct trace_array *tr, int cpu)
+{
+	unsigned long total, entries;
+
+	if (!tr)
+		tr = &global_trace;
+
+	get_total_entries_cpu(&tr->trace_buffer, &total, &entries, cpu);
+
+	return entries;
+}
+
+unsigned long trace_total_entries(struct trace_array *tr)
+{
+	unsigned long total, entries;
+
+	if (!tr)
+		tr = &global_trace;
+
+	get_total_entries(&tr->trace_buffer, &total, &entries);
+
+	return entries;
+}
+
 static void print_lat_help_header(struct seq_file *m)
 {
 	seq_puts(m, "#                  _------=> CPU#            \n"
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index d80cee49e0eb..4562b30eda9d 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -719,6 +719,9 @@ void trace_init_global_iter(struct trace_iterator *iter);
 
 void tracing_iter_reset(struct trace_iterator *iter, int cpu);
 
+unsigned long trace_total_entries_cpu(struct trace_array *tr, int cpu);
+unsigned long trace_total_entries(struct trace_array *tr);
+
 void trace_function(struct trace_array *tr,
 		    unsigned long ip,
 		    unsigned long parent_ip,
-- 
2.21.0.360.g471c308f928-goog

[PATCH v4 3/3] tracing: kdb: Allow ftdump to skip all but the last few entries

[Douglas Anderson]

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 data 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
entries.  Unfortunately it provides no way for you to know how many
entries 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 entries except the last few.  This
allows you to quickly see what you want.

Note that we also change the printout in ftdump to print the
(positive) number of entries actually skipped since that could be
helpful to know when you've specified a negative skip count.

Signed-off-by: Douglas Anderson <dianders@chromium.org>
---

Changes in v4:
- Now uses trace_total_entries() / trace_total_entries_cpu().
- Based upon new patch that renames "lines" to "entries".

Changes in v3:
- Optimize counting as per Steven Rostedt.
- Down to 1 patch since patch #1 from v2 landed.

 kernel/trace/trace_kdb.c | 17 +++++++++++++++--
 1 file changed, 15 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/trace_kdb.c b/kernel/trace/trace_kdb.c
index 4b666643d69f..996e1e9cd9a6 100644
--- a/kernel/trace/trace_kdb.c
+++ b/kernel/trace/trace_kdb.c
@@ -39,7 +39,8 @@ static void ftrace_dump_buf(int skip_entries, 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");
+	kdb_printf("Dumping ftrace buffer (skipping %d entries):\n",
+		   skip_entries);
 
 	/* reset all but tr, trace, and overruns */
 	memset(&iter.seq, 0,
@@ -109,6 +110,7 @@ static int kdb_ftdump(int argc, const char **argv)
 	int skip_entries = 0;
 	long cpu_file;
 	char *cp;
+	int cnt;
 
 	if (argc > 2)
 		return KDB_ARGCOUNT;
@@ -129,6 +131,16 @@ static int kdb_ftdump(int argc, const char **argv)
 	}
 
 	kdb_trap_printk++;
+
+	/* A negative skip_entries means skip all but the last entries */
+	if (skip_entries < 0) {
+		if (cpu_file == RING_BUFFER_ALL_CPUS)
+			cnt = trace_total_entries(NULL);
+		else
+			cnt = trace_total_entries_cpu(NULL, cpu_file);
+		skip_entries = max(cnt + skip_entries, 0);
+	}
+
 	ftrace_dump_buf(skip_entries, cpu_file);
 	kdb_trap_printk--;
 
@@ -138,7 +150,8 @@ static int kdb_ftdump(int argc, const char **argv)
 static __init int kdb_ftrace_register(void)
 {
 	kdb_register_flags("ftdump", kdb_ftdump, "[skip_#entries] [cpu]",
-			    "Dump ftrace log", 0, KDB_ENABLE_ALWAYS_SAFE);
+			    "Dump ftrace log; -skip dumps last #entries", 0,
+			    KDB_ENABLE_ALWAYS_SAFE);
 	return 0;
 }
 
-- 
2.21.0.360.g471c308f928-goog

Re: [PATCH v4 3/3] tracing: kdb: Allow ftdump to skip all but the last few entries

[Daniel Thompson]

On Fri, Mar 15, 2019 at 04:09:06PM -0700, Douglas Anderson wrote:
> 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 data 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
> entries.  Unfortunately it provides no way for you to know how many
> entries 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 entries except the last few.  This
> allows you to quickly see what you want.
> 
> Note that we also change the printout in ftdump to print the
> (positive) number of entries actually skipped since that could be
> helpful to know when you've specified a negative skip count.
> 
> Signed-off-by: Douglas Anderson <dianders@chromium.org>

There's a small nitpick below but otherwise:
Acked-by: Daniel Thompson <daniel.thompson@linaro.org>


> ---
> 
> Changes in v4:
> - Now uses trace_total_entries() / trace_total_entries_cpu().
> - Based upon new patch that renames "lines" to "entries".
> 
> Changes in v3:
> - Optimize counting as per Steven Rostedt.
> - Down to 1 patch since patch #1 from v2 landed.
> 
>  kernel/trace/trace_kdb.c | 17 +++++++++++++++--
>  1 file changed, 15 insertions(+), 2 deletions(-)
> 
> diff --git a/kernel/trace/trace_kdb.c b/kernel/trace/trace_kdb.c
> index 4b666643d69f..996e1e9cd9a6 100644
> --- a/kernel/trace/trace_kdb.c
> +++ b/kernel/trace/trace_kdb.c
> @@ -39,7 +39,8 @@ static void ftrace_dump_buf(int skip_entries, 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");
> +	kdb_printf("Dumping ftrace buffer (skipping %d entries):\n",
> +		   skip_entries);

If someone *doesn't* need to skip any entries I'm not a fan of telling
them we are "skipping 0 entries"; it is more unnerving than helpful
("huh? what does it need to tell me that no entried were skipped?
what makes the tracer skip entries?... Doh... I get it").


Daniel.


>  
>  	/* reset all but tr, trace, and overruns */
>  	memset(&iter.seq, 0,
> @@ -109,6 +110,7 @@ static int kdb_ftdump(int argc, const char **argv)
>  	int skip_entries = 0;
>  	long cpu_file;
>  	char *cp;
> +	int cnt;
>  
>  	if (argc > 2)
>  		return KDB_ARGCOUNT;
> @@ -129,6 +131,16 @@ static int kdb_ftdump(int argc, const char **argv)
>  	}
>  
>  	kdb_trap_printk++;
> +
> +	/* A negative skip_entries means skip all but the last entries */
> +	if (skip_entries < 0) {
> +		if (cpu_file == RING_BUFFER_ALL_CPUS)
> +			cnt = trace_total_entries(NULL);
> +		else
> +			cnt = trace_total_entries_cpu(NULL, cpu_file);
> +		skip_entries = max(cnt + skip_entries, 0);
> +	}
> +
>  	ftrace_dump_buf(skip_entries, cpu_file);
>  	kdb_trap_printk--;
>  
> @@ -138,7 +150,8 @@ static int kdb_ftdump(int argc, const char **argv)
>  static __init int kdb_ftrace_register(void)
>  {
>  	kdb_register_flags("ftdump", kdb_ftdump, "[skip_#entries] [cpu]",
> -			    "Dump ftrace log", 0, KDB_ENABLE_ALWAYS_SAFE);
> +			    "Dump ftrace log; -skip dumps last #entries", 0,
> +			    KDB_ENABLE_ALWAYS_SAFE);
>  	return 0;
>  }
>  
> -- 
> 2.21.0.360.g471c308f928-goog
> 

Re: [PATCH v4 1/3] tracing: kdb: The skip_lines parameter should have been skip_entries

[Daniel Thompson]

On Fri, Mar 15, 2019 at 04:09:04PM -0700, Douglas Anderson wrote:
> The things skipped by kdb's "ftdump" command when you pass it a
> parameter has always been entries, not lines.  The difference usually
> doesn't matter but when the trace buffer has multi-line entries (like
> a stack dump) it can matter.
> 
> Let's fix this both in the help text for ftdump and also in the local
> variable names.
> 
> Signed-off-by: Douglas Anderson <dianders@chromium.org>

Acked-by: Daniel Thompson <daniel.thompson@linaro.org>

> ---
> 
> Changes in v4:
> - skip_lines => skip_entries new for v4.
> 
> Changes in v3: None
> 
>  kernel/trace/trace_kdb.c | 16 ++++++++--------
>  1 file changed, 8 insertions(+), 8 deletions(-)
> 
> diff --git a/kernel/trace/trace_kdb.c b/kernel/trace/trace_kdb.c
> index 810d78a8d14c..4b666643d69f 100644
> --- a/kernel/trace/trace_kdb.c
> +++ b/kernel/trace/trace_kdb.c
> @@ -17,7 +17,7 @@
>  #include "trace.h"
>  #include "trace_output.h"
>  
> -static void ftrace_dump_buf(int skip_lines, long cpu_file)
> +static void ftrace_dump_buf(int skip_entries, long cpu_file)
>  {
>  	/* use static because iter can be a bit big for the stack */
>  	static struct trace_iterator iter;
> @@ -70,11 +70,11 @@ static void ftrace_dump_buf(int skip_lines, long cpu_file)
>  			kdb_printf("---------------------------------\n");
>  		cnt++;
>  
> -		if (!skip_lines) {
> +		if (!skip_entries) {
>  			print_trace_line(&iter);
>  			trace_printk_seq(&iter.seq);
>  		} else {
> -			skip_lines--;
> +			skip_entries--;
>  		}
>  
>  		if (KDB_FLAG(CMD_INTERRUPT))
> @@ -106,7 +106,7 @@ static void ftrace_dump_buf(int skip_lines, long cpu_file)
>   */
>  static int kdb_ftdump(int argc, const char **argv)
>  {
> -	int skip_lines = 0;
> +	int skip_entries = 0;
>  	long cpu_file;
>  	char *cp;
>  
> @@ -114,9 +114,9 @@ static int kdb_ftdump(int argc, const char **argv)
>  		return KDB_ARGCOUNT;
>  
>  	if (argc) {
> -		skip_lines = simple_strtol(argv[1], &cp, 0);
> +		skip_entries = simple_strtol(argv[1], &cp, 0);
>  		if (*cp)
> -			skip_lines = 0;
> +			skip_entries = 0;
>  	}
>  
>  	if (argc == 2) {
> @@ -129,7 +129,7 @@ static int kdb_ftdump(int argc, const char **argv)
>  	}
>  
>  	kdb_trap_printk++;
> -	ftrace_dump_buf(skip_lines, cpu_file);
> +	ftrace_dump_buf(skip_entries, cpu_file);
>  	kdb_trap_printk--;
>  
>  	return 0;
> @@ -137,7 +137,7 @@ 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]",
> +	kdb_register_flags("ftdump", kdb_ftdump, "[skip_#entries] [cpu]",
>  			    "Dump ftrace log", 0, KDB_ENABLE_ALWAYS_SAFE);
>  	return 0;
>  }
> -- 
> 2.21.0.360.g471c308f928-goog
> 

Re: [PATCH v4 3/3] tracing: kdb: Allow ftdump to skip all but the last few entries

[Steven Rostedt]

On Mon, 18 Mar 2019 03:02:38 +0000
Daniel Thompson <daniel.thompson@linaro.org> wrote:

> > diff --git a/kernel/trace/trace_kdb.c b/kernel/trace/trace_kdb.c
> > index 4b666643d69f..996e1e9cd9a6 100644
> > --- a/kernel/trace/trace_kdb.c
> > +++ b/kernel/trace/trace_kdb.c
> > @@ -39,7 +39,8 @@ static void ftrace_dump_buf(int skip_entries, 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");
> > +	kdb_printf("Dumping ftrace buffer (skipping %d entries):\n",
> > +		   skip_entries);  
> 
> If someone *doesn't* need to skip any entries I'm not a fan of telling
> them we are "skipping 0 entries"; it is more unnerving than helpful
> ("huh? what does it need to tell me that no entried were skipped?
> what makes the tracer skip entries?... Doh... I get it").

I agree.

Probably best to have this:

	kdb_printf("Dumping ftrace buffer:\n");
	if (skip_entries)
		kdb_printf("(skipping %d entries)\n", skip_entries);

No reason to inject that skipping line in the first line.

-- Steve