ftrace: Fixes for 6.13

Ftrace fixes for 6.13:

- Fix output of trace when hashing a pointer is disabled

Pointers are recorded into the ring buffer by simply copying them. When the ring buffer is read directly in binary format, the pointers are unhashed, and tools like perf will show them as such. But when the pointers are printed from the trace file, they are hashed because the output from the trace uses vsnprintf() which will hash "%p". Since the tracing infrastructure requires just as much privileged as kallsyms this was an unneeded protection. An option was created to allow the pointers to not be hashed, as in some cases in debugging, the unhashed pointer was required.

To do this, the unhashing would add a "x" after a "%p" to make it "%px" and not hash. It used the iter->fmt temp buffer to accomplish this. The problem was that the iter->fmt temp buffer was already being used as a temp buffer to check if pointers in the event format output were being called indirectly (like using a "%pI4 or %pI6) where the pointer may be pointing to a freed location. The check code will catch that.

The issue was that when the hash pointer was being disabled, that logic that used the temporary iter->fmt buffer passed that buffer to the function that would test bad pointers and that function would use iter->fmt buffer as well, causing the output to be screwed up.

The solution was to change the bad pointer logic to use the iter->fmt buffer directly and not as a temp buffer. If the fmt parameter passed in was not the iter->fmt buffer, it would copy the content to the iter->fmt buffer and process that buffer directly. This now allows passing the iter->fmt buffer as the fmt parameter to the bad pointer check function.

- Always try to initialize the idle functions when graph tracer starts

A bug was found that when a CPU is offline when graph tracing starts and then comes online, that CPU is not traced. The fix to that was to move the initialization of the idle shadow stack over to the hot plug online logic, which also handle onlined CPUs. The issue was that it removed the initialization of the shadow stack when graph tracing starts, but the callbacks to the hot plug logic do nothing if graph tracing isn't currently running. Although that fix fixed the onlining of a CPU during tracing, it broke the CPUs that were already online.

- Have microblaze not try to get the "true parent" in function tracing

If function tracing and graph tracing are both enabled at the same time the parent of the functions traced by the function tracer may sometimes be the graph tracing trampoline. The graph tracing hijacks the return pointer of the function to trace it, but that can interfere with the function tracing parent output. This was fixed by using the ftrace_graph_ret_addr() function passing in the kernel stack pointer using the ftrace_regs_get_stack_pointer() function. But Al Viro reported that Microblaze does not implement the kernel_stack_pointer(regs) helper function that ftrace_regs_get_stack_pointer() uses and fails to compile when function graph tracing is enabled.

The real fix would be to have microblaze implement the kernel_stack_pointer() function, but they haven't responded to emails. For now, just make microblaze use the old logic which prints the function graph trampoline in the function tracer.

git://git.kernel.org/pub/scm/linux/kernel/git/trace/linux-trace.git
ftrace/fixes

Head SHA1: 617bbefc102f266b23beac72185a2b0e13aa378d

Steven Rostedt (3):
tracing: Fix trace output when pointer hash is disabled
fgraph: Still initialize idle shadow stacks when starting ftrace/microblaze: Do not find "true_parent" for return address

----

 kernel/trace/fgraph.c          |  8 +++-
 kernel/trace/trace.c           | 90 ++++++++++++++++++++++++++----------------
 kernel/trace/trace_functions.c |  3 +-
 3 files changed, 64 insertions(+), 37 deletions(-)

From: Steven Rostedt <[email protected]>

The "%p" in the trace output is by default hashes the pointer. An option was added to disable the hashing as reading trace output is a privileged operation (just like reading kallsyms). When hashing is disabled, the iter->fmt temp buffer is used to add "x" to "%p" into "%px" before sending to the svnprintf() functions.

The problem with using iter->fmt, is that the trace_check_vprintf() that makes sure that trace events "%pX" pointers are not dereferencing freed addresses (and prints a warning if it does) also uses the iter->fmt to save to and use to print out for the trace file. When the hash_ptr option is disabled, the "%px" version is added to the iter->fmt buffer, and that then is passed to the trace_check_vprintf() function that then uses the iter->fmt as a temp buffer. Obviously this caused bad results.

This was noticed when backporting the persistent ring buffer to 5.10 and added this code without the option being disabled by default, so it failed one of the selftests because the sched_wakeup was missing the "comm" field:

     cat-907     [006] dN.4.   249.722403: sched_wakeup: comm= pid=74 prio=120 target_cpu=006

Instead of showing:

<idle>-0 [004] dNs6. 49.076464: sched_wakeup: comm=sshd-session pid=896 prio=120 target_cpu=0040

To fix this, change trace_check_vprintf() to modify the iter->fmt instead of copying to it. If the fmt passed in is not the iter->fmt, first copy the entire fmt string to iter->fmt and then iterate the iter->fmt. When the format needs to be processed, perform the following like actions:

  save_ch = p[i];
  p[i] = '\0';
  trace_seq_printf(&iter->seq, p, str);
  p[i] = save_ch;

---
 kernel/trace/trace.c | 90 +++++++++++++++++++++++++++-----------------
 1 file changed, 55 insertions(+), 35 deletions(-)

index be62f0ea1814..b44b1cdaa20e 100644
@@ -3711,8 +3711,10 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
 {
 	long text_delta = 0;
 	long data_delta = 0;
-	const char *p = fmt;
 	const char *str;
+	char save_ch;
+	char *buf = NULL;
+	char *p;
 	bool good;
 	int i, j;
 

@@ -3720,7 +3722,7 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
 		return;
 
 	if (static_branch_unlikely(&trace_no_verify))
-		goto print;
+		goto print_fmt;
 
 	/*
 	 * When the kernel is booted with the tp_printk command line

@@ -3735,8 +3737,21 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
 
 	/* Don't bother checking when doing a ftrace_dump() */
 	if (iter->fmt == static_fmt_buf)
-		goto print;
+		goto print_fmt;
 
+	if (fmt != iter->fmt) {
+		int len = strlen(fmt);
+		while (iter->fmt_size < len + 1) {
+			/*
+			 * If we can't expand the copy buffer,
+			 * just print it.
+			 */
+			if (!trace_iter_expand_format(iter))
+				goto print_fmt;
+		}
+		strscpy(iter->fmt, fmt, iter->fmt_size);
+	}
+	p = iter->fmt;
 	while (*p) {
 		bool star = false;
 		int len = 0;

@@ -3748,14 +3763,6 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
 		 * as well as %p[sS] if delta is non-zero
 		 */
 		for (i = 0; p[i]; i++) {
-			if (i + 1 >= iter->fmt_size) {
-				/*
-				 * If we can't expand the copy buffer,
-				 * just print it.
-				 */
-				if (!trace_iter_expand_format(iter))
-					goto print;
-			}
 
 			if (p[i] == '\\' && p[i+1]) {
 				i++;

@@ -3788,10 +3795,11 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
 		if (!p[i])
 			break;
 
-		/* Copy up to the %s, and print that */
-		strncpy(iter->fmt, p, i);
-		iter->fmt[i] = '\0';
-		trace_seq_vprintf(&iter->seq, iter->fmt, ap);
+		/* Print up to the %s */
+		save_ch = p[i];
+		p[i] = '\0';
+		trace_seq_vprintf(&iter->seq, p, ap);
+		p[i] = save_ch;
 
 		/* Add delta to %pS pointers */
 		if (p[i+1] == 'p') {

@@ -3837,6 +3845,8 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
 			good = trace_safe_str(iter, str, star, len);
 		}
 
+		p += i;
+
 		/*
 		 * If you hit this warning, it is likely that the
 		 * trace event in question used %s on a string that

@@ -3849,41 +3859,51 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
 		if (WARN_ONCE(!good, "fmt: '%s' current_buffer: '%s'",
 			      fmt, seq_buf_str(&iter->seq.seq))) {
 			int ret;
+#define TEMP_BUFSIZ 1024
+
+			if (!buf) {
+				char *buf = kmalloc(TEMP_BUFSIZ, GFP_KERNEL);
+				if (!buf) {
+					/* Need buffer to read address */
+					trace_seq_printf(&iter->seq, "(0x%px)[UNSAFE-MEMORY]", str);
+					p += j + 1;
+					goto print;
+				}
+			}
+			if (len >= TEMP_BUFSIZ)
+				len = TEMP_BUFSIZ - 1;
 
 			/* Try to safely read the string */
 			if (star) {
-				if (len + 1 > iter->fmt_size)
-					len = iter->fmt_size - 1;
-				if (len < 0)
-					len = 0;
-				ret = copy_from_kernel_nofault(iter->fmt, str, len);
-				iter->fmt[len] = 0;
-				star = false;
+				ret = copy_from_kernel_nofault(buf, str, len);
+				buf[len] = 0;
 			} else {
-				ret = strncpy_from_kernel_nofault(iter->fmt, str,
-								  iter->fmt_size);
+				ret = strncpy_from_kernel_nofault(buf, str, TEMP_BUFSIZ);
 			}
 			if (ret < 0)
 				trace_seq_printf(&iter->seq, "(0x%px)", str);
 			else
-				trace_seq_printf(&iter->seq, "(0x%px:%s)",
-						 str, iter->fmt);
-			str = "[UNSAFE-MEMORY]";
-			strcpy(iter->fmt, "%s");
+				trace_seq_printf(&iter->seq, "(0x%px:%s)", str, buf);
+			trace_seq_puts(&iter->seq, "[UNSAFE-MEMORY]");
 		} else {
-			strncpy(iter->fmt, p + i, j + 1);
-			iter->fmt[j+1] = '\0';
+			save_ch = p[j + 1];
+			p[j + 1] = '\0';
+			if (star)
+				trace_seq_printf(&iter->seq, p, len, str);
+			else
+				trace_seq_printf(&iter->seq, p, str);
+			p[j + 1] = save_ch;
 		}
-		if (star)
-			trace_seq_printf(&iter->seq, iter->fmt, len, str);
-		else
-			trace_seq_printf(&iter->seq, iter->fmt, str);
 
-		p += i + j + 1;
+		p += j + 1;
 	}
  print:
 	if (*p)
 		trace_seq_vprintf(&iter->seq, p, ap);
+	kfree(buf);
+	return;
+ print_fmt:
+	trace_seq_vprintf(&iter->seq, fmt, ap);
 }
 
 const char *trace_event_format(struct trace_iterator *iter, const char *fmt)

