diff mbox series

ftrace: Show a list of all functions that have ever been enabled

Message ID 20230124095653.6fd1640e@gandalf.local.home (mailing list archive)
State Accepted
Commit e11b521a7b69c2621bb2e5920bb96f6d2facdc7e
Headers show
Series ftrace: Show a list of all functions that have ever been enabled | expand

Commit Message

Steven Rostedt Jan. 24, 2023, 2:56 p.m. UTC 
From: "Steven Rostedt (Google)" <rostedt@goodmis.org>

When debugging a crash that appears to be related to ftrace, but not for
sure, it is useful to know if a function was ever enabled by ftrace or
not. It could be that a BPF program was attached to it, or possibly a live
patch.

We are having crashes in the field where this information is not always
known. But having ftrace set a flag if a function has ever been attached
since boot up helps tremendously in trying to know if a crash had to do
with something using ftrace.

For analyzing crashes, the use of a kdump image can have access to the
flags. When looking at issues where the kernel did not panic, the
touched_functions file can simply be used.

Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---

[
  This patch will conflict with Mark's patch that is going through the ARM
  tree. I will hold off pulling this patch until the next merge window, and
  rebase it on top of the changes when the tracing tree merges with upstream
  that has the changes from the ARM tree.
]

 include/linux/ftrace.h |  5 ++++-
 kernel/trace/ftrace.c  | 51 +++++++++++++++++++++++++++++++++++++-----
 2 files changed, 50 insertions(+), 6 deletions(-)

Comments

Mark Rutland Jan. 24, 2023, 4:27 p.m. UTC | #1 
On Tue, Jan 24, 2023 at 09:56:53AM -0500, Steven Rostedt wrote:
> From: "Steven Rostedt (Google)" <rostedt@goodmis.org>
> 
> When debugging a crash that appears to be related to ftrace, but not for
> sure, it is useful to know if a function was ever enabled by ftrace or
> not. It could be that a BPF program was attached to it, or possibly a live
> patch.
> 
> We are having crashes in the field where this information is not always
> known. But having ftrace set a flag if a function has ever been attached
> since boot up helps tremendously in trying to know if a crash had to do
> with something using ftrace.
> 
> For analyzing crashes, the use of a kdump image can have access to the
> flags. When looking at issues where the kernel did not panic, the
> touched_functions file can simply be used.
> 
> Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
> ---
> 
> [
>   This patch will conflict with Mark's patch that is going through the ARM
>   tree. I will hold off pulling this patch until the next merge window, and
>   rebase it on top of the changes when the tracing tree merges with upstream
>   that has the changes from the ARM tree.
> ]

Sorry for the conflict!

The patch looks good to me; I just gave it a spin on arm64 (resolving the
conflcit with my changes by moving FTRCE_FL_TOUCHED to bit 20, and
FTRACE_REF_MAX_SHIFT down to 20), and from a naive test that seems happy:

| # cat /sys/kernel/tracing/touched_functions 
| # echo do_el0_svc > /sys/kernel/tracing/set_ftrace_filter 
| # echo function_graph > /sys/kernel/tracing/current_tracer 
| # cat /sys/kernel/tracing/touched_functions 
| do_el0_svc (1)       O  ops: graph_ops+0x0/0xb8 (ftrace_graph_func+0x0/0x58)
| # echo nop > /sys/kernel/tracing/current_tracer 
| # cat /sys/kernel/tracing/touched_functions 
| do_el0_svc (0) 

Thanks,
Mark.

