[PATCH v2 0/2] Enable new kprobe event at boot

[PATCH v2 0/2] Enable new kprobe event at boot

[Masami Hiramatsu]

Hi,

This v2 series adds a kernel parameter, 'kprobe_event=' to add and enable
new kprobe events at boot time.

In this version, I changed to use postcore_initcall() instead of
subsys_initcall() for kprobes initialization.

Currently ftrace can enable some existing trace events at boot time.
This also allows admin/developer to add new kprobe-events at boot
time to debug device drivers etc.

The syntax is similar to tracing/kprobe_events interface, but
uses ',' and ';' instead of ' ' and '\n' respectively. e.g.

  kprobe_event=p,func1,$arg1,$arg2;p,func2,$arg1

will add probes on func1 with the 1st and the 2nd arguments and on
func2 with the 1st argument.

Note that 'trace_event=' option enables trace event at very early
timing, but the events added by 'kprobe_event=' are enabled right
before enabling device drivers at this point. It is enough for
tracing device driver initialization etc.

Thank you,

---

Masami Hiramatsu (2):
      kprobes: Initialize kprobes at postcore_initcall
      tracing/kprobe: Add kprobe_event= boot parameter


 Documentation/admin-guide/kernel-parameters.txt |   13 ++++++
 Documentation/trace/kprobetrace.rst             |   14 ++++++
 kernel/kprobes.c                                |    3 -
 kernel/trace/trace_kprobe.c                     |   54 +++++++++++++++++++++++
 4 files changed, 82 insertions(+), 2 deletions(-)

--
Masami Hiramatsu (Linaro)

[PATCH v2 1/2] kprobes: Initialize kprobes at postcore_initcall

[Masami Hiramatsu]

Initialize kprobes at postcore_initcall level instead of module_init
since kprobes is not a module, and it depends on only subsystems
initialized in core_initcall.
This will allow ftrace kprobe event to add new events when it is
initializing because ftrace kprobe event is initialized at
later initcall level.

Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
---
  Changes in v2
   - use postcore_initcall instead of subsys_initcall
---
 kernel/kprobes.c |    3 +--
 1 file changed, 1 insertion(+), 2 deletions(-)

diff --git a/kernel/kprobes.c b/kernel/kprobes.c
index c83e54727131..5d51dd84b1a2 100644
--- a/kernel/kprobes.c
+++ b/kernel/kprobes.c
@@ -2291,6 +2291,7 @@ static int __init init_kprobes(void)
 		init_test_probes();
 	return err;
 }
+postcore_initcall(init_kprobes);
 
 #ifdef CONFIG_DEBUG_FS
 static void report_probe(struct seq_file *pi, struct kprobe *p,
@@ -2616,5 +2617,3 @@ static int __init debugfs_kprobe_init(void)
 
 late_initcall(debugfs_kprobe_init);
 #endif /* CONFIG_DEBUG_FS */
-
-module_init(init_kprobes);

[PATCH v2 2/2] tracing/kprobe: Add kprobe_event= boot parameter

[Masami Hiramatsu]

Add kprobe_event= boot parameter to define kprobe events
at boot time.
The definition syntax is similar to tracefs/kprobe_events
interface, but use ',' and ';' instead of ' ' and '\n'
respectively. e.g.

  kprobe_event=p,vfs_read,$arg1,$arg2

This puts a probe on vfs_read with argument1 and 2, and
enable the new event.

Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
---
 Documentation/admin-guide/kernel-parameters.txt |   13 ++++++
 Documentation/trace/kprobetrace.rst             |   14 ++++++
 kernel/trace/trace_kprobe.c                     |   54 +++++++++++++++++++++++
 3 files changed, 81 insertions(+)

diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt
index 2b8ee90bb644..96b22db7f763 100644
--- a/Documentation/admin-guide/kernel-parameters.txt
+++ b/Documentation/admin-guide/kernel-parameters.txt
@@ -2002,6 +2002,19 @@
 			Built with CONFIG_DEBUG_KMEMLEAK_DEFAULT_OFF=y,
 			the default is off.
 
+	kprobe_event=[probe-list]
+			[FTRACE] Add kprobe events and enable at boot time.
+			The probe-list is a semicolon delimited list of probe
+			definitions. Each definition is same as kprobe_events
+			interface, but the parameters are comma delimited.
+			For example, to add a kprobe event on vfs_read with
+			arg1 and arg2, add to the command line;
+
+			      kprobe_event=p,vfs_read,$arg1,$arg2
+
+			See also Documentation/trace/kprobetrace.rst "Kernel
+			Boot Parameter" section.
+
 	kpti=		[ARM64] Control page table isolation of user
 			and kernel address spaces.
 			Default: enabled on cores which need mitigation.
diff --git a/Documentation/trace/kprobetrace.rst b/Documentation/trace/kprobetrace.rst
index 235ce2ab131a..5b129215ba33 100644
--- a/Documentation/trace/kprobetrace.rst
+++ b/Documentation/trace/kprobetrace.rst
@@ -124,6 +124,20 @@ You can check the total number of probe hits and probe miss-hits via
 The first column is event name, the second is the number of probe hits,
 the third is the number of probe miss-hits.
 
+Kernel Boot Parameter
+---------------------
+You can add and enable new kprobe events when booting up the kernel by
+"kprobe_event=" parameter. The parameter accepts a semicolon-delimited
+kprobe events, which format is similar to the kprobe_events.
+The difference is that the probe definition parameters are comma-delimited
+instead of space. For example, adding myprobe event on do_sys_open like below
+
+  p:myprobe do_sys_open dfd=%ax filename=%dx flags=%cx mode=+4($stack)
+
+should be below for kernel boot parameter (just replace spaces with comma)
+
+  p:myprobe,do_sys_open,dfd=%ax,filename=%dx,flags=%cx,mode=+4($stack)
+
 
 Usage examples
 --------------
diff --git a/kernel/trace/trace_kprobe.c b/kernel/trace/trace_kprobe.c
index 7d736248a070..6983435ff017 100644
--- a/kernel/trace/trace_kprobe.c
+++ b/kernel/trace/trace_kprobe.c
@@ -12,6 +12,8 @@
 #include <linux/rculist.h>
 #include <linux/error-injection.h>
 
+#include <asm/setup.h>  /* for COMMAND_LINE_SIZE */
+
 #include "trace_dynevent.h"
 #include "trace_kprobe_selftest.h"
 #include "trace_probe.h"
@@ -19,6 +21,17 @@
 
 #define KPROBE_EVENT_SYSTEM "kprobes"
 #define KRETPROBE_MAXACTIVE_MAX 4096
+#define MAX_KPROBE_CMDLINE_SIZE 1024
+
+/* Kprobe early definition from command line */
+static char kprobe_boot_events_buf[COMMAND_LINE_SIZE] __initdata;
+
+static int __init set_kprobe_boot_events(char *str)
+{
+	strlcpy(kprobe_boot_events_buf, str, COMMAND_LINE_SIZE);
+	return 0;
+}
+__setup("kprobe_event=", set_kprobe_boot_events);
 
 static int trace_kprobe_create(int argc, const char **argv);
 static int trace_kprobe_show(struct seq_file *m, struct dyn_event *ev);
@@ -1450,6 +1463,44 @@ void destroy_local_trace_kprobe(struct trace_event_call *event_call)
 }
 #endif /* CONFIG_PERF_EVENTS */
 