2.45.2

From: Steven Rostedt <[email protected]>

A bug was discovered where the idle shadow stacks were not initialized for offline CPUs when starting function graph tracer, and when they came online they were not traced due to the missing shadow stack. To fix this, the idle task shadow stack initialization was moved to using the CPU hotplug callbacks. But it removed the initialization when the function graph was enabled. The problem here is that the hotplug callbacks are called when the CPUs come online, but the idle shadow stack initialization only happens if function graph is currently active. This caused the online CPUs to not get their shadow stack initialized.

The idle shadow stack initialization still needs to be done when the function graph is registered, as they will not be allocated if function graph is not registered.

---
 kernel/trace/fgraph.c | 8 +++++++-
 1 file changed, 7 insertions(+), 1 deletion(-)

index 0bf78517b5d4..ddedcb50917f 100644
@@ -1215,7 +1215,7 @@ void fgraph_update_pid_func(void)
 static int start_graph_tracing(void)
 {
 	unsigned long **ret_stack_list;
-	int ret;
+	int ret, cpu;
 
 	ret_stack_list = kcalloc(FTRACE_RETSTACK_ALLOC_SIZE,
 				 sizeof(*ret_stack_list), GFP_KERNEL);

@@ -1223,6 +1223,12 @@ static int start_graph_tracing(void)
 	if (!ret_stack_list)
 		return -ENOMEM;
 
+	/* The cpu_boot init_task->ret_stack will never be freed */
+	for_each_online_cpu(cpu) {
+		if (!idle_task(cpu)->ret_stack)
+			ftrace_graph_init_idle_task(idle_task(cpu), cpu);
+	}
+
 	do {
 		ret = alloc_retstack_tasklist(ret_stack_list);
 	} while (ret == -EAGAIN);

2.45.2

From: Steven Rostedt <[email protected]>

When function tracing and function graph tracing are both enabled (in different instances) the "parent" of some of the function tracing events is "return_to_handler" which is the trampoline used by function graph tracing. To fix this, ftrace_get_true_parent_ip() was introduced that returns the "true" parent ip instead of the trampoline.

To do this, the ftrace_regs_get_stack_pointer() is used, which uses kernel_stack_pointer(). The problem is that microblaze does not implement kerenl_stack_pointer() so when function graph tracing is enabled, the build fails.

Modify the #ifdef check to the code around ftrace_get_true_parent_ip() to include !defined(CONFIG_MICROBLAZE) which will default it to just return the parent ip passed in, which may still be the ip of the function garph trampoline.

---
 kernel/trace/trace_functions.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

index 74c353164ca1..a75d107a45f8 100644
@@ -176,7 +176,8 @@ static void function_trace_start(struct trace_array *tr)
 	tracing_reset_online_cpus(&tr->array_buffer);
 }
 
