Skip to contentSkip to conversation

tracing: Last minute updates before pushing to Linus

PATCH New Steven Rostedt 1 participant 19 messages Apr 6, 2018

Subsystems (7)
lore
Share & tools
lore

Steven Rostedt

author maintainer
#0 lore raw

cover tracing: Last minute updates before pushing to Linus

git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
for-next

Head SHA1: 8ec8405f081e1e0f800b20f683451c37e81e26c1

Chris Wilson (3):
tracing: Default to using trace_global_clock if sched_clock is unstable
tracing: Mention trace_clock=global when warning about unstable clocks
tracing: Fixup logic inversion on setting trace_global_clock defaults

Dan Carpenter (2):
tracing: Fix a potential NULL dereference
tracing: Uninitialized variable in create_tracing_map_fields()

Salvatore Mesoraca (1):
ftrace: Drop a VLA in module_exists()

Steven Rostedt (VMware) (8):
init: Fix initcall0 name as it is "pure" not "early"
vsprintf: Do not preprocess non-dereferenced pointers for bprintf (%px and %pK)
lockdep: Add print_irqtrace_events() to __warn
ring-buffer: Check if memory is available before allocation
ring-buffer: Add set/clear_current_oom_origin() during allocations
tracing: Hide global trace clock from lockdep
tracing: Add rcu dereference annotation for filter->prog
tracing: Add rcu dereference annotation for test func that touches filter->prog

Tom Zanussi (4):
tracing: Fix display of hist trigger expressions containing timestamps
tracing: Don't add flag strings when displaying variable references
tracing: Add action comparisons when testing matching hist triggers
tracing: Make sure variable string fields are NULL-terminated

----

 init/main.c                        |  2 +-
 kernel/panic.c                     |  2 +
 kernel/trace/ftrace.c              |  7 ++--
 kernel/trace/ring_buffer.c         | 54 +++++++++++++++++++++-----
 kernel/trace/trace.c               | 19 ++++++++++
 kernel/trace/trace_clock.c         |  4 +-
 kernel/trace/trace_events_filter.c | 10 ++++-
 kernel/trace/trace_events_hist.c   | 78 +++++++++++++++++++++++++++++---------
 lib/vsprintf.c                     |  4 ++
 9 files changed, 143 insertions(+), 37 deletions(-)
author maintainer
#1 lore raw

PATCH 1/18 tracing: Fix a potential NULL dereference

From: Dan Carpenter <[email protected]>

We forgot to set the error code on this path so we return ERR_PTR(0) which is NULL. It results in a NULL dereference in the caller.

Fixes 100719dcef44 ("tracing: Add simple expression support to hist triggers")
---
 kernel/trace/trace_events_hist.c | 1 +
 1 file changed, 1 insertion(+)
kernel/trace/trace_events_hist.c +1 -0
index 4f027642ceef..a02bc09d765a 100644
@@ -2776,6 +2776,7 @@ static struct hist_field *parse_expr(struct hist_trigger_data *hist_data,
 		expr->fn = hist_field_plus;
 		break;
 	default:
+		ret = -EINVAL;
 		goto free;
 	}
 
Signature · 1 line
2.15.1
author maintainer
#2 lore raw

PATCH 2/18 init: Fix initcall0 name as it is "pure" not "early"

In reply to Steven Rostedt

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

The early_initcall() functions get assigned to __initcall_start[]. These are called by do_pre_smp_initcalls(). The initcall_levels[] array starts with __initcall0_start[], and initcall_levels[] are to match the initcall_level_names[] array. The first name in that array is "early", but that is not correct. As pure_initcall() functions get assigned to __initcall0_start[] array.

Change the first name in initcall_level_names[] array to "pure".

---
 init/main.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)