+static __init void enable_boot_kprobe_events(void)
+{
+	struct trace_array *tr = top_trace_array();
+	struct trace_event_file *file;
+	struct trace_kprobe *tk;
+	struct dyn_event *pos;
+
+	mutex_lock(&event_mutex);
+	for_each_trace_kprobe(tk, pos) {
+		list_for_each_entry(file, &tr->events, list)
+			if (file->event_call == &tk->tp.call)
+				trace_event_enable_disable(file, 1, 0);
+	}
+	mutex_unlock(&event_mutex);
+}
+
+static __init void setup_boot_kprobe_events(void)
+{
+	char *p, *cmd = kprobe_boot_events_buf;
+	int ret;
+
+	strreplace(kprobe_boot_events_buf, ',', ' ');
+
+	while (cmd && *cmd != '\0') {
+		p = strchr(cmd, ';');
+		if (p)
+			*p++ = '\0';
+
+		ret = trace_run_command(cmd, create_or_delete_trace_kprobe);
+		if (ret)
+			pr_warn("Failed to add event(%d): %s\n", ret, cmd);
+
+		cmd = p;
+	}
+
+	enable_boot_kprobe_events();
+}
+
 /* Make a tracefs interface for controlling probe points */
 static __init int init_kprobe_trace(void)
 {
@@ -1481,6 +1532,9 @@ static __init int init_kprobe_trace(void)
 
 	if (!entry)
 		pr_warn("Could not create tracefs 'kprobe_profile' entry\n");
+
+	setup_boot_kprobe_events();
+
 	return 0;
 }
 fs_initcall(init_kprobe_trace);

Re: [PATCH v2 2/2] tracing/kprobe: Add kprobe_event= boot parameter

[Anders Roxell]

On Wed, 22 May 2019 at 10:32, Masami Hiramatsu <mhiramat@kernel.org> wrote:
>
> Add kprobe_event= boot parameter to define kprobe events
> at boot time.
> The definition syntax is similar to tracefs/kprobe_events
> interface, but use ',' and ';' instead of ' ' and '\n'
> respectively. e.g.
>
>   kprobe_event=p,vfs_read,$arg1,$arg2
>
> This puts a probe on vfs_read with argument1 and 2, and
> enable the new event.
>
> Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>

I built an arm64 kernel from todays linux-next tag next-20190528 and
ran in to this issue when I booted it up in qemu:

[    9.068772][    T1] CPU: 0 PID: 1 Comm: swapper/0 Not tainted
5.2.0-rc2-next-20190528-00019-g9a6008710716 #8
[    9.072893][    T1] Hardware name: linux,dummy-virt (DT)
[    9.075143][    T1] pstate: 80400005 (Nzcv daif +PAN -UAO)
[    9.077528][    T1] pc : kprobe_target+0x0/0x30
[    9.079479][    T1] lr : init_test_probes+0x134/0x540
[    9.081611][    T1] sp : ffff80003f51fbe0
[    9.083331][    T1] x29: ffff80003f51fbe0 x28: ffff200013c17820
[    9.085906][    T1] x27: ffff200015d3ab40 x26: ffff2000122bb120
[    9.088491][    T1] x25: 0000000000000000 x24: ffff200013c08ae0
[    9.091068][    T1] x23: ffff200015d39000 x22: ffff200013a15ac8
[    9.093667][    T1] x21: 1ffff00007ea3f86 x20: ffff200015d39420
[    9.096214][    T1] x19: ffff2000122bad20 x18: 0000000000001400
[    9.098831][    T1] x17: 0000000000000000 x16: ffff80003f510040
[    9.101410][    T1] x15: 0000000000001480 x14: 1ffff00007ea3ea2
[    9.103963][    T1] x13: 00000000f1f1f1f1 x12: ffff040002782e0d
[    9.106549][    T1] x11: 1fffe40002782e0c x10: ffff040002782e0c
[    9.109120][    T1] x9 : 1fffe40002782e0c x8 : dfff200000000000
[    9.111676][    T1] x7 : ffff040002782e0d x6 : ffff200013c17067
[    9.114234][    T1] x5 : ffff80003f510040 x4 : 0000000000000000
[    9.116843][    T1] x3 : ffff200010427508 x2 : 0000000000000000
[    9.119409][    T1] x1 : ffff200010426e10 x0 : 0000000000a6326b
[    9.121980][    T1] Call trace:
[    9.123380][    T1]  kprobe_target+0x0/0x30
[    9.125205][    T1]  init_kprobes+0x2b8/0x300
[    9.127074][    T1]  do_one_initcall+0x4c0/0xa68
[    9.129076][    T1]  kernel_init_freeable+0x3c4/0x4e4
[    9.131234][    T1]  kernel_init+0x14/0x1fc
[    9.133032][    T1]  ret_from_fork+0x10/0x18
[    9.134908][    T1] Code: a9446bf9 f9402bfb a8d87bfd d65f03c0 (d4200080)
[    9.137845][    T1] ---[ end trace 49243ee03446b072 ]---
[    9.140114][    T1] Kernel panic - not syncing: Fatal exception
[    9.142684][    T1] ---[ end Kernel panic - not syncing: Fatal exception ]---

I bisected down to this commit as the one that introduces this issue.
I'm unsure why this causes the call trace though, any ideas?

Cheers,
Anders

Re: [PATCH v2 2/2] tracing/kprobe: Add kprobe_event= boot parameter

[Steven Rostedt]

On Tue, 28 May 2019 14:23:43 +0200
Anders Roxell <anders.roxell@linaro.org> wrote:

> On Wed, 22 May 2019 at 10:32, Masami Hiramatsu <mhiramat@kernel.org> wrote:
> >
> > Add kprobe_event= boot parameter to define kprobe events
> > at boot time.
> > The definition syntax is similar to tracefs/kprobe_events
> > interface, but use ',' and ';' instead of ' ' and '\n'
> > respectively. e.g.
> >
> >   kprobe_event=p,vfs_read,$arg1,$arg2
> >
> > This puts a probe on vfs_read with argument1 and 2, and
> > enable the new event.
> >
> > Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>  
> 
> I built an arm64 kernel from todays linux-next tag next-20190528 and
> ran in to this issue when I booted it up in qemu:
> 

This is partial output from the crash. There should be more output
before this that says what happened to cause the crash.

-- Steve


> [    9.068772][    T1] CPU: 0 PID: 1 Comm: swapper/0 Not tainted
> 5.2.0-rc2-next-20190528-00019-g9a6008710716 #8
> [    9.072893][    T1] Hardware name: linux,dummy-virt (DT)
> [    9.075143][    T1] pstate: 80400005 (Nzcv daif +PAN -UAO)
> [    9.077528][    T1] pc : kprobe_target+0x0/0x30
> [    9.079479][    T1] lr : init_test_probes+0x134/0x540
> [    9.081611][    T1] sp : ffff80003f51fbe0
> [    9.083331][    T1] x29: ffff80003f51fbe0 x28: ffff200013c17820
> [    9.085906][    T1] x27: ffff200015d3ab40 x26: ffff2000122bb120
> [    9.088491][    T1] x25: 0000000000000000 x24: ffff200013c08ae0
> [    9.091068][    T1] x23: ffff200015d39000 x22: ffff200013a15ac8
> [    9.093667][    T1] x21: 1ffff00007ea3f86 x20: ffff200015d39420
> [    9.096214][    T1] x19: ffff2000122bad20 x18: 0000000000001400
> [    9.098831][    T1] x17: 0000000000000000 x16: ffff80003f510040
> [    9.101410][    T1] x15: 0000000000001480 x14: 1ffff00007ea3ea2
> [    9.103963][    T1] x13: 00000000f1f1f1f1 x12: ffff040002782e0d
> [    9.106549][    T1] x11: 1fffe40002782e0c x10: ffff040002782e0c
> [    9.109120][    T1] x9 : 1fffe40002782e0c x8 : dfff200000000000
> [    9.111676][    T1] x7 : ffff040002782e0d x6 : ffff200013c17067
> [    9.114234][    T1] x5 : ffff80003f510040 x4 : 0000000000000000
> [    9.116843][    T1] x3 : ffff200010427508 x2 : 0000000000000000
> [    9.119409][    T1] x1 : ffff200010426e10 x0 : 0000000000a6326b
> [    9.121980][    T1] Call trace:
> [    9.123380][    T1]  kprobe_target+0x0/0x30
> [    9.125205][    T1]  init_kprobes+0x2b8/0x300
> [    9.127074][    T1]  do_one_initcall+0x4c0/0xa68
> [    9.129076][    T1]  kernel_init_freeable+0x3c4/0x4e4
> [    9.131234][    T1]  kernel_init+0x14/0x1fc
> [    9.133032][    T1]  ret_from_fork+0x10/0x18
> [    9.134908][    T1] Code: a9446bf9 f9402bfb a8d87bfd d65f03c0 (d4200080)
> [    9.137845][    T1] ---[ end trace 49243ee03446b072 ]---
> [    9.140114][    T1] Kernel panic - not syncing: Fatal exception
> [    9.142684][    T1] ---[ end Kernel panic - not syncing: Fatal exception ]---
> 
> I bisected down to this commit as the one that introduces this issue.
> I'm unsure why this causes the call trace though, any ideas?
> 
> Cheers,
> Anders

