OpenCloudOS-Kernel/kernel/trace/trace_boot.c

379 lines
8.9 KiB
C
Raw Normal View History

// SPDX-License-Identifier: GPL-2.0
/*
* trace_boot.c
* Tracing kernel boot-time
*/
#define pr_fmt(fmt) "trace_boot: " fmt
#include <linux/bootconfig.h>
#include <linux/cpumask.h>
#include <linux/ftrace.h>
#include <linux/init.h>
#include <linux/kernel.h>
#include <linux/mutex.h>
#include <linux/string.h>
#include <linux/slab.h>
#include <linux/trace.h>
#include <linux/trace_events.h>
#include "trace.h"
#define MAX_BUF_LEN 256
static void __init
trace_boot_set_instance_options(struct trace_array *tr, struct xbc_node *node)
{
struct xbc_node *anode;
const char *p;
char buf[MAX_BUF_LEN];
unsigned long v = 0;
/* Common ftrace options */
xbc_node_for_each_array_value(node, "options", anode, p) {
if (strlcpy(buf, p, ARRAY_SIZE(buf)) >= ARRAY_SIZE(buf)) {
pr_err("String is too long: %s\n", p);
continue;
}
if (trace_set_options(tr, buf) < 0)
pr_err("Failed to set option: %s\n", buf);
}
p = xbc_node_find_value(node, "tracing_on", NULL);
if (p && *p != '\0') {
if (kstrtoul(p, 10, &v))
pr_err("Failed to set tracing on: %s\n", p);
if (v)
tracer_tracing_on(tr);
else
tracer_tracing_off(tr);
}
p = xbc_node_find_value(node, "trace_clock", NULL);
if (p && *p != '\0') {
if (tracing_set_clock(tr, p) < 0)
pr_err("Failed to set trace clock: %s\n", p);
}
p = xbc_node_find_value(node, "buffer_size", NULL);
if (p && *p != '\0') {
v = memparse(p, NULL);
if (v < PAGE_SIZE)
pr_err("Buffer size is too small: %s\n", p);
if (tracing_resize_ring_buffer(tr, v, RING_BUFFER_ALL_CPUS) < 0)
pr_err("Failed to resize trace buffer to %s\n", p);
}
p = xbc_node_find_value(node, "cpumask", NULL);
if (p && *p != '\0') {
cpumask_var_t new_mask;
if (alloc_cpumask_var(&new_mask, GFP_KERNEL)) {
if (cpumask_parse(p, new_mask) < 0 ||
tracing_set_cpumask(tr, new_mask) < 0)
pr_err("Failed to set new CPU mask %s\n", p);
free_cpumask_var(new_mask);
}
}
}
#ifdef CONFIG_EVENT_TRACING
static void __init
trace_boot_enable_events(struct trace_array *tr, struct xbc_node *node)
{
struct xbc_node *anode;
char buf[MAX_BUF_LEN];
const char *p;
xbc_node_for_each_array_value(node, "events", anode, p) {
if (strlcpy(buf, p, ARRAY_SIZE(buf)) >= ARRAY_SIZE(buf)) {
pr_err("String is too long: %s\n", p);
continue;
}
if (ftrace_set_clr_event(tr, buf, 1) < 0)
pr_err("Failed to enable event: %s\n", p);
}
}
#ifdef CONFIG_KPROBE_EVENTS
static int __init
trace_boot_add_kprobe_event(struct xbc_node *node, const char *event)
{
struct dynevent_cmd cmd;
struct xbc_node *anode;
char buf[MAX_BUF_LEN];
const char *val;
int ret = 0;
xbc_node_for_each_array_value(node, "probes", anode, val) {
kprobe_event_cmd_init(&cmd, buf, MAX_BUF_LEN);
ret = kprobe_event_gen_cmd_start(&cmd, event, val);
tracing/boottime: Fix kprobe multiple events Fix boottime kprobe events to report and abort after each failure when adding probes. As an example, when we try to set multiprobe kprobe events in bootconfig like this: ftrace.event.kprobes.vfsevents { probes = "vfs_read $arg1 $arg2,, !error! not reported;?", // leads to error "vfs_write $arg1 $arg2" } This will not work as expected. After commit da0f1f4167e3af69e ("tracing/boottime: Fix kprobe event API usage"), the function trace_boot_add_kprobe_event will not produce any error message when adding a probe fails at kprobe_event_gen_cmd_start. Furthermore, we continue to add probes when kprobe_event_gen_cmd_end fails (and kprobe_event_gen_cmd_start did not fail). In this case the function even returns successfully when the last call to kprobe_event_gen_cmd_end is successful. The behaviour of reporting and aborting after failures is not consistent. The function trace_boot_add_kprobe_event now reports each failure and stops adding probes immediately. Link: https://lkml.kernel.org/r/20200618163301.25854-1-sascha.ortmann@stud.uni-hannover.de Cc: stable@vger.kernel.org Cc: linux-kernel@i4.cs.fau.de Co-developed-by: Maximilian Werner <maximilian.werner96@gmail.com> Fixes: da0f1f4167e3 ("tracing/boottime: Fix kprobe event API usage") Acked-by: Masami Hiramatsu <mhiramat@kernel.org> Signed-off-by: Maximilian Werner <maximilian.werner96@gmail.com> Signed-off-by: Sascha Ortmann <sascha.ortmann@stud.uni-hannover.de> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
2020-06-19 00:33:01 +08:00
if (ret) {
pr_err("Failed to generate probe: %s\n", buf);
break;
tracing/boottime: Fix kprobe multiple events Fix boottime kprobe events to report and abort after each failure when adding probes. As an example, when we try to set multiprobe kprobe events in bootconfig like this: ftrace.event.kprobes.vfsevents { probes = "vfs_read $arg1 $arg2,, !error! not reported;?", // leads to error "vfs_write $arg1 $arg2" } This will not work as expected. After commit da0f1f4167e3af69e ("tracing/boottime: Fix kprobe event API usage"), the function trace_boot_add_kprobe_event will not produce any error message when adding a probe fails at kprobe_event_gen_cmd_start. Furthermore, we continue to add probes when kprobe_event_gen_cmd_end fails (and kprobe_event_gen_cmd_start did not fail). In this case the function even returns successfully when the last call to kprobe_event_gen_cmd_end is successful. The behaviour of reporting and aborting after failures is not consistent. The function trace_boot_add_kprobe_event now reports each failure and stops adding probes immediately. Link: https://lkml.kernel.org/r/20200618163301.25854-1-sascha.ortmann@stud.uni-hannover.de Cc: stable@vger.kernel.org Cc: linux-kernel@i4.cs.fau.de Co-developed-by: Maximilian Werner <maximilian.werner96@gmail.com> Fixes: da0f1f4167e3 ("tracing/boottime: Fix kprobe event API usage") Acked-by: Masami Hiramatsu <mhiramat@kernel.org> Signed-off-by: Maximilian Werner <maximilian.werner96@gmail.com> Signed-off-by: Sascha Ortmann <sascha.ortmann@stud.uni-hannover.de> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
2020-06-19 00:33:01 +08:00
}
ret = kprobe_event_gen_cmd_end(&cmd);
tracing/boottime: Fix kprobe multiple events Fix boottime kprobe events to report and abort after each failure when adding probes. As an example, when we try to set multiprobe kprobe events in bootconfig like this: ftrace.event.kprobes.vfsevents { probes = "vfs_read $arg1 $arg2,, !error! not reported;?", // leads to error "vfs_write $arg1 $arg2" } This will not work as expected. After commit da0f1f4167e3af69e ("tracing/boottime: Fix kprobe event API usage"), the function trace_boot_add_kprobe_event will not produce any error message when adding a probe fails at kprobe_event_gen_cmd_start. Furthermore, we continue to add probes when kprobe_event_gen_cmd_end fails (and kprobe_event_gen_cmd_start did not fail). In this case the function even returns successfully when the last call to kprobe_event_gen_cmd_end is successful. The behaviour of reporting and aborting after failures is not consistent. The function trace_boot_add_kprobe_event now reports each failure and stops adding probes immediately. Link: https://lkml.kernel.org/r/20200618163301.25854-1-sascha.ortmann@stud.uni-hannover.de Cc: stable@vger.kernel.org Cc: linux-kernel@i4.cs.fau.de Co-developed-by: Maximilian Werner <maximilian.werner96@gmail.com> Fixes: da0f1f4167e3 ("tracing/boottime: Fix kprobe event API usage") Acked-by: Masami Hiramatsu <mhiramat@kernel.org> Signed-off-by: Maximilian Werner <maximilian.werner96@gmail.com> Signed-off-by: Sascha Ortmann <sascha.ortmann@stud.uni-hannover.de> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
2020-06-19 00:33:01 +08:00
if (ret) {
pr_err("Failed to add probe: %s\n", buf);
tracing/boottime: Fix kprobe multiple events Fix boottime kprobe events to report and abort after each failure when adding probes. As an example, when we try to set multiprobe kprobe events in bootconfig like this: ftrace.event.kprobes.vfsevents { probes = "vfs_read $arg1 $arg2,, !error! not reported;?", // leads to error "vfs_write $arg1 $arg2" } This will not work as expected. After commit da0f1f4167e3af69e ("tracing/boottime: Fix kprobe event API usage"), the function trace_boot_add_kprobe_event will not produce any error message when adding a probe fails at kprobe_event_gen_cmd_start. Furthermore, we continue to add probes when kprobe_event_gen_cmd_end fails (and kprobe_event_gen_cmd_start did not fail). In this case the function even returns successfully when the last call to kprobe_event_gen_cmd_end is successful. The behaviour of reporting and aborting after failures is not consistent. The function trace_boot_add_kprobe_event now reports each failure and stops adding probes immediately. Link: https://lkml.kernel.org/r/20200618163301.25854-1-sascha.ortmann@stud.uni-hannover.de Cc: stable@vger.kernel.org Cc: linux-kernel@i4.cs.fau.de Co-developed-by: Maximilian Werner <maximilian.werner96@gmail.com> Fixes: da0f1f4167e3 ("tracing/boottime: Fix kprobe event API usage") Acked-by: Masami Hiramatsu <mhiramat@kernel.org> Signed-off-by: Maximilian Werner <maximilian.werner96@gmail.com> Signed-off-by: Sascha Ortmann <sascha.ortmann@stud.uni-hannover.de> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
2020-06-19 00:33:01 +08:00
break;
}
}
return ret;
}
#else
static inline int __init
trace_boot_add_kprobe_event(struct xbc_node *node, const char *event)
{
pr_err("Kprobe event is not supported.\n");
return -ENOTSUPP;
}
#endif
#ifdef CONFIG_SYNTH_EVENTS
static int __init
trace_boot_add_synth_event(struct xbc_node *node, const char *event)
{
struct dynevent_cmd cmd;
struct xbc_node *anode;
char buf[MAX_BUF_LEN];
const char *p;
int ret;
synth_event_cmd_init(&cmd, buf, MAX_BUF_LEN);
ret = synth_event_gen_cmd_start(&cmd, event, NULL);
if (ret)
return ret;
xbc_node_for_each_array_value(node, "fields", anode, p) {
ret = synth_event_add_field_str(&cmd, p);
if (ret)
return ret;
}
ret = synth_event_gen_cmd_end(&cmd);
if (ret < 0)
pr_err("Failed to add synthetic event: %s\n", buf);
return ret;
}
#else
static inline int __init
trace_boot_add_synth_event(struct xbc_node *node, const char *event)
{
pr_err("Synthetic event is not supported.\n");
return -ENOTSUPP;
}
#endif
static void __init
trace_boot_init_one_event(struct trace_array *tr, struct xbc_node *gnode,
struct xbc_node *enode)
{
struct trace_event_file *file;
struct xbc_node *anode;
char buf[MAX_BUF_LEN];
const char *p, *group, *event;
group = xbc_node_get_data(gnode);
event = xbc_node_get_data(enode);
if (!strcmp(group, "kprobes"))
if (trace_boot_add_kprobe_event(enode, event) < 0)
return;
if (!strcmp(group, "synthetic"))
if (trace_boot_add_synth_event(enode, event) < 0)
return;
mutex_lock(&event_mutex);
file = find_event_file(tr, group, event);
if (!file) {
pr_err("Failed to find event: %s:%s\n", group, event);
goto out;
}
p = xbc_node_find_value(enode, "filter", NULL);
if (p && *p != '\0') {
if (strlcpy(buf, p, ARRAY_SIZE(buf)) >= ARRAY_SIZE(buf))
pr_err("filter string is too long: %s\n", p);
else if (apply_event_filter(file, buf) < 0)
pr_err("Failed to apply filter: %s\n", buf);
}
xbc_node_for_each_array_value(enode, "actions", anode, p) {
if (strlcpy(buf, p, ARRAY_SIZE(buf)) >= ARRAY_SIZE(buf))
pr_err("action string is too long: %s\n", p);
else if (trigger_process_regex(file, buf) < 0)
pr_err("Failed to apply an action: %s\n", buf);
}
if (xbc_node_find_value(enode, "enable", NULL)) {
if (trace_event_enable_disable(file, 1, 0) < 0)
pr_err("Failed to enable event node: %s:%s\n",
group, event);
}
out:
mutex_unlock(&event_mutex);
}
static void __init
trace_boot_init_events(struct trace_array *tr, struct xbc_node *node)
{
struct xbc_node *gnode, *enode;
bool enable, enable_all = false;
const char *data;
node = xbc_node_find_child(node, "event");
if (!node)
return;
/* per-event key starts with "event.GROUP.EVENT" */
xbc_node_for_each_child(node, gnode) {
data = xbc_node_get_data(gnode);
if (!strcmp(data, "enable")) {
enable_all = true;
continue;
}
enable = false;
xbc_node_for_each_child(gnode, enode) {
data = xbc_node_get_data(enode);
if (!strcmp(data, "enable")) {
enable = true;
continue;
}
trace_boot_init_one_event(tr, gnode, enode);
}
/* Event enablement must be done after event settings */
if (enable) {
data = xbc_node_get_data(gnode);
trace_array_set_clr_event(tr, data, NULL, true);
}
}
/* Ditto */
if (enable_all)
trace_array_set_clr_event(tr, NULL, NULL, true);
}
#else
#define trace_boot_enable_events(tr, node) do {} while (0)
#define trace_boot_init_events(tr, node) do {} while (0)
#endif
#ifdef CONFIG_DYNAMIC_FTRACE
static void __init
trace_boot_set_ftrace_filter(struct trace_array *tr, struct xbc_node *node)
{
struct xbc_node *anode;
const char *p;
char *q;
xbc_node_for_each_array_value(node, "ftrace.filters", anode, p) {
q = kstrdup(p, GFP_KERNEL);
if (!q)
return;
if (ftrace_set_filter(tr->ops, q, strlen(q), 0) < 0)
pr_err("Failed to add %s to ftrace filter\n", p);
else
ftrace_filter_param = true;
kfree(q);
}
xbc_node_for_each_array_value(node, "ftrace.notraces", anode, p) {
q = kstrdup(p, GFP_KERNEL);
if (!q)
return;
if (ftrace_set_notrace(tr->ops, q, strlen(q), 0) < 0)
pr_err("Failed to add %s to ftrace filter\n", p);
else
ftrace_filter_param = true;
kfree(q);
}
}
#else
#define trace_boot_set_ftrace_filter(tr, node) do {} while (0)
#endif
static void __init
trace_boot_enable_tracer(struct trace_array *tr, struct xbc_node *node)
{
const char *p;
trace_boot_set_ftrace_filter(tr, node);
p = xbc_node_find_value(node, "tracer", NULL);
if (p && *p != '\0') {
if (tracing_set_tracer(tr, p) < 0)
pr_err("Failed to set given tracer: %s\n", p);
}
/* Since tracer can free snapshot buffer, allocate snapshot here.*/
if (xbc_node_find_value(node, "alloc_snapshot", NULL)) {
if (tracing_alloc_snapshot_instance(tr) < 0)
pr_err("Failed to allocate snapshot buffer\n");
}
}
static void __init
trace_boot_init_one_instance(struct trace_array *tr, struct xbc_node *node)
{
trace_boot_set_instance_options(tr, node);
trace_boot_init_events(tr, node);
trace_boot_enable_events(tr, node);
trace_boot_enable_tracer(tr, node);
}
static void __init
trace_boot_init_instances(struct xbc_node *node)
{
struct xbc_node *inode;
struct trace_array *tr;
const char *p;
node = xbc_node_find_child(node, "instance");
if (!node)
return;
xbc_node_for_each_child(node, inode) {
p = xbc_node_get_data(inode);
if (!p || *p == '\0')
continue;
tr = trace_array_get_by_name(p);
if (!tr) {
pr_err("Failed to get trace instance %s\n", p);
continue;
}
trace_boot_init_one_instance(tr, inode);
trace_array_put(tr);
}
}
static int __init trace_boot_init(void)
{
struct xbc_node *trace_node;
struct trace_array *tr;
trace_node = xbc_find_node("ftrace");
if (!trace_node)
return 0;
tr = top_trace_array();
if (!tr)
return 0;
/* Global trace array is also one instance */
trace_boot_init_one_instance(tr, trace_node);
trace_boot_init_instances(trace_node);
tracing: Disable ftrace selftests when any tracer is running Disable ftrace selftests when any tracer (kernel command line options like ftrace=, trace_events=, kprobe_events=, and boot-time tracing) starts running because selftest can disturb it. Currently ftrace= and trace_events= are checked, but kprobe_events has a different flag, and boot-time tracing didn't checked. This unifies the disabled flag and all of those boot-time tracing features sets the flag. This also fixes warnings on kprobe-event selftest (CONFIG_FTRACE_STARTUP_TEST=y and CONFIG_KPROBE_EVENTS=y) with boot-time tracing (ftrace.event.kprobes.EVENT.probes) like below; [ 59.803496] trace_kprobe: Testing kprobe tracing: [ 59.804258] ------------[ cut here ]------------ [ 59.805682] WARNING: CPU: 3 PID: 1 at kernel/trace/trace_kprobe.c:1987 kprobe_trace_self_tests_ib [ 59.806944] Modules linked in: [ 59.807335] CPU: 3 PID: 1 Comm: swapper/0 Not tainted 5.10.0-rc7+ #172 [ 59.808029] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-1ubuntu1 04/01/204 [ 59.808999] RIP: 0010:kprobe_trace_self_tests_init+0x5f/0x42b [ 59.809696] Code: e8 03 00 00 48 c7 c7 30 8e 07 82 e8 6d 3c 46 ff 48 c7 c6 00 b2 1a 81 48 c7 c7 7 [ 59.812439] RSP: 0018:ffffc90000013e78 EFLAGS: 00010282 [ 59.813038] RAX: 00000000ffffffef RBX: 0000000000000000 RCX: 0000000000049443 [ 59.813780] RDX: 0000000000049403 RSI: 0000000000049403 RDI: 000000000002deb0 [ 59.814589] RBP: ffffc90000013e90 R08: 0000000000000001 R09: 0000000000000001 [ 59.815349] R10: 0000000000000001 R11: 0000000000000000 R12: 00000000ffffffef [ 59.816138] R13: ffff888004613d80 R14: ffffffff82696940 R15: ffff888004429138 [ 59.816877] FS: 0000000000000000(0000) GS:ffff88807dcc0000(0000) knlGS:0000000000000000 [ 59.817772] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 59.818395] CR2: 0000000001a8dd38 CR3: 0000000002222000 CR4: 00000000000006a0 [ 59.819144] Call Trace: [ 59.819469] ? init_kprobe_trace+0x6b/0x6b [ 59.819948] do_one_initcall+0x5f/0x300 [ 59.820392] ? rcu_read_lock_sched_held+0x4f/0x80 [ 59.820916] kernel_init_freeable+0x22a/0x271 [ 59.821416] ? rest_init+0x241/0x241 [ 59.821841] kernel_init+0xe/0x10f [ 59.822251] ret_from_fork+0x22/0x30 [ 59.822683] irq event stamp: 16403349 [ 59.823121] hardirqs last enabled at (16403359): [<ffffffff810db81e>] console_unlock+0x48e/0x580 [ 59.824074] hardirqs last disabled at (16403368): [<ffffffff810db786>] console_unlock+0x3f6/0x580 [ 59.825036] softirqs last enabled at (16403200): [<ffffffff81c0033a>] __do_softirq+0x33a/0x484 [ 59.825982] softirqs last disabled at (16403087): [<ffffffff81a00f02>] asm_call_irq_on_stack+0x10 [ 59.827034] ---[ end trace 200c544775cdfeb3 ]--- [ 59.827635] trace_kprobe: error on probing function entry. Link: https://lkml.kernel.org/r/160741764955.3448999.3347769358299456915.stgit@devnote2 Fixes: 4d655281eb1b ("tracing/boot Add kprobe event support") Cc: Ingo Molnar <mingo@kernel.org> Cc: stable@vger.kernel.org Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
2020-12-08 16:54:09 +08:00
disable_tracing_selftest("running boot-time tracing");
return 0;
}
/*
* Start tracing at the end of core-initcall, so that it starts tracing
* from the beginning of postcore_initcall.
*/
core_initcall_sync(trace_boot_init);