init/main.c +1 -1
index 969eaf140ef0..0ebdd5f15be8 100644
@@ -874,7 +874,7 @@ static initcall_t *initcall_levels[] __initdata = {
 
 /* Keep these in sync with initcalls in include/linux/init.h */
 static char *initcall_level_names[] __initdata = {
-	"early",
+	"pure",
 	"core",
 	"postcore",
 	"arch",
Signature · 1 line
2.15.1
author maintainer
#3 lore raw

PATCH 3/18 tracing: Default to using trace_global_clock if sched_clock is unstable

In reply to Steven Rostedt

From: Chris Wilson <[email protected]>

Across suspend, we may see a very large drift in timestamps if the sched clock is unstable, prompting the global trace's ringbuffer code to warn and suggest switching to the global clock. Preempt this request by detecting when the sched clock is unstable (determined during late_initcall) and automatically switching the default clock over to trace_global_clock.

This should prevent requiring user interaction to resolve warnings such as:

Delta way too big! 18446743856563626466 ts=18446744054496180323 write stamp = 197932553857 If you just came from a suspend/resume,
please switch to the trace global clock:
echo global > /sys/kernel/debug/tracing/trace_clock

---
 kernel/trace/trace.c | 19 +++++++++++++++++++
 1 file changed, 19 insertions(+)
kernel/trace/trace.c +19 -0
index 551a7cd0d705..0f47e653ffd8 100644
@@ -41,6 +41,7 @@
 #include <linux/nmi.h>
 #include <linux/fs.h>
 #include <linux/trace.h>
+#include <linux/sched/clock.h>
 #include <linux/sched/rt.h>
 
 #include "trace.h"
@@ -8596,3 +8597,21 @@ __init static int clear_boot_tracer(void)
 
 fs_initcall(tracer_init_tracefs);
 late_initcall_sync(clear_boot_tracer);
+
+#ifdef CONFIG_HAVE_UNSTABLE_SCHED_CLOCK
+__init static int tracing_set_default_clock(void)
+{
+	/* sched_clock_stable() is determined in late_initcall */
+	if (trace_boot_clock || sched_clock_stable()) {
+		printk(KERN_WARNING
+		       "Unstable clock detected, switching default tracing clock to \"global\"\n"
+		       "If you want to keep using the local clock, then add:\n"
+		       "  \"trace_clock=local\"\n"
+		       "on the kernel command line\n");
+		tracing_set_clock(&global_trace, "global");
+	}
+
+	return 0;
+}
+late_initcall_sync(tracing_set_default_clock);
+#endif
Signature · 1 line
2.15.1
author maintainer
#4 lore raw

PATCH 4/18 tracing: Mention trace_clock=global when warning about unstable clocks

In reply to Steven Rostedt

From: Chris Wilson <[email protected]>

Mention the alternative of adding trace_clock=global to the kernel command line when we detect that we've used an unstable clock across a suspend/resume cycle.

---
 kernel/trace/ring_buffer.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)
kernel/trace/ring_buffer.c +2 -1
index a2fd3893cc02..515be03e3009 100644
@@ -2731,7 +2731,8 @@ rb_handle_timestamp(struct ring_buffer_per_cpu *cpu_buffer,
 		  sched_clock_stable() ? "" :
 		  "If you just came from a suspend/resume,\n"
 		  "please switch to the trace global clock:\n"
-		  "  echo global > /sys/kernel/debug/tracing/trace_clock\n");
+		  "  echo global > /sys/kernel/debug/tracing/trace_clock\n"
+		  "or add trace_clock=global to the kernel command line\n");
 	info->add_timestamp = 1;
 }
 
Signature · 1 line
2.15.1
author maintainer
#5 lore raw

PATCH 5/18 ftrace: Drop a VLA in module_exists()

In reply to Steven Rostedt

From: Salvatore Mesoraca <[email protected]>

Avoid a VLA by using a real constant expression instead of a variable. The compiler should be able to optimize the original code and avoid using an actual VLA. Anyway this change is useful because it will avoid a false positive with -Wvla, it might also help the compiler generating better code.

---
 kernel/trace/ftrace.c | 7 +++----
 1 file changed, 3 insertions(+), 4 deletions(-)