Re: [PATCH v2 2/2] tracing/kprobe: Add kprobe_event= boot parameter

[Anders Roxell]

On Tue, 28 May 2019 at 14:36, Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Tue, 28 May 2019 14:23:43 +0200
> Anders Roxell <anders.roxell@linaro.org> wrote:
>
> > On Wed, 22 May 2019 at 10:32, Masami Hiramatsu <mhiramat@kernel.org> wrote:
> > >
> > > Add kprobe_event= boot parameter to define kprobe events
> > > at boot time.
> > > The definition syntax is similar to tracefs/kprobe_events
> > > interface, but use ',' and ';' instead of ' ' and '\n'
> > > respectively. e.g.
> > >
> > >   kprobe_event=p,vfs_read,$arg1,$arg2
> > >
> > > This puts a probe on vfs_read with argument1 and 2, and
> > > enable the new event.
> > >
> > > Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
> >
> > I built an arm64 kernel from todays linux-next tag next-20190528 and
> > ran in to this issue when I booted it up in qemu:
> >
>
> This is partial output from the crash. There should be more output
> before this that says what happened to cause the crash.

Oh I'm sorry.

Here is the full output

[    0.000000][    T0] Booting Linux on physical CPU 0x0000000000 [0x410fd034]
[    0.000000][    T0] Linux version
5.2.0-rc2-next-20190528-00019-g9a6008710716 (anders@compilator) (gcc
version 8.3.0 (Debian 8.3.0-2)) #8 SMP PREEMPT Tue May 28 11:47:57
CEST 2019
[    0.000000][    T0] Machine model: linux,dummy-virt
[    0.000000][    T0] earlycon: pl11 at MMIO 0x0000000009000000 (options '')
[    0.000000][    T0] printk: bootconsole [pl11] enabled
[    0.000000][    T0] efi: Getting EFI parameters from FDT:
[    0.000000][    T0] efi: UEFI not found.
[    0.000000][    T0] cma: Reserved 32 MiB at 0x00000000be000000
[    0.000000][    T0] kmemleak: Kernel memory leak detector disabled
[    0.000000][    T0] NUMA: No NUMA configuration found
[    0.000000][    T0] NUMA: Faking a node at [mem
0x0000000040000000-0x00000000bfffffff]
[    0.000000][    T0] NUMA: NODE_DATA [mem 0xbdbfd480-0xbdbfefff]
[    0.000000][    T0] Zone ranges:
[    0.000000][    T0]   DMA32    [mem 0x0000000040000000-0x00000000bfffffff]
[    0.000000][    T0]   Normal   empty
[    0.000000][    T0] Movable zone start for each node
[    0.000000][    T0] Early memory node ranges
[    0.000000][    T0]   node   0: [mem 0x0000000040000000-0x00000000bfffffff]
[    0.000000][    T0] Initmem setup node 0 [mem
0x0000000040000000-0x00000000bfffffff]
[    0.000000][    T0] kasan: KernelAddressSanitizer initialized
[    0.000000][    T0] psci: probing for conduit method from DT.
[    0.000000][    T0] psci: PSCIv1.0 detected in firmware.
[    0.000000][    T0] psci: Using standard PSCI v0.2 function IDs
[    0.000000][    T0] psci: Trusted OS migration not required
[    0.000000][    T0] psci: SMC Calling Convention v1.1
[    0.000000][    T0] percpu: Embedded 505 pages/cpu s2030744 r8192
d29544 u2068480
[    0.000000][    T0] Detected VIPT I-cache on CPU0
[    0.000000][    T0] CPU features: detected: ARM erratum 845719
[    0.000000][    T0] CPU features: GIC system register CPU interface
present but disabled by higher exception level
[    0.000000][    T0] node[0] zonelist: 0:DMA32
[    0.000000][    T0] Built 1 zonelists, mobility grouping on.  Total
pages: 516096
[    0.000000][    T0] Policy zone: DMA32
[    0.000000][    T0] Kernel command line: root=/dev/root
rootfstype=9p rootflags=trans=virtio console=ttyAMA0,38400n8
earlycon=pl011,0x9000000 initcall_debug softlockup_panic=0
security=none
[    0.000000][    T0] Memory: 942464K/2097152K available (33532K
kernel code, 24756K rwdata, 16956K rodata, 6144K init, 22215K bss,
420912K reserved, 32768K cma-reserved)
[    0.000000][    T0] random: get_random_u64 called from
kmem_cache_open+0x2c/0x580 with crng_init=0
[    0.000000][    T0] random: get_random_u64 called from
cache_random_seq_create+0x6c/0x1a8 with crng_init=0
[    0.000000][    T0] SLUB: HWalign=64, Order=0-3, MinObjects=0,
CPUs=1, Nodes=1
[    0.000000][    T0] random: get_random_u64 called from
kmem_cache_open+0x2c/0x580 with crng_init=0
[    0.000000][    T0] ODEBUG: selftest passed
[    0.000000][    T0] Running RCU self tests
[    0.000000][    T0] rcu: Preemptible hierarchical RCU implementation.
[    0.000000][    T0] rcu:     RCU event tracing is enabled.
[    0.000000][    T0] rcu:     RCU dyntick-idle grace-period
acceleration is enabled.
[    0.000000][    T0] rcu:     RCU lockdep checking is enabled.
[    0.000000][    T0] rcu:     RCU restricting CPUs from NR_CPUS=256
to nr_cpu_ids=1.
[    0.000000][    T0] rcu:     RCU priority boosting: priority 1 delay 500 ms.
[    0.000000][    T0] rcu:     RCU callback double-/use-after-free
debug enabled.
[    0.000000][    T0] rcu:     RCU debug extended QS entry/exit.
[    0.000000][    T0]  Tasks RCU enabled.
[    0.000000][    T0] rcu: RCU calculated value of
scheduler-enlistment delay is 25 jiffies.
[    0.000000][    T0] rcu: Adjusting geometry for rcu_fanout_leaf=16,
nr_cpu_ids=1
[    0.000000][    T0] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
[    0.000000][    T0] GICv2m: range[mem 0x08020000-0x08020fff], SPI[80:143]
[    0.000000][    T0] arch_timer: cp15 timer(s) running at 100.00MHz (virt).
[    0.000000][    T0] clocksource: arch_sys_counter: mask:
0xffffffffffffff max_cycles: 0x171024e7e0, max_idle_ns: 440795205315
ns
[    0.000041][    T0] sched_clock: 56 bits at 100MHz, resolution
10ns, wraps every 4398046511100ns
[    0.007303][    T0] Console: colour dummy device 80x25
[    0.012458][    T0] Lock dependency validator: Copyright (c) 2006
Red Hat, Inc., Ingo Molnar
[    0.016254][    T0] ... MAX_LOCKDEP_SUBCLASSES:  8
[    0.018260][    T0] ... MAX_LOCK_DEPTH:          48
[    0.020472][    T0] ... MAX_LOCKDEP_KEYS:        8191
[    0.022584][    T0] ... CLASSHASH_SIZE:          4096
[    0.024891][    T0] ... MAX_LOCKDEP_ENTRIES:     32768
[    0.027089][    T0] ... MAX_LOCKDEP_CHAINS:      65536
[    0.029532][    T0] ... CHAINHASH_SIZE:          32768
[    0.031812][    T0]  memory used by lock dependency info: 6747 kB
[    0.034789][    T0]  per task-struct memory footprint: 2688 bytes
[    0.037446][    T0] ------------------------
[    0.039583][    T0] | Locking API testsuite:
[    0.041539][    T0]
----------------------------------------------------------------------------
[    0.045659][    T0]                                  | spin |wlock
|rlock |mutex | wsem | rsem |
[    0.049470][    T0]
--------------------------------------------------------------------------
[    0.053770][    T0]                      A-A deadlock:  ok  |  ok
|  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.175649][    T0]                  A-B-B-A deadlock:  ok  |  ok
|  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.304904][    T0]              A-B-B-C-C-A deadlock:  ok  |  ok
|  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.441305][    T0]              A-B-C-A-B-C deadlock:  ok  |  ok
|  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.577838][    T0]          A-B-B-C-C-D-D-A deadlock:  ok  |  ok
|  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.721811][    T0]          A-B-C-D-B-D-D-A deadlock:  ok  |  ok
|  ok  |  ok  |  ok  |  ok  |  ok  |
[    0.866090][    T0]          A-B-C-D-B-C-D-A deadlock:  ok  |  ok
|  ok  |  ok  |  ok  |  ok  |  ok  |
[    1.009999][    T0]                     double unlock:  ok  |  ok
|  ok  |  ok  |  ok  |  ok  |  ok  |
[    1.131550][    T0]                   initialize held:  ok  |  ok
|  ok  |  ok  |  ok  |  ok  |  ok  |
[    1.250065][    T0]
--------------------------------------------------------------------------
[    1.254034][    T0]               recursive read-lock:
|  ok  |             |  ok  |
[    1.292322][    T0]            recursive read-lock #2:
|  ok  |             |  ok  |
[    1.329570][    T0]             mixed read-write-lock:
|  ok  |             |  ok  |
[    1.366837][    T0]             mixed write-read-lock:
|  ok  |             |  ok  |
[    1.404193][    T0]   mixed read-lock/lock-write ABBA:
|FAILED|             |  ok  |
[    1.440046][    T0]    mixed read-lock/lock-read ABBA:
|  ok  |             |  ok  |
[    1.479427][    T0]  mixed write-lock/lock-write ABBA:
|  ok  |             |  ok  |
[    1.518841][    T0]
--------------------------------------------------------------------------
[    1.526367][    T0]      hard-irqs-on + irq-safe-A/12:  ok  |  ok  |  ok  |
[    1.579733][    T0]      soft-irqs-on + irq-safe-A/12:  ok  |  ok  |  ok  |
[    1.633140][    T0]      hard-irqs-on + irq-safe-A/21:  ok  |  ok  |  ok  |
[    1.686438][    T0]      soft-irqs-on + irq-safe-A/21:  ok  |  ok  |  ok  |
[    1.739858][    T0]        sirq-safe-A => hirqs-on/12:  ok  |  ok  |  ok  |
[    1.793336][    T0]        sirq-safe-A => hirqs-on/21:  ok  |  ok  |  ok  |
[    1.846724][    T0]          hard-safe-A + irqs-on/12:  ok  |  ok  |  ok  |
[    1.900131][    T0]          soft-safe-A + irqs-on/12:  ok  |  ok  |  ok  |
[    1.953611][    T0]          hard-safe-A + irqs-on/21:  ok  |  ok  |  ok  |
[    2.007020][    T0]          soft-safe-A + irqs-on/21:  ok  |  ok  |  ok  |
[    2.060514][    T0]     hard-safe-A + unsafe-B #1/123:  ok  |  ok  |  ok  |
[    2.117068][    T0]     soft-safe-A + unsafe-B #1/123:  ok  |  ok  |  ok  |
[    2.173630][    T0]     hard-safe-A + unsafe-B #1/132:  ok  |  ok  |  ok  |
[    2.230160][    T0]     soft-safe-A + unsafe-B #1/132:  ok  |  ok  |  ok  |
[    2.286732][    T0]     hard-safe-A + unsafe-B #1/213:  ok  |  ok  |  ok  |
[    2.343298][    T0]     soft-safe-A + unsafe-B #1/213:  ok  |  ok  |  ok  |
[    2.399899][    T0]     hard-safe-A + unsafe-B #1/231:  ok  |  ok  |  ok  |
[    2.456366][    T0]     soft-safe-A + unsafe-B #1/231:  ok  |  ok  |  ok  |
[    2.512893][    T0]     hard-safe-A + unsafe-B #1/312:  ok  |  ok  |  ok  |
[    2.567341][    T0]     soft-safe-A + unsafe-B #1/312:  ok  |  ok  |  ok  |
[    2.621874][    T0]     hard-safe-A + unsafe-B #1/321:  ok  |  ok  |  ok  |
[    2.678319][    T0]     soft-safe-A + unsafe-B #1/321:  ok  |  ok  |  ok  |
[    2.734909][    T0]     hard-safe-A + unsafe-B #2/123:  ok  |  ok  |  ok  |
[    2.793422][    T0]     soft-safe-A + unsafe-B #2/123:  ok  |  ok  |  ok  |
[    2.850039][    T0]     hard-safe-A + unsafe-B #2/132:  ok  |  ok  |  ok  |
[    2.906635][    T0]     soft-safe-A + unsafe-B #2/132:  ok  |  ok  |  ok  |
[    2.963319][    T0]     hard-safe-A + unsafe-B #2/213:  ok  |  ok  |  ok  |
[    3.019876][    T0]     soft-safe-A + unsafe-B #2/213:  ok  |  ok  |  ok  |
[    3.076494][    T0]     hard-safe-A + unsafe-B #2/231:  ok  |  ok  |  ok  |
[    3.133040][    T0]     soft-safe-A + unsafe-B #2/231:  ok  |  ok  |  ok  |
[    3.189646][    T0]     hard-safe-A + unsafe-B #2/312:  ok  |  ok  |  ok  |
[    3.246206][    T0]     soft-safe-A + unsafe-B #2/312:  ok  |  ok  |  ok  |
[    3.302881][    T0]     hard-safe-A + unsafe-B #2/321:  ok  |  ok  |  ok  |
[    3.359434][    T0]     soft-safe-A + unsafe-B #2/321:  ok  |  ok  |  ok  |
[    3.416138][    T0]       hard-irq lock-inversion/123:  ok  |  ok  |  ok  |
[    3.472719][    T0]       soft-irq lock-inversion/123:  ok  |  ok  |  ok  |
[    3.529397][    T0]       hard-irq lock-inversion/132:  ok  |  ok  |  ok  |
[    3.585922][    T0]       soft-irq lock-inversion/132:  ok  |  ok  |  ok  |
[    3.642564][    T0]       hard-irq lock-inversion/213:  ok  |  ok  |  ok  |
[    3.699083][    T0]       soft-irq lock-inversion/213:  ok  |  ok  |  ok  |
[    3.755762][    T0]       hard-irq lock-inversion/231:  ok  |  ok  |  ok  |
[    3.812295][    T0]       soft-irq lock-inversion/231:  ok  |  ok  |  ok  |
[    3.868913][    T0]       hard-irq lock-inversion/312:  ok  |  ok  |  ok  |
[    3.925502][    T0]       soft-irq lock-inversion/312:  ok  |  ok  |  ok  |
[    3.982216][    T0]       hard-irq lock-inversion/321:  ok  |  ok  |  ok  |
[    4.038836][    T0]       soft-irq lock-inversion/321:  ok  |  ok  |  ok  |
[    4.095484][    T0]       hard-irq read-recursion/123:  ok  |
[    4.115858][    T0]       soft-irq read-recursion/123:  ok  |
[    4.136275][    T0]       hard-irq read-recursion/132:  ok  |
[    4.156655][    T0]       soft-irq read-recursion/132:  ok  |
[    4.177108][    T0]       hard-irq read-recursion/213:  ok  |
[    4.197524][    T0]       soft-irq read-recursion/213:  ok  |
[    4.217951][    T0]       hard-irq read-recursion/231:  ok  |
[    4.238361][    T0]       soft-irq read-recursion/231:  ok  |
[    4.258769][    T0]       hard-irq read-recursion/312:  ok  |
[    4.279146][    T0]       soft-irq read-recursion/312:  ok  |
[    4.299601][    T0]       hard-irq read-recursion/321:  ok  |
[    4.320000][    T0]       soft-irq read-recursion/321:  ok  |
[    4.340415][    T0]
--------------------------------------------------------------------------
[    4.344302][    T0]   | Wound/wait tests |
[    4.346060][    T0]   ---------------------
[    4.347804][    T0]                   ww api failures:  ok  |  ok  |  ok  |
[    4.403866][    T0]                ww contexts mixing:  ok  |  ok  |
[    4.441325][    T0]              finishing ww context:  ok  |  ok
|  ok  |  ok  |
[    4.513923][    T0]                locking mismatches:  ok  |  ok  |  ok  |
[    4.569425][    T0]                  EDEADLK handling:  ok  |  ok
|  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
[    4.756084][    T0]            spinlock nest unlocked:  ok  |
[    4.775442][    T0]   -----------------------------------------------------
[    4.778554][    T0]                                  |block | try  |context|
[    4.781423][    T0]   -----------------------------------------------------
[    4.784561][    T0]                           context:  ok  |  ok  |  ok  |
[    4.841364][    T0]                               try:  ok  |  ok  |  ok  |
[    4.895896][    T0]                             block:  ok  |  ok  |  ok  |
[    4.950507][    T0]                          spinlock:  ok  |  ok  |  ok  |
[    5.008309][    T0] -------------------------------------------------------
[    5.011499][    T0] Good, all 261 testcases passed! |
[    5.013625][    T0] ---------------------------------
[    5.016475][    T0] _warn_unseeded_randomness: 17 callbacks suppressed
[    5.016589][    T0] random: get_random_u64 called from
kmem_cache_open+0x2c/0x580 with crng_init=0
[    5.023654][    T0] random: get_random_u64 called from
cache_random_seq_create+0x6c/0x1a8 with crng_init=0
[    5.028321][    T0] random: get_random_u64 called from
kmem_cache_open+0x2c/0x580 with crng_init=0
[    5.033170][    T0] Calibrating delay loop (skipped), value
calculated using timer frequency.. 200.00 BogoMIPS (lpj=400000)
[    5.038026][    T0] pid_max: default: 32768 minimum: 301
[    5.048372][    T0] LSM: Security Framework initializing
[    5.051427][    T0] Yama: becoming mindful.
[    5.054542][    T0] LoadPin: ready to pin (currently enforcing)
[    5.091650][    T0] Dentry cache hash table entries: 262144 (order:
9, 2097152 bytes)
[    5.109677][    T0] Inode-cache hash table entries: 131072 (order:
8, 1048576 bytes)
[    5.115043][    T0] Mount-cache hash table entries: 4096 (order: 3,
32768 bytes)
[    5.119102][    T0] Mountpoint-cache hash table entries: 4096
(order: 3, 32768 bytes)
[    5.145756][    T0] *** VALIDATE proc ***
[    5.161518][    T0] *** VALIDATE cgroup1 ***
[    5.163416][    T0] *** VALIDATE cgroup2 ***
[    5.216366][    T1] ASID allocator initialised with 32768 entries
[    5.233346][    T1] rcu: Hierarchical SRCU implementation.
[    5.355951][    T1] EFI services will not be available.
[    5.390252][    T1] smp: Bringing up secondary CPUs ...
[    5.392549][    T1] smp: Brought up 1 node, 1 CPU
[    5.395021][    T1] SMP: Total of 1 processors activated.
[    5.397323][    T1] CPU features: detected: 32-bit EL0 Support
[    5.400043][    T1] CPU features: detected: CRC32 instructions
[    5.453529][    T1] CPU features: emulated: Privileged Access Never
(PAN) using TTBR0_EL1 switching
[    5.457701][    T1] CPU: All CPU(s) started at EL1
[    5.459924][   T13] alternatives: patching kernel code
[    7.488419][   T17] node 0 initialised, 175252 pages in 4ms
[    7.498797][   T17] pgdatinit0 (17) used greatest stack depth:
29312 bytes left
[    7.622979][    T1] devtmpfs: initialized
[    7.875584][    T1] Registered cp15_barrier emulation handler
[    7.878291][    T1] Registered setend emulation handler
[    7.885484][    T1] workqueue: round-robin CPU selection forced,
expect performance impact
[    7.921303][   T21] kworker/u2:0 (21) used greatest stack depth:
26864 bytes left
[    8.098703][    T1] DMA-API: preallocated 65536 debug entries
[    8.101639][    T1] DMA-API: debugging enabled by kernel config
[    8.104431][    T1] clocksource: jiffies: mask: 0xffffffff
max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    8.110343][    T1] futex hash table entries: 256 (order: 3, 32768 bytes)
[    8.315582][    T1] _warn_unseeded_randomness: 73 callbacks suppressed
[    8.315680][    T1] random: get_random_u64 called from
kmem_cache_open+0x2c/0x580 with crng_init=0
[    8.322746][    T1] random: get_random_u64 called from
cache_random_seq_create+0x6c/0x1a8 with crng_init=0
[    8.328032][    T1] random: get_random_u64 called from
kmem_cache_open+0x2c/0x580 with crng_init=0
[    8.342773][    T1] prandom: seed boundary self test passed
[    8.362169][    T1] prandom: 100 self tests passed
[    8.370915][    T1] pinctrl core: initialized pinctrl subsystem
[    8.429194][   T26] kworker/u2:1 (26) used greatest stack depth:
26320 bytes left
[    8.495363][   T32] kworker/u2:1 (32) used greatest stack depth:
26272 bytes left
[    8.743241][    T1]
[    8.750192][    T1]
*************************************************************
[    8.760037][    T1] **     NOTICE NOTICE NOTICE NOTICE NOTICE
NOTICE NOTICE    **
[    8.764666][    T1] **
           **