> 
>  include/linux/ftrace.h |  5 ++++-
>  kernel/trace/ftrace.c  | 51 +++++++++++++++++++++++++++++++++++++-----
>  2 files changed, 50 insertions(+), 6 deletions(-)
> 
> diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
> index 99f1146614c0..76baba9bd21b 100644
> --- a/include/linux/ftrace.h
> +++ b/include/linux/ftrace.h
> @@ -563,6 +563,7 @@ bool is_ftrace_trampoline(unsigned long addr);
>   *  IPMODIFY - the record allows for the IP address to be changed.
>   *  DISABLED - the record is not ready to be touched yet
>   *  DIRECT   - there is a direct function to call
> + *  TOUCHED  - A callback was added since boot up
>   *
>   * When a new ftrace_ops is registered and wants a function to save
>   * pt_regs, the rec->flags REGS is set. When the function has been
> @@ -580,9 +581,10 @@ enum {
>  	FTRACE_FL_DISABLED	= (1UL << 25),
>  	FTRACE_FL_DIRECT	= (1UL << 24),
>  	FTRACE_FL_DIRECT_EN	= (1UL << 23),
> +	FTRACE_FL_TOUCHED	= (1UL << 22),
>  };
>  
> -#define FTRACE_REF_MAX_SHIFT	23
> +#define FTRACE_REF_MAX_SHIFT	22
>  #define FTRACE_REF_MAX		((1UL << FTRACE_REF_MAX_SHIFT) - 1)
>  
>  #define ftrace_rec_count(rec)	((rec)->flags & FTRACE_REF_MAX)
> @@ -641,6 +643,7 @@ enum {
>  	FTRACE_ITER_PROBE	= (1 << 4),
>  	FTRACE_ITER_MOD		= (1 << 5),
>  	FTRACE_ITER_ENABLED	= (1 << 6),
> +	FTRACE_ITER_TOUCHED	= (1 << 7),
>  };
>  
>  void arch_ftrace_update_code(int command);
> diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
> index 442438b93fe9..7687f413ab36 100644
> --- a/kernel/trace/ftrace.c
> +++ b/kernel/trace/ftrace.c
> @@ -45,6 +45,9 @@
>  #include "trace_output.h"
>  #include "trace_stat.h"
>  
> +/* Flags that do not get reset */
> +#define FTRACE_NOCLEAR_FLAGS	(FTRACE_FL_DISABLED | FTRACE_FL_TOUCHED)
> +
>  #define FTRACE_INVALID_FUNCTION		"__ftrace_invalid_address__"
>  
>  #define FTRACE_WARN_ON(cond)			\
> @@ -2196,7 +2199,7 @@ static int ftrace_check_record(struct dyn_ftrace *rec, bool enable, bool update)
>  		flag ^= rec->flags & FTRACE_FL_ENABLED;
>  
>  		if (update) {
> -			rec->flags |= FTRACE_FL_ENABLED;
> +			rec->flags |= FTRACE_FL_ENABLED | FTRACE_FL_TOUCHED;
>  			if (flag & FTRACE_FL_REGS) {
>  				if (rec->flags & FTRACE_FL_REGS)
>  					rec->flags |= FTRACE_FL_REGS_EN;
> @@ -2251,7 +2254,7 @@ static int ftrace_check_record(struct dyn_ftrace *rec, bool enable, bool update)
>  	if (update) {
>  		/* If there's no more users, clear all flags */
>  		if (!ftrace_rec_count(rec))
> -			rec->flags &= FTRACE_FL_DISABLED;
> +			rec->flags &= FTRACE_NOCLEAR_FLAGS;
>  		else
>  			/*
>  			 * Just disable the record, but keep the ops TRAMP
> @@ -3067,7 +3070,7 @@ int ftrace_shutdown(struct ftrace_ops *ops, int command)
>  		struct dyn_ftrace *rec;
>  
>  		do_for_each_ftrace_rec(pg, rec) {
> -			if (FTRACE_WARN_ON_ONCE(rec->flags & ~FTRACE_FL_DISABLED))
> +			if (FTRACE_WARN_ON_ONCE(rec->flags & ~FTRACE_NOCLEAR_FLAGS))
>  				pr_warn("  %pS flags:%lx\n",
>  					(void *)rec->ip, rec->flags);
>  		} while_for_each_ftrace_rec();
> @@ -3518,7 +3521,10 @@ t_func_next(struct seq_file *m, loff_t *pos)
>  		     !ftrace_lookup_ip(iter->hash, rec->ip)) ||
>  
>  		    ((iter->flags & FTRACE_ITER_ENABLED) &&
> -		     !(rec->flags & FTRACE_FL_ENABLED))) {
> +		     !(rec->flags & FTRACE_FL_ENABLED)) ||
> +
> +		    ((iter->flags & FTRACE_ITER_TOUCHED) &&
> +		     !(rec->flags & FTRACE_FL_TOUCHED))) {
>  
>  			rec = NULL;
>  			goto retry;
> @@ -3777,7 +3783,7 @@ static int t_show(struct seq_file *m, void *v)
>  		return 0;
>  	}
>  
> -	if (iter->flags & FTRACE_ITER_ENABLED) {
> +	if (iter->flags & (FTRACE_ITER_ENABLED | FTRACE_ITER_TOUCHED)) {
>  		struct ftrace_ops *ops;
>  
>  		seq_printf(m, " (%ld)%s%s%s",
> @@ -3869,6 +3875,31 @@ ftrace_enabled_open(struct inode *inode, struct file *file)
>  	return 0;
>  }
>  
> +static int
> +ftrace_touched_open(struct inode *inode, struct file *file)
> +{
> +	struct ftrace_iterator *iter;
> +
> +	/*
> +	 * This shows us what functions have ever been enabled
> +	 * (traced, direct, patched, etc). Not sure if we want lockdown
> +	 * to hide such critical information for an admin.
> +	 * Although, perhaps it can show information we don't
> +	 * want people to see, but if something had traced
> +	 * something, we probably want to know about it.
> +	 */
> +
> +	iter = __seq_open_private(file, &show_ftrace_seq_ops, sizeof(*iter));
> +	if (!iter)
> +		return -ENOMEM;
> +
> +	iter->pg = ftrace_pages_start;
> +	iter->flags = FTRACE_ITER_TOUCHED;
> +	iter->ops = &global_ops;
> +
> +	return 0;
> +}
> +
>  /**
>   * ftrace_regex_open - initialize function tracer filter files
>   * @ops: The ftrace_ops that hold the hash filters
> @@ -6137,6 +6168,13 @@ static const struct file_operations ftrace_enabled_fops = {
>  	.release = seq_release_private,
>  };
>  
> +static const struct file_operations ftrace_touched_fops = {
> +	.open = ftrace_touched_open,
> +	.read = seq_read,
> +	.llseek = seq_lseek,
> +	.release = seq_release_private,
> +};
> +
>  static const struct file_operations ftrace_filter_fops = {
>  	.open = ftrace_filter_open,
>  	.read = seq_read,
> @@ -6601,6 +6639,9 @@ static __init int ftrace_init_dyn_tracefs(struct dentry *d_tracer)
>  	trace_create_file("enabled_functions", TRACE_MODE_READ,
>  			d_tracer, NULL, &ftrace_enabled_fops);
>  
> +	trace_create_file("touched_functions", TRACE_MODE_READ,
> +			d_tracer, NULL, &ftrace_touched_fops);
> +
>  	ftrace_create_filter_files(&global_ops, d_tracer);
>  
>  #ifdef CONFIG_FUNCTION_GRAPH_TRACER
> -- 
> 2.39.0
>
Steven Rostedt Jan. 24, 2023, 7:06 p.m. UTC | #2 
On Tue, 24 Jan 2023 16:27:23 +0000
Mark Rutland <mark.rutland@arm.com> wrote:

> > [
> >   This patch will conflict with Mark's patch that is going through the ARM
> >   tree. I will hold off pulling this patch until the next merge window, and
> >   rebase it on top of the changes when the tracing tree merges with upstream
> >   that has the changes from the ARM tree.
> > ]  
> 
> Sorry for the conflict!

No problem. This was more to help us debug something, and we are currently
just backporting it for now to our kernels in order to help with the
crashes we are seeing. No rush to get it upstream. But I figured that if it
can help us, it can also help others.

> 
> The patch looks good to me; I just gave it a spin on arm64 (resolving the
> conflcit with my changes by moving FTRCE_FL_TOUCHED to bit 20, and
> FTRACE_REF_MAX_SHIFT down to 20), and from a naive test that seems happy:
> 
> | # cat /sys/kernel/tracing/touched_functions 
> | # echo do_el0_svc > /sys/kernel/tracing/set_ftrace_filter 
> | # echo function_graph > /sys/kernel/tracing/current_tracer 
> | # cat /sys/kernel/tracing/touched_functions 
> | do_el0_svc (1)       O  ops: graph_ops+0x0/0xb8 (ftrace_graph_func+0x0/0x58)
> | # echo nop > /sys/kernel/tracing/current_tracer 
> | # cat /sys/kernel/tracing/touched_functions 
> | do_el0_svc (0) 

Thanks for testing! I guess I can add a "tested-by" from you?

-- Steve
Mark Rutland Jan. 25, 2023, 9:29 a.m. UTC | #3 
On Tue, Jan 24, 2023 at 02:06:17PM -0500, Steven Rostedt wrote:
> On Tue, 24 Jan 2023 16:27:23 +0000
> Mark Rutland <mark.rutland@arm.com> wrote:
> 
> > > [
> > >   This patch will conflict with Mark's patch that is going through the ARM
> > >   tree. I will hold off pulling this patch until the next merge window, and
> > >   rebase it on top of the changes when the tracing tree merges with upstream
> > >   that has the changes from the ARM tree.
> > > ]  
> > 
> > Sorry for the conflict!
> 
> No problem. This was more to help us debug something, and we are currently
> just backporting it for now to our kernels in order to help with the
> crashes we are seeing. No rush to get it upstream. But I figured that if it
> can help us, it can also help others.

Indeed!

> > The patch looks good to me; I just gave it a spin on arm64 (resolving the
> > conflcit with my changes by moving FTRCE_FL_TOUCHED to bit 20, and
> > FTRACE_REF_MAX_SHIFT down to 20), and from a naive test that seems happy:
> > 
> > | # cat /sys/kernel/tracing/touched_functions 
> > | # echo do_el0_svc > /sys/kernel/tracing/set_ftrace_filter 
> > | # echo function_graph > /sys/kernel/tracing/current_tracer 
> > | # cat /sys/kernel/tracing/touched_functions 
> > | do_el0_svc (1)       O  ops: graph_ops+0x0/0xb8 (ftrace_graph_func+0x0/0x58)
> > | # echo nop > /sys/kernel/tracing/current_tracer 
> > | # cat /sys/kernel/tracing/touched_functions 
> > | do_el0_svc (0) 
> 
> Thanks for testing! I guess I can add a "tested-by" from you?

Yes, please feel free to add:

Tested-by: Mark Rutland <mark.rutland@arm.com>

... and I'm happy to test the rebased version once this marge window as
settled.

Thanks,
Mark.
Chris Li Jan. 25, 2023, 10:53 p.m. UTC | #4 
On Tue, Jan 24, 2023 at 11:06 AM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> No problem. This was more to help us debug something, and we are currently
> just backporting it for now to our kernels in order to help with the
> crashes we are seeing. No rush to get it upstream. But I figured that if it
> can help us, it can also help others.

I just tested it against the tip of the kernel git repo. Works fine for me.
Feel free to add:

Tested-by: Chris Li <chriscli@google.com>

Chris
diff mbox series

Patch

diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index 99f1146614c0..76baba9bd21b 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -563,6 +563,7 @@  bool is_ftrace_trampoline(unsigned long addr);
  *  IPMODIFY - the record allows for the IP address to be changed.
  *  DISABLED - the record is not ready to be touched yet
  *  DIRECT   - there is a direct function to call
+ *  TOUCHED  - A callback was added since boot up
  *
  * When a new ftrace_ops is registered and wants a function to save
  * pt_regs, the rec->flags REGS is set. When the function has been
@@ -580,9 +581,10 @@  enum {
 	FTRACE_FL_DISABLED	= (1UL << 25),
 	FTRACE_FL_DIRECT	= (1UL << 24),
 	FTRACE_FL_DIRECT_EN	= (1UL << 23),
+	FTRACE_FL_TOUCHED	= (1UL << 22),
 };
 
-#define FTRACE_REF_MAX_SHIFT	23
+#define FTRACE_REF_MAX_SHIFT	22
 #define FTRACE_REF_MAX		((1UL << FTRACE_REF_MAX_SHIFT) - 1)
 
 #define ftrace_rec_count(rec)	((rec)->flags & FTRACE_REF_MAX)
@@ -641,6 +643,7 @@  enum {
 	FTRACE_ITER_PROBE	= (1 << 4),
 	FTRACE_ITER_MOD		= (1 << 5),
 	FTRACE_ITER_ENABLED	= (1 << 6),
+	FTRACE_ITER_TOUCHED	= (1 << 7),
 };
 
 void arch_ftrace_update_code(int command);
diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index 442438b93fe9..7687f413ab36 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -45,6 +45,9 @@ 
 #include "trace_output.h"
 #include "trace_stat.h"
 
+/* Flags that do not get reset */
+#define FTRACE_NOCLEAR_FLAGS	(FTRACE_FL_DISABLED | FTRACE_FL_TOUCHED)
+
 #define FTRACE_INVALID_FUNCTION		"__ftrace_invalid_address__"
 
 #define FTRACE_WARN_ON(cond)			\
@@ -2196,7 +2199,7 @@  static int ftrace_check_record(struct dyn_ftrace *rec, bool enable, bool update)
 		flag ^= rec->flags & FTRACE_FL_ENABLED;
 
 		if (update) {
-			rec->flags |= FTRACE_FL_ENABLED;
+			rec->flags |= FTRACE_FL_ENABLED | FTRACE_FL_TOUCHED;
 			if (flag & FTRACE_FL_REGS) {
 				if (rec->flags & FTRACE_FL_REGS)
 					rec->flags |= FTRACE_FL_REGS_EN;
@@ -2251,7 +2254,7 @@  static int ftrace_check_record(struct dyn_ftrace *rec, bool enable, bool update)
 	if (update) {
 		/* If there's no more users, clear all flags */
 		if (!ftrace_rec_count(rec))
-			rec->flags &= FTRACE_FL_DISABLED;
+			rec->flags &= FTRACE_NOCLEAR_FLAGS;
 		else
 			/*
 			 * Just disable the record, but keep the ops TRAMP
@@ -3067,7 +3070,7 @@  int ftrace_shutdown(struct ftrace_ops *ops, int command)
 		struct dyn_ftrace *rec;
 
 		do_for_each_ftrace_rec(pg, rec) {
-			if (FTRACE_WARN_ON_ONCE(rec->flags & ~FTRACE_FL_DISABLED))
+			if (FTRACE_WARN_ON_ONCE(rec->flags & ~FTRACE_NOCLEAR_FLAGS))
 				pr_warn("  %pS flags:%lx\n",
 					(void *)rec->ip, rec->flags);
 		} while_for_each_ftrace_rec();
@@ -3518,7 +3521,10 @@  t_func_next(struct seq_file *m, loff_t *pos)
 		     !ftrace_lookup_ip(iter->hash, rec->ip)) ||
 
 		    ((iter->flags & FTRACE_ITER_ENABLED) &&
-		     !(rec->flags & FTRACE_FL_ENABLED))) {
+		     !(rec->flags & FTRACE_FL_ENABLED)) ||
+
+		    ((iter->flags & FTRACE_ITER_TOUCHED) &&
+		     !(rec->flags & FTRACE_FL_TOUCHED))) {
 
 			rec = NULL;
 			goto retry;
@@ -3777,7 +3783,7 @@  static int t_show(struct seq_file *m, void *v)
 		return 0;
 	}
 
-	if (iter->flags & FTRACE_ITER_ENABLED) {
+	if (iter->flags & (FTRACE_ITER_ENABLED | FTRACE_ITER_TOUCHED)) {
 		struct ftrace_ops *ops;
 
 		seq_printf(m, " (%ld)%s%s%s",
@@ -3869,6 +3875,31 @@  ftrace_enabled_open(struct inode *inode, struct file *file)
 	return 0;
 }
 
+static int
+ftrace_touched_open(struct inode *inode, struct file *file)
+{
+	struct ftrace_iterator *iter;
+
+	/*
+	 * This shows us what functions have ever been enabled
+	 * (traced, direct, patched, etc). Not sure if we want lockdown
+	 * to hide such critical information for an admin.
+	 * Although, perhaps it can show information we don't
+	 * want people to see, but if something had traced
+	 * something, we probably want to know about it.
+	 */
+
+	iter = __seq_open_private(file, &show_ftrace_seq_ops, sizeof(*iter));
+	if (!iter)
+		return -ENOMEM;
+
+	iter->pg = ftrace_pages_start;
+	iter->flags = FTRACE_ITER_TOUCHED;
+	iter->ops = &global_ops;
+
+	return 0;
+}
+
 /**
  * ftrace_regex_open - initialize function tracer filter files
  * @ops: The ftrace_ops that hold the hash filters
@@ -6137,6 +6168,13 @@  static const struct file_operations ftrace_enabled_fops = {
 	.release = seq_release_private,
 };
 
+static const struct file_operations ftrace_touched_fops = {
+	.open = ftrace_touched_open,
+	.read = seq_read,
+	.llseek = seq_lseek,
+	.release = seq_release_private,
+};
+
 static const struct file_operations ftrace_filter_fops = {
 	.open = ftrace_filter_open,
 	.read = seq_read,
@@ -6601,6 +6639,9 @@  static __init int ftrace_init_dyn_tracefs(struct dentry *d_tracer)
 	trace_create_file("enabled_functions", TRACE_MODE_READ,
 			d_tracer, NULL, &ftrace_enabled_fops);
 
+	trace_create_file("touched_functions", TRACE_MODE_READ,
+			d_tracer, NULL, &ftrace_touched_fops);
+
 	ftrace_create_filter_files(&global_ops, d_tracer);
 
 #ifdef CONFIG_FUNCTION_GRAPH_TRACER