kernel/trace/ftrace.c +3 -4
index eac9ce2c57a2..16bbf062018f 100644
@@ -3902,14 +3902,13 @@ static bool module_exists(const char *module)
 {
 	/* All modules have the symbol __this_module */
 	const char this_mod[] = "__this_module";
-	const int modname_size = MAX_PARAM_PREFIX_LEN + sizeof(this_mod) + 1;
-	char modname[modname_size + 1];
+	char modname[MAX_PARAM_PREFIX_LEN + sizeof(this_mod) + 2];
 	unsigned long val;
 	int n;
 
-	n = snprintf(modname, modname_size + 1, "%s:%s", module, this_mod);
+	n = snprintf(modname, sizeof(modname), "%s:%s", module, this_mod);
 
-	if (n > modname_size)
+	if (n > sizeof(modname) - 1)
 		return false;
 
 	val = module_kallsyms_lookup_name(modname);
Signature · 1 line
2.15.1
author maintainer
#6 lore raw

PATCH 6/18 tracing: Fix display of hist trigger expressions containing timestamps

In reply to Steven Rostedt

From: Tom Zanussi <[email protected]>

When displaying hist triggers, variable references that have the timestamp field flag set are erroneously displayed as common_timestamp rather than the variable reference. Additionally, timestamp expressions are displayed in the same way. Fix this by forcing the timestamp flag handling to follow variable reference and expression handling.

Before:

  # cat /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  hist:keys=next_pid:vals=hitcount:wakeup_lat=common_timestamp.usecs:...

After:

  # cat /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  hist:keys=next_pid:vals=hitcount:wakeup_lat=common_timestamp.usecs-$ts0.usecs:...
---
 kernel/trace/trace_events_hist.c | 19 +++++--------------
 1 file changed, 5 insertions(+), 14 deletions(-)
kernel/trace/trace_events_hist.c +5 -14
index a02bc09d765a..4f4792f4c83f 100644
@@ -1686,8 +1686,6 @@ static const char *hist_field_name(struct hist_field *field,
 	else if (field->flags & HIST_FIELD_FL_LOG2 ||
 		 field->flags & HIST_FIELD_FL_ALIAS)
 		field_name = hist_field_name(field->operands[0], ++level);
-	else if (field->flags & HIST_FIELD_FL_TIMESTAMP)
-		field_name = "common_timestamp";
 	else if (field->flags & HIST_FIELD_FL_CPU)
 		field_name = "cpu";
 	else if (field->flags & HIST_FIELD_FL_EXPR ||
@@ -1703,7 +1701,8 @@ static const char *hist_field_name(struct hist_field *field,
 			field_name = full_name;
 		} else
 			field_name = field->name;
-	}
+	} else if (field->flags & HIST_FIELD_FL_TIMESTAMP)
+		field_name = "common_timestamp";
 
 	if (field_name == NULL)
 		field_name = "";
@@ -4858,23 +4857,15 @@ static void hist_field_print(struct seq_file *m, struct hist_field *hist_field)
 	if (hist_field->var.name)
 		seq_printf(m, "%s=", hist_field->var.name);
 
-	if (hist_field->flags & HIST_FIELD_FL_TIMESTAMP)
-		seq_puts(m, "common_timestamp");
-	else if (hist_field->flags & HIST_FIELD_FL_CPU)
+	if (hist_field->flags & HIST_FIELD_FL_CPU)
 		seq_puts(m, "cpu");
 	else if (field_name) {
 		if (hist_field->flags & HIST_FIELD_FL_VAR_REF ||
 		    hist_field->flags & HIST_FIELD_FL_ALIAS)
 			seq_putc(m, '$');
 		seq_printf(m, "%s", field_name);
-	}
-
-	if (hist_field->flags) {
-		const char *flags_str = get_hist_field_flags(hist_field);
-
-		if (flags_str)
-			seq_printf(m, ".%s", flags_str);
-	}
+	} else if (hist_field->flags & HIST_FIELD_FL_TIMESTAMP)
+		seq_puts(m, "common_timestamp");
 }
 
 static int event_hist_trigger_print(struct seq_file *m,
Signature · 1 line
2.15.1
author maintainer
#7 lore raw

PATCH 7/18 tracing: Dont add flag strings when displaying variable references

In reply to Steven Rostedt

From: Tom Zanussi <[email protected]>

Variable references should never have flags appended when displayed - prevent that from happening.

Before:

  # cat /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  hist:keys=next_pid:vals=hitcount:wakeup_lat=common_timestamp.usecs-$ts0.usecs:...

After:

hist:keys=next_pid:vals=hitcount:wakeup_lat=common_timestamp.usecs-$ts0:...

---
 kernel/trace/trace_events_hist.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)
kernel/trace/trace_events_hist.c +1 -1
index 4f4792f4c83f..d867502a56ba 100644
@@ -2052,7 +2052,7 @@ static void expr_field_str(struct hist_field *field, char *expr)
 
 	strcat(expr, hist_field_name(field, 0));
 