-#ifdef CONFIG_FUNCTION_GRAPH_TRACER
+/* Microblaze currently doesn't implement kernel_stack_pointer() */
+#if defined(CONFIG_FUNCTION_GRAPH_TRACER) && !defined(CONFIG_MICROBLAZE)
 static __always_inline unsigned long
 function_get_true_parent_ip(unsigned long parent_ip, struct ftrace_regs *fregs)
 {

2.45.2

What does this mean different instances? Two processes or two cores?

the "parent" of some of the function tracing events

here is typo.

Michal Simek, Ing. (M.Eng), OpenPGP -> KeyID: FE3D1F91
w: www.monstr.eu p: +42-0-721842854
Maintainer of Linux kernel - Xilinx Microblaze
Maintainer of Linux kernel - Xilinx Zynq ARM and ZynqMP/Versal ARM64 SoCs
U-Boot custodian - Xilinx Microblaze/Zynq/ZynqMP/Versal/Versal NET SoCs
TF-A maintainer - Xilinx ZynqMP/Versal/Versal NET SoCs

Trace instances:

 # mkdir /sys/kernel/tracing/instances/foo
 # echo function > /sys/kernel/tracing/instances/foo/current_tracer

 # mkdir /sys/kernel/tracing/instances/bar
 # echo function_graph > /sys/kernel/tracing/instances/bar/current_tracer

Oops, thanks!

Hmm, I was looking for a more generic option and didn't find one. I don't think I looked well enough as that could be what we want. Let me check.

I'll drop this patch for now then.

Thanks for the review,

-- Steve

Nope. ARCH_HAS_CURRENT_STACK_POINTER == "there's a current_stack_pointer variable" (presumably something like register unsigned long current_stack_pointer asm("r1"); in case of microblaze). kernel_stack_pointer() is "here's pt_regs, give me the kernel stack pointer stored in it (assuming it _is_ stored there)".

And what ftrace code really want is "here's the structure formed by _mcount(); give me the kernel stack pointer at the time of _mcount() entry". _IF_ that structure is pt_regs (fairly common) and if there's kernel_stack_pointer(), we get the default implementation of that helper in linux/ftrace_regs.h:

#define ftrace_regs_get_stack_pointer(fregs) \
        kernel_stack_pointer(&arch_ftrace_regs(fregs)->regs)

If it's not pt_regs, you are expected to define HAVE_ARCH_FTRACE_REGS, define struct __arch_ftrace_regs to match whatever layout you are using and provide the set of ftrace_regs_...() helpers.

From my reading of your mcount.S, the layout is, indeed, different and r1 is not stored there at all - something like

struct __arch_ftrace_regs {
	unsigned long r2, r3, r4, r6;
	unsigned long r7, r8, r9, r10;
	unsigned long r11, r12, r13, r14;
	unsigned long r16, r17, r18, r19;
	unsigned long r20, r21, r22, r23;
	unsigned long r24, r25, r26, r27;
	unsigned long r28, r29, r30, r31;
	unsigned long r5;
}

static inline unsigned long ftrace_regs_get_stack_pointer(struct ftrace_regs *regs)

{
	return (unsigned long)regs + sizeof(struct __arch_ftrace_regs) + 4;
}

OK, so this is still unique for Microblaze. I'll keep the patch, but fix the typo in the change log.

Michal,

Any objections?

-- Steve