[    8.769961][    T1] **  IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN
THIS KERNEL  **
[    8.774188][    T1] **
           **
[    8.777236][    T1] ** This means that this kernel is built to
expose internal **
[    8.782049][    T1] ** IOMMU data structures, which may compromise
security on **
[    8.786179][    T1] ** your system.
           **
[    8.789225][    T1] **
           **
[    8.793520][    T1] ** If you see this message and you are not
debugging the   **
[    8.796556][    T1] ** kernel, report this immediately to your
vendor!         **
[    8.801025][    T1] **
           **
[    8.804360][    T1] **     NOTICE NOTICE NOTICE NOTICE NOTICE
NOTICE NOTICE    **
[    8.807379][    T1]
*************************************************************
[    8.880289][    T1] DMI not present or invalid.
[    8.945156][    T1] NET: Registered protocol family 16
[    8.965688][    T1] audit: initializing netlink subsys (disabled)
[    8.977767][   T57] audit: type=2000 audit(2.960:1):
state=initialized audit_enabled=0 res=1
[    9.020354][    T1] Kprobe smoke test: started
[    9.064132][    T1] Internal error: aarch64 BRK: f2000004 [#1] PREEMPT SMP
[    9.067084][    T1] Modules linked in:
[    9.068772][    T1] CPU: 0 PID: 1 Comm: swapper/0 Not tainted
5.2.0-rc2-next-20190528-00019-g9a6008710716 #8
[    9.072893][    T1] Hardware name: linux,dummy-virt (DT)
[    9.075143][    T1] pstate: 80400005 (Nzcv daif +PAN -UAO)
[    9.077528][    T1] pc : kprobe_target+0x0/0x30
[    9.079479][    T1] lr : init_test_probes+0x134/0x540
[    9.081611][    T1] sp : ffff80003f51fbe0
[    9.083331][    T1] x29: ffff80003f51fbe0 x28: ffff200013c17820
[    9.085906][    T1] x27: ffff200015d3ab40 x26: ffff2000122bb120
[    9.088491][    T1] x25: 0000000000000000 x24: ffff200013c08ae0
[    9.091068][    T1] x23: ffff200015d39000 x22: ffff200013a15ac8
[    9.093667][    T1] x21: 1ffff00007ea3f86 x20: ffff200015d39420
[    9.096214][    T1] x19: ffff2000122bad20 x18: 0000000000001400
[    9.098831][    T1] x17: 0000000000000000 x16: ffff80003f510040
[    9.101410][    T1] x15: 0000000000001480 x14: 1ffff00007ea3ea2
[    9.103963][    T1] x13: 00000000f1f1f1f1 x12: ffff040002782e0d
[    9.106549][    T1] x11: 1fffe40002782e0c x10: ffff040002782e0c
[    9.109120][    T1] x9 : 1fffe40002782e0c x8 : dfff200000000000
[    9.111676][    T1] x7 : ffff040002782e0d x6 : ffff200013c17067
[    9.114234][    T1] x5 : ffff80003f510040 x4 : 0000000000000000
[    9.116843][    T1] x3 : ffff200010427508 x2 : 0000000000000000
[    9.119409][    T1] x1 : ffff200010426e10 x0 : 0000000000a6326b
[    9.121980][    T1] Call trace:
[    9.123380][    T1]  kprobe_target+0x0/0x30
[    9.125205][    T1]  init_kprobes+0x2b8/0x300
[    9.127074][    T1]  do_one_initcall+0x4c0/0xa68
[    9.129076][    T1]  kernel_init_freeable+0x3c4/0x4e4
[    9.131234][    T1]  kernel_init+0x14/0x1fc
[    9.133032][    T1]  ret_from_fork+0x10/0x18
[    9.134908][    T1] Code: a9446bf9 f9402bfb a8d87bfd d65f03c0 (d4200080)
[    9.137845][    T1] ---[ end trace 49243ee03446b072 ]---
[    9.140114][    T1] Kernel panic - not syncing: Fatal exception
[    9.142684][    T1] ---[ end Kernel panic - not syncing: Fatal exception ]---


Cheers,
Anders

>
> -- Steve
>
>
> > [    9.068772][    T1] CPU: 0 PID: 1 Comm: swapper/0 Not tainted
> > 5.2.0-rc2-next-20190528-00019-g9a6008710716 #8
> > [    9.072893][    T1] Hardware name: linux,dummy-virt (DT)
> > [    9.075143][    T1] pstate: 80400005 (Nzcv daif +PAN -UAO)
> > [    9.077528][    T1] pc : kprobe_target+0x0/0x30
> > [    9.079479][    T1] lr : init_test_probes+0x134/0x540
> > [    9.081611][    T1] sp : ffff80003f51fbe0
> > [    9.083331][    T1] x29: ffff80003f51fbe0 x28: ffff200013c17820
> > [    9.085906][    T1] x27: ffff200015d3ab40 x26: ffff2000122bb120
> > [    9.088491][    T1] x25: 0000000000000000 x24: ffff200013c08ae0
> > [    9.091068][    T1] x23: ffff200015d39000 x22: ffff200013a15ac8
> > [    9.093667][    T1] x21: 1ffff00007ea3f86 x20: ffff200015d39420
> > [    9.096214][    T1] x19: ffff2000122bad20 x18: 0000000000001400
> > [    9.098831][    T1] x17: 0000000000000000 x16: ffff80003f510040
> > [    9.101410][    T1] x15: 0000000000001480 x14: 1ffff00007ea3ea2
> > [    9.103963][    T1] x13: 00000000f1f1f1f1 x12: ffff040002782e0d
> > [    9.106549][    T1] x11: 1fffe40002782e0c x10: ffff040002782e0c
> > [    9.109120][    T1] x9 : 1fffe40002782e0c x8 : dfff200000000000
> > [    9.111676][    T1] x7 : ffff040002782e0d x6 : ffff200013c17067
> > [    9.114234][    T1] x5 : ffff80003f510040 x4 : 0000000000000000
> > [    9.116843][    T1] x3 : ffff200010427508 x2 : 0000000000000000
> > [    9.119409][    T1] x1 : ffff200010426e10 x0 : 0000000000a6326b
> > [    9.121980][    T1] Call trace:
> > [    9.123380][    T1]  kprobe_target+0x0/0x30
> > [    9.125205][    T1]  init_kprobes+0x2b8/0x300
> > [    9.127074][    T1]  do_one_initcall+0x4c0/0xa68
> > [    9.129076][    T1]  kernel_init_freeable+0x3c4/0x4e4
> > [    9.131234][    T1]  kernel_init+0x14/0x1fc
> > [    9.133032][    T1]  ret_from_fork+0x10/0x18
> > [    9.134908][    T1] Code: a9446bf9 f9402bfb a8d87bfd d65f03c0 (d4200080)
> > [    9.137845][    T1] ---[ end trace 49243ee03446b072 ]---
> > [    9.140114][    T1] Kernel panic - not syncing: Fatal exception
> > [    9.142684][    T1] ---[ end Kernel panic - not syncing: Fatal exception ]---
> >
> > I bisected down to this commit as the one that introduces this issue.
> > I'm unsure why this causes the call trace though, any ideas?
> >
> > Cheers,
> > Anders
>

Re: [PATCH v2 2/2] tracing/kprobe: Add kprobe_event= boot parameter

[Masami Hiramatsu]

Hi Anders,

Sorry for replying later.

On Tue, 28 May 2019 15:39:15 +0200
Anders Roxell <anders.roxell@linaro.org> wrote:

> On Tue, 28 May 2019 at 14:36, Steven Rostedt <rostedt@goodmis.org> wrote:
> >
> > On Tue, 28 May 2019 14:23:43 +0200
> > Anders Roxell <anders.roxell@linaro.org> wrote:
> >
> > > On Wed, 22 May 2019 at 10:32, Masami Hiramatsu <mhiramat@kernel.org> wrote:
> > > >
> > > > Add kprobe_event= boot parameter to define kprobe events
> > > > at boot time.
> > > > The definition syntax is similar to tracefs/kprobe_events
> > > > interface, but use ',' and ';' instead of ' ' and '\n'
> > > > respectively. e.g.
> > > >
> > > >   kprobe_event=p,vfs_read,$arg1,$arg2
> > > >
> > > > This puts a probe on vfs_read with argument1 and 2, and
> > > > enable the new event.
> > > >
> > > > Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
> > >
> > > I built an arm64 kernel from todays linux-next tag next-20190528 and
> > > ran in to this issue when I booted it up in qemu:

Thank you for reporting!


> [    9.020354][    T1] Kprobe smoke test: started
> [    9.064132][    T1] Internal error: aarch64 BRK: f2000004 [#1] PREEMPT SMP
> [    9.067084][    T1] Modules linked in:
> [    9.068772][    T1] CPU: 0 PID: 1 Comm: swapper/0 Not tainted
> 5.2.0-rc2-next-20190528-00019-g9a6008710716 #8
> [    9.072893][    T1] Hardware name: linux,dummy-virt (DT)
> [    9.075143][    T1] pstate: 80400005 (Nzcv daif +PAN -UAO)
> [    9.077528][    T1] pc : kprobe_target+0x0/0x30
> [    9.079479][    T1] lr : init_test_probes+0x134/0x540
> [    9.081611][    T1] sp : ffff80003f51fbe0
> [    9.083331][    T1] x29: ffff80003f51fbe0 x28: ffff200013c17820
> [    9.085906][    T1] x27: ffff200015d3ab40 x26: ffff2000122bb120
> [    9.088491][    T1] x25: 0000000000000000 x24: ffff200013c08ae0
> [    9.091068][    T1] x23: ffff200015d39000 x22: ffff200013a15ac8
> [    9.093667][    T1] x21: 1ffff00007ea3f86 x20: ffff200015d39420
> [    9.096214][    T1] x19: ffff2000122bad20 x18: 0000000000001400
> [    9.098831][    T1] x17: 0000000000000000 x16: ffff80003f510040
> [    9.101410][    T1] x15: 0000000000001480 x14: 1ffff00007ea3ea2
> [    9.103963][    T1] x13: 00000000f1f1f1f1 x12: ffff040002782e0d
> [    9.106549][    T1] x11: 1fffe40002782e0c x10: ffff040002782e0c
> [    9.109120][    T1] x9 : 1fffe40002782e0c x8 : dfff200000000000
> [    9.111676][    T1] x7 : ffff040002782e0d x6 : ffff200013c17067
> [    9.114234][    T1] x5 : ffff80003f510040 x4 : 0000000000000000
> [    9.116843][    T1] x3 : ffff200010427508 x2 : 0000000000000000
> [    9.119409][    T1] x1 : ffff200010426e10 x0 : 0000000000a6326b
> [    9.121980][    T1] Call trace:
> [    9.123380][    T1]  kprobe_target+0x0/0x30
> [    9.125205][    T1]  init_kprobes+0x2b8/0x300
> [    9.127074][    T1]  do_one_initcall+0x4c0/0xa68
> [    9.129076][    T1]  kernel_init_freeable+0x3c4/0x4e4
> [    9.131234][    T1]  kernel_init+0x14/0x1fc
> [    9.133032][    T1]  ret_from_fork+0x10/0x18
> [    9.134908][    T1] Code: a9446bf9 f9402bfb a8d87bfd d65f03c0 (d4200080)
> [    9.137845][    T1] ---[ end trace 49243ee03446b072 ]---
> [    9.140114][    T1] Kernel panic - not syncing: Fatal exception
> [    9.142684][    T1] ---[ end Kernel panic - not syncing: Fatal exception ]---

Ah, I think you hit this in [1/2], not this change. 

I guess arm64's breakpoint handler is not initialized at postcore_initcall().
I have to check the arch depend implementation on arm64.


Thank you,

-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH v2 2/2] tracing/kprobe: Add kprobe_event= boot parameter

[Masami Hiramatsu]

On Mon, 3 Jun 2019 20:52:38 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> Hi Anders,
> 
> Sorry for replying later.
> 
> On Tue, 28 May 2019 15:39:15 +0200
> Anders Roxell <anders.roxell@linaro.org> wrote:
> 
> > On Tue, 28 May 2019 at 14:36, Steven Rostedt <rostedt@goodmis.org> wrote:
> > >
> > > On Tue, 28 May 2019 14:23:43 +0200
> > > Anders Roxell <anders.roxell@linaro.org> wrote:
> > >
> > > > On Wed, 22 May 2019 at 10:32, Masami Hiramatsu <mhiramat@kernel.org> wrote:
> > > > >
> > > > > Add kprobe_event= boot parameter to define kprobe events
> > > > > at boot time.
> > > > > The definition syntax is similar to tracefs/kprobe_events
> > > > > interface, but use ',' and ';' instead of ' ' and '\n'
> > > > > respectively. e.g.
> > > > >
> > > > >   kprobe_event=p,vfs_read,$arg1,$arg2
> > > > >
> > > > > This puts a probe on vfs_read with argument1 and 2, and
> > > > > enable the new event.
> > > > >
> > > > > Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
> > > >
> > > > I built an arm64 kernel from todays linux-next tag next-20190528 and
> > > > ran in to this issue when I booted it up in qemu:
> 
> Thank you for reporting!
> 
> 
> > [    9.020354][    T1] Kprobe smoke test: started
> > [    9.064132][    T1] Internal error: aarch64 BRK: f2000004 [#1] PREEMPT SMP
> > [    9.067084][    T1] Modules linked in:
> > [    9.068772][    T1] CPU: 0 PID: 1 Comm: swapper/0 Not tainted
> > 5.2.0-rc2-next-20190528-00019-g9a6008710716 #8
> > [    9.072893][    T1] Hardware name: linux,dummy-virt (DT)
> > [    9.075143][    T1] pstate: 80400005 (Nzcv daif +PAN -UAO)
> > [    9.077528][    T1] pc : kprobe_target+0x0/0x30
> > [    9.079479][    T1] lr : init_test_probes+0x134/0x540
> > [    9.081611][    T1] sp : ffff80003f51fbe0
> > [    9.083331][    T1] x29: ffff80003f51fbe0 x28: ffff200013c17820
> > [    9.085906][    T1] x27: ffff200015d3ab40 x26: ffff2000122bb120
> > [    9.088491][    T1] x25: 0000000000000000 x24: ffff200013c08ae0
> > [    9.091068][    T1] x23: ffff200015d39000 x22: ffff200013a15ac8
> > [    9.093667][    T1] x21: 1ffff00007ea3f86 x20: ffff200015d39420
> > [    9.096214][    T1] x19: ffff2000122bad20 x18: 0000000000001400
> > [    9.098831][    T1] x17: 0000000000000000 x16: ffff80003f510040
> > [    9.101410][    T1] x15: 0000000000001480 x14: 1ffff00007ea3ea2
> > [    9.103963][    T1] x13: 00000000f1f1f1f1 x12: ffff040002782e0d
> > [    9.106549][    T1] x11: 1fffe40002782e0c x10: ffff040002782e0c
> > [    9.109120][    T1] x9 : 1fffe40002782e0c x8 : dfff200000000000
> > [    9.111676][    T1] x7 : ffff040002782e0d x6 : ffff200013c17067
> > [    9.114234][    T1] x5 : ffff80003f510040 x4 : 0000000000000000
> > [    9.116843][    T1] x3 : ffff200010427508 x2 : 0000000000000000
> > [    9.119409][    T1] x1 : ffff200010426e10 x0 : 0000000000a6326b
> > [    9.121980][    T1] Call trace:
> > [    9.123380][    T1]  kprobe_target+0x0/0x30
> > [    9.125205][    T1]  init_kprobes+0x2b8/0x300
> > [    9.127074][    T1]  do_one_initcall+0x4c0/0xa68
> > [    9.129076][    T1]  kernel_init_freeable+0x3c4/0x4e4
> > [    9.131234][    T1]  kernel_init+0x14/0x1fc
> > [    9.133032][    T1]  ret_from_fork+0x10/0x18
> > [    9.134908][    T1] Code: a9446bf9 f9402bfb a8d87bfd d65f03c0 (d4200080)
> > [    9.137845][    T1] ---[ end trace 49243ee03446b072 ]---
> > [    9.140114][    T1] Kernel panic - not syncing: Fatal exception
> > [    9.142684][    T1] ---[ end Kernel panic - not syncing: Fatal exception ]---
> 
> Ah, I think you hit this in [1/2], not this change. 
> 
> I guess arm64's breakpoint handler is not initialized at postcore_initcall().
> I have to check the arch depend implementation on arm64.

Yes, for some reason, arm64 breakpoint handler vector is initalized in arch_initcall().
Let's move init_kprobes to subsys_initcall, which is called before fs_initcall.

Thank you,

-- 
Masami Hiramatsu <mhiramat@kernel.org>

[PATCH] kprobes: Fix to init kprobes in subsys_initcall

[Masami Hiramatsu]

Since arm64 kernel initializes breakpoint trap vector in arch_initcall(),
initializing kprobe (and run smoke test) in postcore_initcall() causes
a kernel panic.

To fix this issue, move the kprobe initialization in subsys_initcall()
(which is called right afer the arch_initcall).

In-kernel kprobe users (ftrace and bpf) are using fs_initcall() which is
called after subsys_initcall(), so this shouldn't cause more problem.

Reported-by: Anders Roxell <anders.roxell@linaro.org>
Fixes: b5f8b32c93b2 ("kprobes: Initialize kprobes at postcore_initcall")
Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
---
 kernel/kprobes.c |    2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/kernel/kprobes.c b/kernel/kprobes.c
index 54aaaad00a47..5471efbeb937 100644
--- a/kernel/kprobes.c
+++ b/kernel/kprobes.c
@@ -2289,7 +2289,7 @@ static int __init init_kprobes(void)
 		init_test_probes();
 	return err;
 }
-postcore_initcall(init_kprobes);
+subsys_initcall(init_kprobes);
 
 #ifdef CONFIG_DEBUG_FS
 static void report_probe(struct seq_file *pi, struct kprobe *p,

Re: [PATCH] kprobes: Fix to init kprobes in subsys_initcall

[Anders Roxell]

On Mon, 3 Jun 2019 at 15:04, Masami Hiramatsu <mhiramat@kernel.org> wrote:
>
> Since arm64 kernel initializes breakpoint trap vector in arch_initcall(),
> initializing kprobe (and run smoke test) in postcore_initcall() causes
> a kernel panic.
>
> To fix this issue, move the kprobe initialization in subsys_initcall()
> (which is called right afer the arch_initcall).
>
> In-kernel kprobe users (ftrace and bpf) are using fs_initcall() which is
> called after subsys_initcall(), so this shouldn't cause more problem.
>
> Reported-by: Anders Roxell <anders.roxell@linaro.org>
> Fixes: b5f8b32c93b2 ("kprobes: Initialize kprobes at postcore_initcall")
> Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>

Tested-by: Anders Roxell <anders.roxell@linaro.org>

Cheers,
Anders

> ---
>  kernel/kprobes.c |    2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/kernel/kprobes.c b/kernel/kprobes.c
> index 54aaaad00a47..5471efbeb937 100644
> --- a/kernel/kprobes.c
> +++ b/kernel/kprobes.c
> @@ -2289,7 +2289,7 @@ static int __init init_kprobes(void)
>                 init_test_probes();
>         return err;
>  }
> -postcore_initcall(init_kprobes);
> +subsys_initcall(init_kprobes);
>
>  #ifdef CONFIG_DEBUG_FS
>  static void report_probe(struct seq_file *pi, struct kprobe *p,
>

Re: [PATCH] kprobes: Fix to init kprobes in subsys_initcall

[Steven Rostedt]

On Mon,  3 Jun 2019 22:04:42 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> Since arm64 kernel initializes breakpoint trap vector in arch_initcall(),
> initializing kprobe (and run smoke test) in postcore_initcall() causes
> a kernel panic.
> 
> To fix this issue, move the kprobe initialization in subsys_initcall()
> (which is called right afer the arch_initcall).
> 
> In-kernel kprobe users (ftrace and bpf) are using fs_initcall() which is
> called after subsys_initcall(), so this shouldn't cause more problem.
> 
> Reported-by: Anders Roxell <anders.roxell@linaro.org>
> Fixes: b5f8b32c93b2 ("kprobes: Initialize kprobes at postcore_initcall")

Hi Masami,

Is this really a fix, or is this just needed to add kprobes to the command line?

-- Steve


> Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
> ---
>  kernel/kprobes.c |    2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/kernel/kprobes.c b/kernel/kprobes.c
> index 54aaaad00a47..5471efbeb937 100644
> --- a/kernel/kprobes.c
> +++ b/kernel/kprobes.c
> @@ -2289,7 +2289,7 @@ static int __init init_kprobes(void)
>  		init_test_probes();
>  	return err;
>  }
> -postcore_initcall(init_kprobes);
> +subsys_initcall(init_kprobes);
>  
>  #ifdef CONFIG_DEBUG_FS
>  static void report_probe(struct seq_file *pi, struct kprobe *p,

Re: [PATCH] kprobes: Fix to init kprobes in subsys_initcall

[Masami Hiramatsu]

On Tue, 4 Jun 2019 05:06:29 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Mon,  3 Jun 2019 22:04:42 +0900
> Masami Hiramatsu <mhiramat@kernel.org> wrote:
> 
> > Since arm64 kernel initializes breakpoint trap vector in arch_initcall(),
> > initializing kprobe (and run smoke test) in postcore_initcall() causes
> > a kernel panic.
> > 
> > To fix this issue, move the kprobe initialization in subsys_initcall()
> > (which is called right afer the arch_initcall).
> > 
> > In-kernel kprobe users (ftrace and bpf) are using fs_initcall() which is
> > called after subsys_initcall(), so this shouldn't cause more problem.
> > 
> > Reported-by: Anders Roxell <anders.roxell@linaro.org>
> > Fixes: b5f8b32c93b2 ("kprobes: Initialize kprobes at postcore_initcall")
> 
> Hi Masami,
> 
> Is this really a fix, or is this just needed to add kprobes to the command line?

Hi Steve,

Yes, this is a real fix, not related to the kprobes command line feature.

First of all, the problem was that kprobes(module_init) was initialized
later than trace_kprobe(fs_initcall). the commit b5f8b32c93b2 is to solve
it. But I missed that the break-point hander initialization can be done 
in arch_initcall on some archs. This is fixing that bug.

Thank you,


> 
> -- Steve
> 
> 
> > Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
> > ---
> >  kernel/kprobes.c |    2 +-
> >  1 file changed, 1 insertion(+), 1 deletion(-)
> > 
> > diff --git a/kernel/kprobes.c b/kernel/kprobes.c
> > index 54aaaad00a47..5471efbeb937 100644
> > --- a/kernel/kprobes.c
> > +++ b/kernel/kprobes.c
> > @@ -2289,7 +2289,7 @@ static int __init init_kprobes(void)
> >  		init_test_probes();
> >  	return err;
> >  }
> > -postcore_initcall(init_kprobes);
> > +subsys_initcall(init_kprobes);
> >  
> >  #ifdef CONFIG_DEBUG_FS
> >  static void report_probe(struct seq_file *pi, struct kprobe *p,
> 


-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH] kprobes: Fix to init kprobes in subsys_initcall

[Masami Hiramatsu]

Hi Steve,

Could you pick this to your ftrace/core branch?

Thank you,


On Mon,  3 Jun 2019 22:04:42 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> Since arm64 kernel initializes breakpoint trap vector in arch_initcall(),
> initializing kprobe (and run smoke test) in postcore_initcall() causes
> a kernel panic.
> 
> To fix this issue, move the kprobe initialization in subsys_initcall()
> (which is called right afer the arch_initcall).
> 
> In-kernel kprobe users (ftrace and bpf) are using fs_initcall() which is
> called after subsys_initcall(), so this shouldn't cause more problem.
> 
> Reported-by: Anders Roxell <anders.roxell@linaro.org>
> Fixes: b5f8b32c93b2 ("kprobes: Initialize kprobes at postcore_initcall")
> Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
> ---
>  kernel/kprobes.c |    2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/kernel/kprobes.c b/kernel/kprobes.c
> index 54aaaad00a47..5471efbeb937 100644
> --- a/kernel/kprobes.c
> +++ b/kernel/kprobes.c
> @@ -2289,7 +2289,7 @@ static int __init init_kprobes(void)
>  		init_test_probes();
>  	return err;
>  }
> -postcore_initcall(init_kprobes);
> +subsys_initcall(init_kprobes);
>  
>  #ifdef CONFIG_DEBUG_FS
>  static void report_probe(struct seq_file *pi, struct kprobe *p,
> 


-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH] kprobes: Fix to init kprobes in subsys_initcall