-	if (field->flags) {
+	if (field->flags && !(field->flags & HIST_FIELD_FL_VAR_REF)) {
 		const char *flags_str = get_hist_field_flags(field);
 
 		if (flags_str) {
Signature · 1 line
2.15.1
author maintainer
#8 lore raw

PATCH 8/18 tracing: Add action comparisons when testing matching hist triggers

In reply to Steven Rostedt

From: Tom Zanussi <[email protected]>

Actions also need to be considered when checking for matching triggers
- triggers differing only by action should be allowed, but currently aren't because the matching check ignores the action and erroneously returns -EEXIST.

Add and call an actions_match() function to address that.

Here's an example using onmatch() actions. The first -EEXIST shouldn't occur because the onmatch() is different in the second wakeup_latency() param. The second -EEXIST shouldn't occur because it's a different action (in this case, it doesn't have an action, so shouldn't be seen as being the same and therefore rejected).

In the after case, both are correctly accepted (and trying to add one of them again returns -EEXIST as it should).

before:

  # echo 'wakeup_latency u64 lat; pid_t pid' >> /sys/kernel/debug/tracing/synthetic_events
  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0 if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,next_pid) if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,prev_pid) if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
-su: echo: write error: File exists
  # echo 'hist:keys=next_pid if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
-su: echo: write error: File exists

after:

  # echo 'wakeup_latency u64 lat; pid_t pid' >> /sys/kernel/debug/tracing/synthetic_events
  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0 if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,next_pid) if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,prev_pid) if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
---
 kernel/trace/trace_events_hist.c | 50 ++++++++++++++++++++++++++++++++++++++++
 1 file changed, 50 insertions(+)
kernel/trace/trace_events_hist.c +50 -0
index d867502a56ba..6114939f065a 100644
@@ -4364,6 +4364,53 @@ static void print_onmatch_spec(struct seq_file *m,
 	seq_puts(m, ")");
 }
 
+static bool actions_match(struct hist_trigger_data *hist_data,
+			  struct hist_trigger_data *hist_data_test)
+{
+	unsigned int i, j;
+
+	if (hist_data->n_actions != hist_data_test->n_actions)
+		return false;
+
+	for (i = 0; i < hist_data->n_actions; i++) {
+		struct action_data *data = hist_data->actions[i];
+		struct action_data *data_test = hist_data_test->actions[i];
+
+		if (data->fn != data_test->fn)
+			return false;
+
+		if (data->n_params != data_test->n_params)
+			return false;
+
+		for (j = 0; j < data->n_params; j++) {
+			if (strcmp(data->params[j], data_test->params[j]) != 0)
+				return false;
+		}
+
+		if (data->fn == action_trace) {
+			if (strcmp(data->onmatch.synth_event_name,
+				   data_test->onmatch.synth_event_name) != 0)
+				return false;
+			if (strcmp(data->onmatch.match_event_system,
+				   data_test->onmatch.match_event_system) != 0)
+				return false;
+			if (strcmp(data->onmatch.match_event,
+				   data_test->onmatch.match_event) != 0)
+				return false;
+		} else if (data->fn == onmax_save) {
+			if (strcmp(data->onmax.var_str,
+				   data_test->onmax.var_str) != 0)
+				return false;
+			if (strcmp(data->onmax.fn_name,
+				   data_test->onmax.fn_name) != 0)
+				return false;
+		}
+	}
+
+	return true;
+}
+
+
 static void print_actions_spec(struct seq_file *m,
 			       struct hist_trigger_data *hist_data)
 {
@@ -5174,6 +5221,9 @@ static bool hist_trigger_match(struct event_trigger_data *data,
 	    (strcmp(data->filter_str, data_test->filter_str) != 0))
 		return false;
 
+	if (!actions_match(hist_data, hist_data_test))
+		return false;
+
 	return true;
 }
 
Signature · 1 line
2.15.1
author maintainer
#9 lore raw

PATCH 9/18 tracing: Make sure variable string fields are NULL-terminated

In reply to Steven Rostedt

From: Tom Zanussi <[email protected]>

The strncpy() currently being used for variable string fields can result in a lack of termination if the string length is equal to the field size. Use the safer strscpy() instead, which will guarantee termination.

