tracing/ftrace: Updates for 4.12-rc1

I'll let these sit in linux-next for a day or two before pushing to Linus.

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

Head SHA1: 545a028190dae4437aac4f86da7c8ab20857647c

Naveen N. Rao (4):
ftrace: Simplify glob handling in unregister_ftrace_function_probe_func() ftrace/instances: Clear function triggers when removing instances selftests/ftrace: Fix bashisms
selftests/ftrace: Add test to remove instance with active event triggers

Steven Rostedt (1):
tracing: Move postpone selftests to core from early_initcall

Steven Rostedt (VMware) (2):
ftrace: Remove #ifdef from code and add clear_ftrace_function_probes() stub
kprobes: Document how optimized kprobes are removed from module unload

Thomas Gleixner (1):
tracing/kprobes: Enforce kprobes teardown after testing

----

 include/linux/kprobes.h                                      |  3 +++
 kernel/kprobes.c                                             |  8 +++++++-
 kernel/trace/ftrace.c                                        | 12 ++++++++++--
 kernel/trace/trace.c                                         |  3 ++-
 kernel/trace/trace.h                                         |  5 +++++
 kernel/trace/trace_kprobe.c                                  |  5 +++++
 tools/testing/selftests/ftrace/ftracetest                    |  2 +-
 .../selftests/ftrace/test.d/ftrace/func_event_triggers.tc    |  2 +-
 tools/testing/selftests/ftrace/test.d/functions              |  4 ++--
 .../selftests/ftrace/test.d/instances/instance-event.tc      |  8 ++++++--
 10 files changed, 42 insertions(+), 10 deletions(-)

From: Steven Rostedt <[email protected]>

I hit the following lockdep splat when booting with ftrace selftests enabled, as well as CONFIG_PREEMPT and LOCKDEP.

Testing dynamic ftrace ops #1:
(1 0 1 0 0)
(1 1 2 0 0)
(2 1 3 0 169)
(2 2 4 0 50066)

 ------------[ cut here ]------------
 WARNING: CPU: 0 PID: 13 at kernel/rcu/srcutree.c:202 check_init_srcu_struct+0x60/0x70
 Modules linked in:
 CPU: 0 PID: 13 Comm: rcu_tasks_kthre Not tainted 4.12.0-rc1-test+ #587
 Hardware name: Hewlett-Packard HP Compaq Pro 6300 SFF/339A, BIOS K01 v02.05 05/07/2012
 task: ffff880119628040 task.stack: ffffc900006a4000
 RIP: 0010:check_init_srcu_struct+0x60/0x70
 RSP: 0000:ffffc900006a7d98 EFLAGS: 00010246
 RAX: 0000000000000246 RBX: 0000000000000000 RCX: 0000000000000000
 RDX: ffff880119628040 RSI: 00000000ffffffff RDI: ffffffff81e5fb40
 RBP: ffffc900006a7e20 R08: 00000023b403c000 R09: 0000000000000001
 R10: ffffc900006a7e40 R11: 0000000000000000 R12: ffffffff81e5fb40
 R13: 0000000000000286 R14: ffff880119628040 R15: ffffc900006a7e98
 FS:  0000000000000000(0000) GS:ffff88011ea00000(0000) knlGS:0000000000000000
 CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
 CR2: ffff88011edff000 CR3: 0000000001e0f000 CR4: 00000000001406f0
 Call Trace:
  ? __synchronize_srcu+0x6e/0x140
  ? lock_acquire+0xdc/0x1d0
  ? ktime_get_mono_fast_ns+0x5d/0xb0
  synchronize_srcu+0x6f/0x110
  ? synchronize_srcu+0x6f/0x110
  rcu_tasks_kthread+0x20a/0x540
  kthread+0x114/0x150
  ? __rcu_read_unlock+0x70/0x70
  ? kthread_create_on_node+0x40/0x40
  ret_from_fork+0x2e/0x40
 Code: f6 83 70 06 00 00 03 49 89 c5 74 0d be 01 00 00 00 48 89 df e8 42 fa ff ff 4c 89 ee 4c 89 e7 e8 b7 42 75 00 5b 41 5c 41 5d 5d c3 <0f> ff eb aa 66 90 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00
 ---[ end trace 5c3f4206ce50f6ac ]---

What happens is that the selftests include a creating of a dynamically allocated ftrace_ops, which requires the use of synchronize_rcu_tasks() which uses srcu, and triggers the above warning.

It appears that synchronize_rcu_tasks() is not set up at early_initcall(), but it is at core_initcall(). By moving the tests down to that location works out properly.

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

index c4536c449021..cdf97ce8cff2 100644
@@ -1558,7 +1558,7 @@ static __init int init_trace_selftests(void)
 
 	return 0;
 }
