2019-05-22 08:33:53

by Masami Hiramatsu

[permalink] [raw]
Subject: [PATCH v2 0/2] Enable new kprobe event at boot

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)


2019-05-22 08:34:05

by Masami Hiramatsu

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

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 <[email protected]>
---
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);

2019-05-22 08:35:17

by Masami Hiramatsu

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

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 <[email protected]>
---
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);

2019-05-28 12:26:09

by Anders Roxell

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

On Wed, 22 May 2019 at 10:32, Masami Hiramatsu <[email protected]> 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 <[email protected]>

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

2019-05-28 13:42:12

by Anders Roxell

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

On Tue, 28 May 2019 at 14:36, Steven Rostedt <[email protected]> wrote:
>
> On Tue, 28 May 2019 14:23:43 +0200
> Anders Roxell <[email protected]> wrote:
>
> > On Wed, 22 May 2019 at 10:32, Masami Hiramatsu <[email protected]> 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 <[email protected]>
> >
> > 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
>

2019-05-28 15:06:08

by Steven Rostedt

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

On Tue, 28 May 2019 14:23:43 +0200
Anders Roxell <[email protected]> wrote:

> On Wed, 22 May 2019 at 10:32, Masami Hiramatsu <[email protected]> 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 <[email protected]>
>
> 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

2019-06-03 16:59:02

by Masami Hiramatsu

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

On Mon, 3 Jun 2019 20:52:38 +0900
Masami Hiramatsu <[email protected]> wrote:

> Hi Anders,
>
> Sorry for replying later.
>
> On Tue, 28 May 2019 15:39:15 +0200
> Anders Roxell <[email protected]> wrote:
>
> > On Tue, 28 May 2019 at 14:36, Steven Rostedt <[email protected]> wrote:
> > >
> > > On Tue, 28 May 2019 14:23:43 +0200
> > > Anders Roxell <[email protected]> wrote:
> > >
> > > > On Wed, 22 May 2019 at 10:32, Masami Hiramatsu <[email protected]> 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 <[email protected]>
> > > >
> > > > 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 <[email protected]>

2019-06-03 18:01:36

by Masami Hiramatsu

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

Hi Anders,

Sorry for replying later.

On Tue, 28 May 2019 15:39:15 +0200
Anders Roxell <[email protected]> wrote:

> On Tue, 28 May 2019 at 14:36, Steven Rostedt <[email protected]> wrote:
> >
> > On Tue, 28 May 2019 14:23:43 +0200
> > Anders Roxell <[email protected]> wrote:
> >
> > > On Wed, 22 May 2019 at 10:32, Masami Hiramatsu <[email protected]> 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 <[email protected]>
> > >
> > > 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 <[email protected]>