---
 kernel/trace/trace_events_hist.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)
kernel/trace/trace_events_hist.c +2 -2
index 6114939f065a..15ea11c29a51 100644
@@ -669,7 +669,7 @@ static notrace void trace_event_raw_event_synth(void *__data,
 			char *str_val = (char *)(long)var_ref_vals[var_ref_idx + i];
 			char *str_field = (char *)&entry->fields[n_u64];
 
-			strncpy(str_field, str_val, STR_VAR_LEN_MAX);
+			strscpy(str_field, str_val, STR_VAR_LEN_MAX);
 			n_u64 += STR_VAR_LEN_MAX / sizeof(u64);
 		} else {
 			entry->fields[n_u64] = var_ref_vals[var_ref_idx + i];
@@ -3091,7 +3091,7 @@ static inline void __update_field_vars(struct tracing_map_elt *elt,
 			char *str = elt_data->field_var_str[j++];
 			char *val_str = (char *)(uintptr_t)var_val;
 
-			strncpy(str, val_str, STR_VAR_LEN_MAX);
+			strscpy(str, val_str, STR_VAR_LEN_MAX);
 			var_val = (u64)(uintptr_t)str;
 		}
 		tracing_map_set_var(elt, var_idx, var_val);
Signature · 1 line
2.15.1
author maintainer
#10 lore raw

PATCH 10/18 tracing: Uninitialized variable in create_tracing_map_fields()

In reply to Steven Rostedt

From: Dan Carpenter <[email protected]>

Smatch complains that idx can be used uninitialized when we check if (idx < 0). It has to be the first iteration through the loop and the HIST_FIELD_FL_STACKTRACE bit has to be clear and the HIST_FIELD_FL_VAR bit has to be set to reach the bug.

Fixes 30350d65ac56 ("tracing: Add variable support to hist triggers")
---
 kernel/trace/trace_events_hist.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)
kernel/trace/trace_events_hist.c +1 -1
index 15ea11c29a51..0d7b3ffbecc2 100644
@@ -4458,7 +4458,7 @@ static int create_tracing_map_fields(struct hist_trigger_data *hist_data)
 	struct tracing_map *map = hist_data->map;
 	struct ftrace_event_field *field;
 	struct hist_field *hist_field;