[Steven Rostedt]

On Wed, 12 Jun 2019 16:59:47 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> Hi Steve,
> 
> Could you pick this to your ftrace/core branch?

"core" or should this go to "urgent"? The difference is that core is
scheduled for the next merge window, and urgent is for the rc releases
(ie. bug fixes).

-- Steve

> 
> Thank you,
> 
> 

Re: [PATCH] kprobes: Fix to init kprobes in subsys_initcall

[Masami Hiramatsu]

On Wed, 12 Jun 2019 09:47:29 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Wed, 12 Jun 2019 16:59:47 +0900
> Masami Hiramatsu <mhiramat@kernel.org> wrote:
> 
> > Hi Steve,
> > 
> > Could you pick this to your ftrace/core branch?
> 
> "core" or should this go to "urgent"? The difference is that core is
> scheduled for the next merge window, and urgent is for the rc releases
> (ie. bug fixes).

If the previous one (b5f8b32c93b2) has already gone to rc, yes
this should be in urgent, since this always crashes arm64 kernel
if we enables CONFIG_KPROBES_SANITY_TEST.

Thank you,


-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH] kprobes: Fix to init kprobes in subsys_initcall

[Steven Rostedt]

On Thu, 13 Jun 2019 16:08:57 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> On Wed, 12 Jun 2019 09:47:29 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > On Wed, 12 Jun 2019 16:59:47 +0900
> > Masami Hiramatsu <mhiramat@kernel.org> wrote:
> >   
> > > Hi Steve,
> > > 
> > > Could you pick this to your ftrace/core branch?  
> > 
> > "core" or should this go to "urgent"? The difference is that core is
> > scheduled for the next merge window, and urgent is for the rc releases
> > (ie. bug fixes).  
> 
> If the previous one (b5f8b32c93b2) has already gone to rc, yes
> this should be in urgent, since this always crashes arm64 kernel
> if we enables CONFIG_KPROBES_SANITY_TEST.
> 

Ah, no it's not in -rc. I'll add it to my linux-next queue.

Thanks!

-- Steve