-early_initcall(init_trace_selftests);
+core_initcall(init_trace_selftests);
 #else
 static inline int run_tracer_selftest(struct tracer *type)
 {

2.10.2

From: Thomas Gleixner <[email protected]>

Enabling the tracer selftest triggers occasionally the warning in text_poke(), which warns when the to be modified page is not marked reserved.

The reason is that the tracer selftest installs kprobes on functions marked __init for testing. These probes are removed after the tests, but that removal schedules the delayed kprobes_optimizer work, which will do the actual text poke. If the work is executed after the init text is freed, then the warning triggers. The bug can be reproduced reliably when the work delay is increased.

Flush the optimizer work and wait for the optimizing/unoptimizing lists to become empty before returning from the kprobes tracer selftest. That ensures that all operations which were queued due to the probes removal have completed.

---
 include/linux/kprobes.h     | 3 +++
 kernel/kprobes.c            | 2 +-
 kernel/trace/trace_kprobe.c | 5 +++++
 3 files changed, 9 insertions(+), 1 deletion(-)

index 30f90c1a0aaf..541df0b5b815 100644
@@ -349,6 +349,9 @@ extern int proc_kprobes_optimization_handler(struct ctl_table *table,
 					     int write, void __user *buffer,
 					     size_t *length, loff_t *ppos);
 #endif
+extern void wait_for_kprobe_optimizer(void);
+#else
+static inline void wait_for_kprobe_optimizer(void) { }
 #endif /* CONFIG_OPTPROBES */
 #ifdef CONFIG_KPROBES_ON_FTRACE
 extern void kprobe_ftrace_handler(unsigned long ip, unsigned long parent_ip,

index 7367e0ec6f81..199243bba554 100644
@@ -595,7 +595,7 @@ static void kprobe_optimizer(struct work_struct *work)
 }
 
 /* Wait for completing optimization and unoptimization */
-static void wait_for_kprobe_optimizer(void)
+void wait_for_kprobe_optimizer(void)
 {
 	mutex_lock(&kprobe_mutex);
 

index 8485f6738a87..c129fca6ec99 100644
@@ -1535,6 +1535,11 @@ static __init int kprobe_trace_self_tests_init(void)
 
 end:
 	release_all_trace_kprobes();
+	/*
+	 * Wait for the optimizer work to finish. Otherwise it might fiddle
+	 * with probes in already freed __init text.
+	 */
+	wait_for_kprobe_optimizer();
 	if (warn)
 		pr_cont("NG: Some tests are failed. Please check them.\n");
 	else

2.10.2

From: "Naveen N. Rao" <[email protected]>

Handle a NULL glob properly and simplify the check.

---
 kernel/trace/ftrace.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

index 39dca4e86a94..c35c3e67d09a 100644
@@ -4144,9 +4144,9 @@ unregister_ftrace_function_probe_func(char *glob, struct trace_array *tr,
 	int i, ret = -ENODEV;
 	int size;
 
-	if (glob && (strcmp(glob, "*") == 0 || !strlen(glob)))
+	if (!glob || !strlen(glob) || !strcmp(glob, "*"))
 		func_g.search = NULL;
-	else if (glob) {
+	else {
 		int not;
 
 		func_g.type = filter_parse_regex(glob, strlen(glob),

2.10.2

From: "Naveen N. Rao" <[email protected]>

If instance directories are deleted while there are registered function triggers:

  # cd /sys/kernel/debug/tracing/instances
  # mkdir test
  # echo "schedule:enable_event:sched:sched_switch" > test/set_ftrace_filter
  # rmdir test
  Unable to handle kernel paging request for data at address 0x00000008
  Unable to handle kernel paging request for data at address 0x00000008
  Faulting instruction address: 0xc0000000021edde8
  Oops: Kernel access of bad area, sig: 11 [#1]
  SMP NR_CPUS=2048
  NUMA
  pSeries
  Modules linked in: iptable_mangle ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack ipt_REJECT nf_reject_ipv4 xt_tcpudp tun bridge stp llc kvm iptable_filter fuse binfmt_misc pseries_rng rng_core vmx_crypto ib_iser rdma_cm iw_cm ib_cm ib_core libiscsi scsi_transport_iscsi ip_tables x_tables autofs4 btrfs raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c multipath virtio_net virtio_blk virtio_pci crc32c_vpmsum virtio_ring virtio
  CPU: 8 PID: 8694 Comm: rmdir Not tainted 4.11.0-nnr+ #113
  task: c0000000bab52800 task.stack: c0000000baba0000
  NIP: c0000000021edde8 LR: c0000000021f0590 CTR: c000000002119620
  REGS: c0000000baba3870 TRAP: 0300   Not tainted  (4.11.0-nnr+)
  MSR: 8000000000009033 <SF,EE,ME,IR,DR,RI,LE>
    CR: 22002422  XER: 20000000
  CFAR: 00007fffabb725a8 DAR: 0000000000000008 DSISR: 40000000 SOFTE: 0
  GPR00: c00000000220f750 c0000000baba3af0 c000000003157e00 0000000000000000
  GPR04: 0000000000000040 00000000000000eb 0000000000000040 0000000000000000
  GPR08: 0000000000000000 0000000000000113 0000000000000000 c00000000305db98
  GPR12: c000000002119620 c00000000fd42c00 0000000000000000 0000000000000000
  GPR16: 0000000000000000 0000000000000000 0000000000000000 0000000000000000
  GPR20: 0000000000000000 0000000000000000 c0000000bab52e90 0000000000000000
  GPR24: 0000000000000000 00000000000000eb 0000000000000040 c0000000baba3bb0
  GPR28: c00000009cb06eb0 c0000000bab52800 c00000009cb06eb0 c0000000baba3bb0
  NIP [c0000000021edde8] ring_buffer_lock_reserve+0x8/0x4e0
  LR [c0000000021f0590] trace_event_buffer_lock_reserve+0xe0/0x1a0
  Call Trace:
  [c0000000baba3af0] [c0000000021f96c8] trace_event_buffer_commit+0x1b8/0x280 (unreliable)
  [c0000000baba3b60] [c00000000220f750] trace_event_buffer_reserve+0x80/0xd0
  [c0000000baba3b90] [c0000000021196b8] trace_event_raw_event_sched_switch+0x98/0x180
  [c0000000baba3c10] [c0000000029d9980] __schedule+0x6e0/0xab0
  [c0000000baba3ce0] [c000000002122230] do_task_dead+0x70/0xc0
  [c0000000baba3d10] [c0000000020ea9c8] do_exit+0x828/0xd00
  [c0000000baba3dd0] [c0000000020eaf70] do_group_exit+0x60/0x100
  [c0000000baba3e10] [c0000000020eb034] SyS_exit_group+0x24/0x30
  [c0000000baba3e30] [c00000000200bcec] system_call+0x38/0x54
  Instruction dump:
  60000000 60420000 7d244b78 7f63db78 4bffaa09 393efff8 793e0020 39200000
  4bfffecc 60420000 3c4c00f7 3842a020 <81230008> 2f890000 409e02f0 a14d0008
  ---[ end trace b917b8985d0e650b ]---
  Unable to handle kernel paging request for data at address 0x00000008
  Faulting instruction address: 0xc0000000021edde8
  Unable to handle kernel paging request for data at address 0x00000008
  Faulting instruction address: 0xc0000000021edde8
  Faulting instruction address: 0xc0000000021edde8

To address this, let's clear all registered function probes before deleting the ftrace instance.

---
 kernel/trace/ftrace.c | 8 ++++++++
 kernel/trace/trace.c  | 3 +++
 kernel/trace/trace.h  | 1 +
 3 files changed, 12 insertions(+)

index c35c3e67d09a..74fdfe9ed3db 100644
@@ -4256,6 +4256,14 @@ unregister_ftrace_function_probe_func(char *glob, struct trace_array *tr,
 	return ret;
 }
 
+void clear_ftrace_function_probes(struct trace_array *tr)
+{
+	struct ftrace_func_probe *probe, *n;
+
+	list_for_each_entry_safe(probe, n, &tr->func_probes, list)
+		unregister_ftrace_function_probe_func(NULL, tr, probe->probe_ops);
+}
+
 static LIST_HEAD(ftrace_commands);
 static DEFINE_MUTEX(ftrace_cmd_mutex);
 

index cdf97ce8cff2..664c44a6d48f 100644
@@ -7550,6 +7550,9 @@ static int instance_rmdir(const char *name)
 	}
 
 	tracing_set_nop(tr);
+#if defined(CONFIG_FUNCTION_TRACER) && defined(CONFIG_DYNAMIC_FTRACE)
+	clear_ftrace_function_probes(tr);
+#endif
 	event_trace_del_tracer(tr);
 	ftrace_clear_pids(tr);
 	ftrace_destroy_function_files(tr);

index 291a1bca5748..98e0845f7235 100644
@@ -980,6 +980,7 @@ register_ftrace_function_probe(char *glob, struct trace_array *tr,
 extern int
 unregister_ftrace_function_probe_func(char *glob, struct trace_array *tr,
 				      struct ftrace_probe_ops *ops);
+extern void clear_ftrace_function_probes(struct trace_array *tr);
 
 int register_ftrace_command(struct ftrace_func_command *cmd);
 int unregister_ftrace_command(struct ftrace_func_command *cmd);

2.10.2

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

No need to add ugly #ifdefs in the code. Having a standard stub file is much prettier.

---
 kernel/trace/trace.c | 2 --
 kernel/trace/trace.h | 4 ++++
 2 files changed, 4 insertions(+), 2 deletions(-)

index 664c44a6d48f..fcc9a2d774c3 100644
@@ -7550,9 +7550,7 @@ static int instance_rmdir(const char *name)
 	}
 
 	tracing_set_nop(tr);
-#if defined(CONFIG_FUNCTION_TRACER) && defined(CONFIG_DYNAMIC_FTRACE)
 	clear_ftrace_function_probes(tr);
-#endif
 	event_trace_del_tracer(tr);
 	ftrace_clear_pids(tr);
 	ftrace_destroy_function_files(tr);

index 98e0845f7235..39fd77330aab 100644
@@ -999,6 +999,10 @@ static inline __init int unregister_ftrace_command(char *cmd_name)
 {
 	return -EINVAL;
 }
+static inline void clear_ftrace_function_probes(struct trace_array *tr)
+{
+}
+
 /*
  * The ops parameter passed in is usually undefined.
  * This must be a macro.

2.10.2

From: "Naveen N. Rao" <[email protected]>

Fix a few bashisms in ftrace selftests.

---
 tools/testing/selftests/ftrace/ftracetest                           | 2 +-
 tools/testing/selftests/ftrace/test.d/ftrace/func_event_triggers.tc | 2 +-
 tools/testing/selftests/ftrace/test.d/functions                     | 4 ++--
 3 files changed, 4 insertions(+), 4 deletions(-)

index 32e6211e1c6e..717581145cfc 100755
@@ -58,7 +58,7 @@ parse_opts() { # opts
     ;;
     --verbose|-v|-vv)
       VERBOSE=$((VERBOSE + 1))
-      [ $1 == '-vv' ] && VERBOSE=$((VERBOSE + 1))
+      [ $1 = '-vv' ] && VERBOSE=$((VERBOSE + 1))
       shift 1
     ;;
     --debug|-d)

index 07bb3e5930b4..aa31368851c9 100644
@@ -48,7 +48,7 @@ test_event_enabled() {
     e=`cat $EVENT_ENABLE`
     if [ "$e" != $val ]; then
 	echo "Expected $val but found $e"
-	exit -1
+	exit 1
     fi
 }
 

index 9aec6fcb7729..f2019b37370d 100644
@@ -34,10 +34,10 @@ reset_ftrace_filter() { # reset all triggers in set_ftrace_filter
     echo > set_ftrace_filter
     grep -v '^#' set_ftrace_filter | while read t; do
 	tr=`echo $t | cut -d: -f2`
-	if [ "$tr" == "" ]; then
+	if [ "$tr" = "" ]; then
 	    continue
 	fi
-	if [ $tr == "enable_event" -o $tr == "disable_event" ]; then
+	if [ $tr = "enable_event" -o $tr = "disable_event" ]; then
 	    tr=`echo $t | cut -d: -f1-4`
 	    limit=`echo $t | cut -d: -f5`
 	else

2.10.2

From: "Naveen N. Rao" <[email protected]>

Add a test to ensure we clean up properly when removing an instance with active event triggers.

---
 tools/testing/selftests/ftrace/test.d/instances/instance-event.tc | 8 ++++++--
 1 file changed, 6 insertions(+), 2 deletions(-)

index 4c5a061a5b4e..c73db7863adb 100644
@@ -75,9 +75,13 @@ rmdir foo
 if [ -d foo ]; then
         fail "foo still exists"
 fi
-exit 0
-
 
+mkdir foo
+echo "schedule:enable_event:sched:sched_switch" > foo/set_ftrace_filter
+rmdir foo
+if [ -d foo ]; then
+        fail "foo still exists"
+fi
 
 
 instance_slam() {

2.10.2

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

Thomas discovered a bug where the kprobe trace tests had a race condition where the kprobe_optimizer called from a delayed work queue that does the optimizing and "unoptimizing" of a kprobe, can try to modify the text after it has been freed by the init code.

The kprobe trace selftest is a special case, and Thomas and myself investigated to see if there's a chance that this could also be a bug with module unloading, as the code is not obvious to how it handles this. After adding lots of printks, I figured it out. Thomas suggested that this should be commented so that others will not have to go through this exercise again.

---
 kernel/kprobes.c | 6 ++++++
 1 file changed, 6 insertions(+)

index 199243bba554..2d2d3a568e4e 100644
@@ -2183,6 +2183,12 @@ static int kprobes_module_callback(struct notifier_block *nb,
 				 * The vaddr this probe is installed will soon
 				 * be vfreed buy not synced to disk. Hence,
 				 * disarming the breakpoint isn't needed.
+				 *
+				 * Note, this will also move any optimized probes
+				 * that are pending to be removed from their
+				 * corresponding lists to the freeing_list and
+				 * will not be touched by the delayed
+				 * kprobe_optimizer work handler.
 				 */
 				kill_kprobe(p);
 			}

2.10.2