-	int i, idx;
+	int i, idx = 0;
 
 	for_each_hist_field(i, hist_data) {
 		hist_field = hist_data->fields[i];
Signature · 1 line
2.15.1
author maintainer
#11 lore raw

PATCH 11/18 vsprintf: Do not preprocess non-dereferenced pointers for bprintf (%px and %pK)

In reply to Steven Rostedt

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

Commit 841a915d20c7b2 ("printf: Do not have bprintf dereference pointers") would preprocess various pointers that are dereferenced in the bprintf() because the recording and printing are done at two different times. Some pointers stayed dereferenced in the ring buffer because user space could handle them (namely "%pS" and friends). Pointers that are not dereferenced should not be processed immediately but instead just saved directly.

Fixes 841a915d20c7b2 ("printf: Do not have bprintf dereference pointers")
---
 lib/vsprintf.c | 4 ++++
 1 file changed, 4 insertions(+)
lib/vsprintf.c +4 -0
index d7a708f82559..89f8a4a4b770 100644
@@ -2591,6 +2591,8 @@ int vbin_printf(u32 *bin_buf, size_t size, const char *fmt, va_list args)
 			case 's':
 			case 'F':
 			case 'f':
+			case 'x':
+			case 'K':
 				save_arg(void *);
 				break;
 			default:
@@ -2765,6 +2767,8 @@ int bstr_printf(char *buf, size_t size, const char *fmt, const u32 *bin_buf)
 			case 's':
 			case 'F':
 			case 'f':
+			case 'x':
+			case 'K':
 				process = true;
 				break;
 			default:
Signature · 1 line
2.15.1
author maintainer
#12 lore raw

PATCH 12/18 lockdep: Add print_irqtrace_events() to __warn

In reply to Steven Rostedt

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

Running a test on a x86_32 kernel I triggered a bug that an interrupt disable/enable isn't being catched by lockdep. At least knowing where the last one was found would be helpful, but the warnings that are produced do not show this information. Even without debugging lockdep, having the WARN() display the last place hard and soft irqs were enabled or disabled is valuable.

---
 kernel/panic.c | 2 ++
 1 file changed, 2 insertions(+)
kernel/panic.c +2 -0
index 2cfef408fec9..fa8d4cc4956a 100644
@@ -554,6 +554,8 @@ void __warn(const char *file, int line, void *caller, unsigned taint,
 	else
 		dump_stack();
 
+	print_irqtrace_events(current);
+
 	print_oops_end_marker();
 
 	/* Just a warning, don't kill lockdep. */
Signature · 1 line
2.15.1
author maintainer
#13 lore raw

PATCH 13/18 ring-buffer: Check if memory is available before allocation

In reply to Steven Rostedt

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

The ring buffer is made up of a link list of pages. When making the ring buffer bigger, it will allocate all the pages it needs before adding to the ring buffer, and if it fails, it frees them and returns an error. This makes increasing the ring buffer size an all or nothing action. When this was first created, the pages were allocated with "NORETRY". This was to not cause any Out-Of-Memory (OOM) actions from allocating the ring buffer. But NORETRY was too strict, as the ring buffer would fail to expand even when there's memory available, but was taken up in the page cache.

Commit 848618857d253 ("tracing/ring_buffer: Try harder to allocate") changed the allocating from NORETRY to RETRY_MAYFAIL. The RETRY_MAYFAIL would allocate from the page cache, but if there was no memory available, it would simple fail the allocation and not trigger an OOM.

This worked fine, but had one problem. As the ring buffer would allocate one page at a time, it could take up all memory in the system before it failed to allocate and free that memory. If the allocation is happening and the ring buffer allocates all memory and then tries to take more than available, its allocation will not trigger an OOM, but if there's any allocation that happens someplace else, that could trigger an OOM, even though once the ring buffer's allocation fails, it would free up all the previous memory it tried to allocate, and allow other memory allocations to succeed.

Commit d02bd27bd33dd ("mm/page_alloc.c: calculate 'available' memory in a separate function") separated out si_mem_availble() as a separate function that could be used to see how much memory is available in the system. Using this function to make sure that the ring buffer could be allocated before it tries to allocate pages we can avoid allocating all memory in the system and making it vulnerable to OOMs if other allocations are taking place.

Fixes 848618857d253 ("tracing/ring_buffer: Try harder to allocate")

Requires: d02bd27bd33dd ("mm/page_alloc.c: calculate 'available' memory in a separate function")

---
 kernel/trace/ring_buffer.c | 5 +++++
 1 file changed, 5 insertions(+)
kernel/trace/ring_buffer.c +5 -0
index 515be03e3009..966128f02121 100644
@@ -1164,6 +1164,11 @@ static int __rb_allocate_pages(long nr_pages, struct list_head *pages, int cpu)
 	struct buffer_page *bpage, *tmp;
 	long i;
 
+	/* Check if the available memory is there first */
+	i = si_mem_available();
+	if (i < nr_pages)
+		return -ENOMEM;
+
 	for (i = 0; i < nr_pages; i++) {
 		struct page *page;
 		/*
Signature · 1 line
2.15.1
author maintainer
#14 lore raw

PATCH 14/18 ring-buffer: Add set/clear_current_oom_origin() during allocations

In reply to Steven Rostedt

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

As si_mem_available() can say there is enough memory even though the memory available is not useable by the ring buffer, it is best to not kill innocent applications because the ring buffer is taking up all the memory while it is trying to allocate a great deal of memory.

If the allocator is user space (because kernel threads can also increase the size of the kernel ring buffer on boot up), then after si_mem_available() says there is enough memory, set the OOM killer to kill the current task if an OOM triggers during the allocation.

---
 kernel/trace/ring_buffer.c | 48 ++++++++++++++++++++++++++++++++++++----------
 1 file changed, 38 insertions(+), 10 deletions(-)
kernel/trace/ring_buffer.c +38 -10
index 966128f02121..c9cb9767d49b 100644
@@ -22,6 +22,7 @@
 #include <linux/hash.h>
 #include <linux/list.h>
 #include <linux/cpu.h>
+#include <linux/oom.h>
 
 #include <asm/local.h>
 
@@ -1162,35 +1163,60 @@ static int rb_check_pages(struct ring_buffer_per_cpu *cpu_buffer)
 static int __rb_allocate_pages(long nr_pages, struct list_head *pages, int cpu)
 {
 	struct buffer_page *bpage, *tmp;
+	bool user_thread = current->mm != NULL;
+	gfp_t mflags;
 	long i;
 
-	/* Check if the available memory is there first */
+	/*
+	 * Check if the available memory is there first.
+	 * Note, si_mem_available() only gives us a rough estimate of available
+	 * memory. It may not be accurate. But we don't care, we just want
+	 * to prevent doing any allocation when it is obvious that it is
+	 * not going to succeed.
+	 */
 	i = si_mem_available();
 	if (i < nr_pages)
 		return -ENOMEM;
 
+	/*
+	 * __GFP_RETRY_MAYFAIL flag makes sure that the allocation fails
+	 * gracefully without invoking oom-killer and the system is not
+	 * destabilized.
+	 */
+	mflags = GFP_KERNEL | __GFP_RETRY_MAYFAIL;
+
+	/*
+	 * If a user thread allocates too much, and si_mem_available()
+	 * reports there's enough memory, even though there is not.
+	 * Make sure the OOM killer kills this thread. This can happen
+	 * even with RETRY_MAYFAIL because another task may be doing
+	 * an allocation after this task has taken all memory.
+	 * This is the task the OOM killer needs to take out during this
+	 * loop, even if it was triggered by an allocation somewhere else.
+	 */
+	if (user_thread)
+		set_current_oom_origin();
 	for (i = 0; i < nr_pages; i++) {
 		struct page *page;
-		/*
-		 * __GFP_RETRY_MAYFAIL flag makes sure that the allocation fails
-		 * gracefully without invoking oom-killer and the system is not
-		 * destabilized.
-		 */
+
 		bpage = kzalloc_node(ALIGN(sizeof(*bpage), cache_line_size()),
-				    GFP_KERNEL | __GFP_RETRY_MAYFAIL,
-				    cpu_to_node(cpu));
+				    mflags, cpu_to_node(cpu));
 		if (!bpage)
 			goto free_pages;
 
 		list_add(&bpage->list, pages);
 
-		page = alloc_pages_node(cpu_to_node(cpu),
-					GFP_KERNEL | __GFP_RETRY_MAYFAIL, 0);
+		page = alloc_pages_node(cpu_to_node(cpu), mflags, 0);
 		if (!page)
 			goto free_pages;
 		bpage->page = page_address(page);
 		rb_init_page(bpage->page);
+
+		if (user_thread && fatal_signal_pending(current))
+			goto free_pages;
 	}
+	if (user_thread)
+		clear_current_oom_origin();
 
 	return 0;
 
@@ -1199,6 +1225,8 @@ static int __rb_allocate_pages(long nr_pages, struct list_head *pages, int cpu)
 		list_del_init(&bpage->list);
 		free_buffer_page(bpage);
 	}
+	if (user_thread)
+		clear_current_oom_origin();
 
 	return -ENOMEM;
 }
Signature · 1 line
2.15.1
author maintainer
#15 lore raw

PATCH 15/18 tracing: Hide global trace clock from lockdep

In reply to Steven Rostedt

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

Function tracing can trace in NMIs and such. If the TSC is determined to be unstable, the tracing clock will switch to the global clock on boot up, unless "trace_clock" is specified on the kernel command line.

The global clock disables interrupts to access sched_clock_cpu(), and in doing so can be done within lockdep internals (because of function tracing and NMIs). This can trigger false lockdep splats.

The trace_clock_global() is special, best not to trace the irq logic within it.

---
 kernel/trace/trace_clock.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)
kernel/trace/trace_clock.c +2 -2
index 5fdc779f411d..d8a188e0418a 100644
@@ -96,7 +96,7 @@ u64 notrace trace_clock_global(void)
 	int this_cpu;
 	u64 now;
 
-	local_irq_save(flags);
+	raw_local_irq_save(flags);
 
 	this_cpu = raw_smp_processor_id();
 	now = sched_clock_cpu(this_cpu);
@@ -122,7 +122,7 @@ u64 notrace trace_clock_global(void)
 	arch_spin_unlock(&trace_clock_struct.lock);
 
  out:
-	local_irq_restore(flags);
+	raw_local_irq_restore(flags);
 
 	return now;
 }
Signature · 1 line
2.15.1
author maintainer
#16 lore raw

PATCH 16/18 tracing: Fixup logic inversion on setting trace_global_clock defaults

In reply to Steven Rostedt

From: Chris Wilson <[email protected]>

In commit 932066a15335 ("tracing: Default to using trace_global_clock if sched_clock is unstable"), the logic for deciding to override the default clock if unstable was reversed from the earlier posting. I was trying to reduce the width of the message by using an early return rather than a if-block, but reverted back to using the if-block and accidentally left the predicate inverted.

Fixes 932066a15335 ("tracing: Default to using trace_global_clock if sched_clock is unstable")
---
 kernel/trace/trace.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)
kernel/trace/trace.c +1 -1
index 0f47e653ffd8..e18e69183c9a 100644
@@ -8602,7 +8602,7 @@ late_initcall_sync(clear_boot_tracer);
 __init static int tracing_set_default_clock(void)
 {
 	/* sched_clock_stable() is determined in late_initcall */
-	if (trace_boot_clock || sched_clock_stable()) {
+	if (!trace_boot_clock && !sched_clock_stable()) {
 		printk(KERN_WARNING
 		       "Unstable clock detected, switching default tracing clock to \"global\"\n"
 		       "If you want to keep using the local clock, then add:\n"
Signature · 1 line
2.15.1
author maintainer
#17 lore raw

PATCH 17/18 tracing: Add rcu dereference annotation for filter->prog

In reply to Steven Rostedt

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

ftrace_function_set_filter() referenences filter->prog without annotation and sparse complains about it. It needs a rcu_dereference_protected() wrapper.

Fixes 80765597bc587 ("tracing: Rewrite filter logic to be simpler and faster")
---
 kernel/trace/trace_events_filter.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)
kernel/trace/trace_events_filter.c +2 -1
index 703a416aa5c2..cf8460caa95c 100644
@@ -1992,7 +1992,8 @@ static bool is_or(struct prog_entry *prog, int i)
 static int ftrace_function_set_filter(struct perf_event *event,
 				      struct event_filter *filter)
 {
-	struct prog_entry *prog = filter->prog;
+	struct prog_entry *prog = rcu_dereference_protected(filter->prog,
+						lockdep_is_held(&event_mutex));
 	struct function_filter_data data = {
 		.first_filter  = 1,
 		.first_notrace = 1,
Signature · 1 line
2.15.1
author maintainer
#18 lore raw

PATCH 18/18 tracing: Add rcu dereference annotation for test func that touches filter->prog

In reply to Steven Rostedt

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

A boot up test function update_pred_fn() dereferences filter->prog without the proper rcu annotation.

To do this, we must also take the event_mutex first. Normally, this isn't needed because this test function can not race with other use cases that touch the event filters (it is disabled if any events are enabled).

Fixes 80765597bc587 ("tracing: Rewrite filter logic to be simpler and faster")
---
 kernel/trace/trace_events_filter.c | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)
kernel/trace/trace_events_filter.c +6 -1
index cf8460caa95c..1bda4ec95e18 100644
@@ -2155,7 +2155,8 @@ static int test_pred_visited_fn(struct filter_pred *pred, void *event)
 
 static void update_pred_fn(struct event_filter *filter, char *fields)
 {
-	struct prog_entry *prog = filter->prog;
+	struct prog_entry *prog = rcu_dereference_protected(filter->prog,
+						lockdep_is_held(&event_mutex));
 	int i;
 
 	for (i = 0; prog[i].pred; i++) {
@@ -2197,6 +2198,8 @@ static __init int ftrace_test_event_filter(void)
 			break;
 		}
 
+		/* Needed to dereference filter->prog */
+		mutex_lock(&event_mutex);
 		/*
 		 * The preemption disabling is not really needed for self
 		 * tests, but the rcu dereference will complain without it.
@@ -2209,6 +2212,8 @@ static __init int ftrace_test_event_filter(void)
 		err = filter_match_preds(filter, &d->rec);
 		preempt_enable();
 
+		mutex_unlock(&event_mutex);
+
 		__free_filter(filter);
 
 		if (test_pred_visited) {
Signature · 1 line
2.15.1