Introduce a method based on function tracer to trace any object and get
the value of the object dynamically. the object can be obtained from the
dynamic event (kprobe_event/uprobe_event) or the static event(tracepoint).
Usage:
When using the kprobe event, only need to set the objtrace(a new trigger),
we can get the value of the object. The object is from the setting of the
kprobe event.
For example:
For the function bio_add_page():
int bio_add_page(struct bio *bio, struct page *page,
unsigned int len, unsigned int offset)
Firstly, we can set the base of the object, thus the first string "arg1"
stands for the value of the first parameter of this function bio_add_gage(),
# echo 'p bio_add_page arg1=$arg1' > ./kprobe_events
Secondly, we can get the value dynamically based on above object.
find the offset of the bi_size in struct bio:
$ gdb vmlinux
(gdb) p &(((struct bio *)0)->bi_iter.bi_size)
$1 = (unsigned int *) 0x28
# echo 'objtrace:add:arg1,0x28:u32:1 if comm == "cat"' > ./events/kprobes/ \
p_bio_add_page_0/trigger
# cd /sys/kernel/debug/tracing/
# echo 'p bio_add_page arg1=$arg1' > ./kprobe_events
# echo 'objtrace:add:arg1,0x28:u32:1 if comm == "cat"' > ./events/kprobes/p_bio_add_page_0/trigger
# du -sh /test.txt
12.0K /test.txt
# cat /test.txt > /dev/null
# cat ./trace
# tracer: nop
#
# entries-in-buffer/entries-written: 128/128 #P:4
#
# _-----=> irqs-off/BH-disabled
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / _-=> migrate-disable
# |||| / delay
# TASK-PID CPU# ||||| TIMESTAMP FUNCTION
# | | | ||||| | |
cat-117 [002] ...1. 1.602243: __bio_try_merge_page <-bio_add_page object:0xffff88811bee4000 value:0x0
cat-117 [002] ...1. 1.602244: __bio_add_page <-bio_add_page object:0xffff88811bee4000 value:0x0
cat-117 [002] ...2. 1.602244: bio_add_page <-ext4_mpage_readpages object:0xffff88811bee4000 value:0x1000
cat-117 [002] ...1. 1.602245: __bio_try_merge_page <-bio_add_page object:0xffff88811bee4000 value:0x1000
cat-117 [002] ...1. 1.602245: __bio_add_page <-bio_add_page object:0xffff88811bee4000 value:0x1000
cat-117 [002] ...2. 1.602245: bio_add_page <-ext4_mpage_readpages object:0xffff88811bee4000 value:0x2000
cat-117 [002] ...1. 1.602245: __bio_try_merge_page <-bio_add_page object:0xffff88811bee4000 value:0x2000
cat-117 [002] ...1. 1.602245: __bio_add_page <-bio_add_page object:0xffff88811bee4000 value:0x2000
cat-117 [002] ...1. 1.602245: submit_bio <-ext4_mpage_readpages object:0xffff88811bee4000 value:0x3000
cat-117 [002] ...1. 1.602245: submit_bio_noacct <-ext4_mpage_readpages object:0xffff88811bee4000 value:0x3000
cat-117 [002] ...1. 1.602246: __submit_bio <-submit_bio_noacct object:0xffff88811bee4000 value:0x3000
cat-117 [002] ...1. 1.602246: submit_bio_checks <-__submit_bio object:0xffff88811bee4000 value:0x3000
cat-117 [002] ...1. 1.602246: __cond_resched <-submit_bio_checks object:0xffff88811bee4000 value:0x3000
cat-117 [002] ...1. 1.602246: should_fail_bio <-submit_bio_checks object:0xffff88811bee4000 value:0x3000
cat-117 [002] ...1. 1.602246: blk_mq_submit_bio <-submit_bio_noacct object:0xffff88811bee4000 value:0x3000
cat-117 [002] ...1. 1.602246: blk_attempt_plug_merge <-blk_mq_submit_bio object:0xffff88811bee4000 value:0x3000
cat-117 [002] ...1. 1.602246: blk_mq_sched_bio_merge <-blk_mq_submit_bio object:0xffff88811bee4000 value:0x3000
cat-117 [002] ...1. 1.602247: __rcu_read_lock <-blk_mq_submit_bio object:0xffff88811bee4000 value:0x3000
cat-117 [002] ...1. 1.602247: __rcu_read_unlock <-blk_mq_submit_bio object:0xffff88811bee4000 value:0x3000
cat-117 [002] ...1. 1.602247: __blk_mq_alloc_requests <-blk_mq_submit_bio object:0xffff88811bee4000 value:0x3000
<idle>-0 [002] d..3. 1.602298: bio_endio <-blk_update_request object:0xffff88811bee4000 value:0x0
<idle>-0 [002] d..3. 1.602298: mpage_end_io <-blk_update_request object:0xffff88811bee4000 value:0x0
<idle>-0 [002] d..3. 1.602298: __read_end_io <-blk_update_request object:0xffff88811bee4000 value:0x0
<idle>-0 [002] d..3. 1.602300: bio_put <-blk_update_request object:0xffff88811bee4000 value:0x0
<idle>-0 [002] d..3. 1.602300: bio_free <-blk_update_request object:0xffff88811bee4000 value:0x0
<idle>-0 [002] d..3. 1.602300: mempool_free <-blk_update_request object:0xffff88811bee4000 value:0x0
<idle>-0 [002] d..3. 1.602300: mempool_free_slab <-blk_update_request object:0xffff88811bee4000 value:0x0
<idle>-0 [002] d..3. 1.602300: kmem_cache_free <-blk_update_request object:0xffff88811bee4000 value:0x0
...
Almost all changelogs were suggested by Masami([email protected])
and steve([email protected]), thank you all so much.
v8:
- revert to use per-cpu recursion for the function trace_object_events_call
- recover the filter when getting the value of the object
- simplify the implementation for the function get_object_value
- fix the build error
v7:
- use fixed-size array for object pool instead of list structure
- use ftrace_test_recursion_trylock for function trace hook function
- fix trace_object_ref reference count in the init_trace_object
- invoke exit_trace_object no matter whether data->ops->free is null
in the unregister_object_trigger
- release private_data of event_trigger_data in the trace_object_trigger_free
- remove [RFC] tag
v6:
- change the objtrace trigger syntax.
- add patchset description
- add <tracefs>/README
v5:
- add testcasts
- add check the field->size
- add lockless to search object
- describe the object trace more clearly in Kconfig
v4:
- please ignore the v4 which is the same as v3
v3:
- change the objfilter to objtrace
- add a command to the objfilter syntax
- change to get the value of the object
- use trace_find_event_field to find the field instead of using argN
- get data from @rec in the event trigger callback funciton
v2:
- adding a "objfilter" trigger to update object
Jeff Xie (4):
trace: Add trace any kernel object
trace/objtrace: get the value of the object
trace/objtrace: Add testcases for objtrace
trace/objtrace: Add documentation for objtrace
Documentation/trace/events.rst | 83 +++
include/linux/trace_events.h | 1 +
kernel/trace/Kconfig | 10 +
kernel/trace/Makefile | 1 +
kernel/trace/trace.c | 3 +
kernel/trace/trace.h | 8 +
kernel/trace/trace_entries.h | 18 +
kernel/trace/trace_events_trigger.c | 1 +
kernel/trace/trace_object.c | 631 ++++++++++++++++++
kernel/trace/trace_output.c | 40 ++
.../ftrace/test.d/trigger/trigger-objtrace.tc | 39 ++
11 files changed, 835 insertions(+)
create mode 100644 kernel/trace/trace_object.c
create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-objtrace.tc
--
2.25.1
Introduce objtrace trigger to get the call flow by tracing any kernel
object in the function parameter.
The objtrace trigger makes a list of the target object address from
the given event parameter, and records all kernel function calls
which has the object address in its parameter.
Syntax:
objtrace:add:obj[:count][if <filter>]
Usage:
# echo 'p bio_add_page arg1=$arg1' > kprobe_events
# cd events/kprobes/p_bio_add_page_0
# echo 'objtrace:add:arg1:1 if comm == "cat"' > ./trigger
# cat /test.txt
Signed-off-by: Jeff Xie <[email protected]>
---
include/linux/trace_events.h | 1 +
kernel/trace/Kconfig | 10 +
kernel/trace/Makefile | 1 +
kernel/trace/trace.c | 3 +
kernel/trace/trace.h | 8 +
kernel/trace/trace_entries.h | 17 +
kernel/trace/trace_events_trigger.c | 1 +
kernel/trace/trace_object.c | 465 ++++++++++++++++++++++++++++
kernel/trace/trace_output.c | 40 +++
9 files changed, 546 insertions(+)
create mode 100644 kernel/trace/trace_object.c
diff --git a/include/linux/trace_events.h b/include/linux/trace_events.h
index 70c069aef02c..3ccdbc1d25dd 100644
--- a/include/linux/trace_events.h
+++ b/include/linux/trace_events.h
@@ -685,6 +685,7 @@ enum event_trigger_type {
ETT_EVENT_HIST = (1 << 4),
ETT_HIST_ENABLE = (1 << 5),
ETT_EVENT_EPROBE = (1 << 6),
+ ETT_TRACE_OBJECT = (1 << 7),
};
extern int filter_match_preds(struct event_filter *filter, void *rec);
diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
index a5eb5e7fd624..c51b7eb1508d 100644
--- a/kernel/trace/Kconfig
+++ b/kernel/trace/Kconfig
@@ -250,6 +250,16 @@ config FUNCTION_PROFILER
If in doubt, say N.
+config TRACE_OBJECT
+ bool "Trace kernel object in function parameter"
+ depends on FUNCTION_TRACER
+ depends on HAVE_FUNCTION_ARG_ACCESS_API
+ select TRACING
+ default y
+ help
+ You can trace the kernel object in the kernel function parameter.
+ The kernel object is dynamically specified via event trigger.
+
config STACK_TRACER
bool "Trace max stack"
depends on HAVE_FUNCTION_TRACER
diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
index bedc5caceec7..b924b8e55922 100644
--- a/kernel/trace/Makefile
+++ b/kernel/trace/Makefile
@@ -67,6 +67,7 @@ obj-$(CONFIG_FUNCTION_GRAPH_TRACER) += trace_functions_graph.o
obj-$(CONFIG_TRACE_BRANCH_PROFILING) += trace_branch.o
obj-$(CONFIG_BLK_DEV_IO_TRACE) += blktrace.o
obj-$(CONFIG_FUNCTION_GRAPH_TRACER) += fgraph.o
+obj-$(CONFIG_TRACE_OBJECT) += trace_object.o
ifeq ($(CONFIG_BLOCK),y)
obj-$(CONFIG_EVENT_TRACING) += blktrace.o
endif
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index a734d5ae34c8..b4513c2bbd52 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -5605,6 +5605,9 @@ static const char readme_msg[] =
"\t enable_hist:<system>:<event>\n"
"\t disable_hist:<system>:<event>\n"
#endif
+#ifdef CONFIG_TRACE_OBJECT
+ "\t objtrace:add:obj[:count][if <filter>]\n"
+#endif
#ifdef CONFIG_STACKTRACE
"\t\t stacktrace\n"
#endif
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 0f5e22238cd2..8b66515a36d5 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -54,6 +54,7 @@ enum trace_type {
TRACE_TIMERLAT,
TRACE_RAW_DATA,
TRACE_FUNC_REPEATS,
+ TRACE_OBJECT,
__TRACE_LAST_TYPE,
};
@@ -472,6 +473,7 @@ extern void __ftrace_bad_type(void);
TRACE_GRAPH_RET); \
IF_ASSIGN(var, ent, struct func_repeats_entry, \
TRACE_FUNC_REPEATS); \
+ IF_ASSIGN(var, ent, struct trace_object_entry, TRACE_OBJECT);\
__ftrace_bad_type(); \
} while (0)
@@ -1537,6 +1539,12 @@ static inline int register_trigger_hist_cmd(void) { return 0; }
static inline int register_trigger_hist_enable_disable_cmds(void) { return 0; }
#endif
+#ifdef CONFIG_TRACE_OBJECT
+extern int register_trigger_object_cmd(void);
+#else
+static inline int register_trigger_object_cmd(void) { return 0; }
+#endif
+
extern int register_trigger_cmds(void);
extern void clear_event_triggers(struct trace_array *tr);
diff --git a/kernel/trace/trace_entries.h b/kernel/trace/trace_entries.h
index cd41e863b51c..bb120d9498a9 100644
--- a/kernel/trace/trace_entries.h
+++ b/kernel/trace/trace_entries.h
@@ -401,3 +401,20 @@ FTRACE_ENTRY(timerlat, timerlat_entry,
__entry->context,
__entry->timer_latency)
);
+
+/*
+ * trace object entry:
+ */
+FTRACE_ENTRY(object, trace_object_entry,
+
+ TRACE_OBJECT,
+
+ F_STRUCT(
+ __field( unsigned long, ip )
+ __field( unsigned long, parent_ip )
+ __field( unsigned long, object )
+ ),
+
+ F_printk(" %ps <-- %ps object:%lx\n",
+ (void *)__entry->ip, (void *)__entry->parent_ip, __entry->object)
+);
diff --git a/kernel/trace/trace_events_trigger.c b/kernel/trace/trace_events_trigger.c
index d00fee705f9c..c3371a6902af 100644
--- a/kernel/trace/trace_events_trigger.c
+++ b/kernel/trace/trace_events_trigger.c
@@ -2025,6 +2025,7 @@ __init int register_trigger_cmds(void)
register_trigger_enable_disable_cmds();
register_trigger_hist_enable_disable_cmds();
register_trigger_hist_cmd();
+ register_trigger_object_cmd();
return 0;
}
diff --git a/kernel/trace/trace_object.c b/kernel/trace/trace_object.c
new file mode 100644
index 000000000000..1eb485c513e9
--- /dev/null
+++ b/kernel/trace/trace_object.c
@@ -0,0 +1,465 @@
+// SPDX-License-Identifier: GPL-2.0
+/*
+ * trace the kernel object in the kernel function parameter
+ * Copyright (C) 2021 Jeff Xie <[email protected]>
+ */
+
+#define pr_fmt(fmt) "trace_object: " fmt
+
+#include "trace_output.h"
+
+#define MAX_TRACED_OBJECT 5
+static DEFINE_PER_CPU(unsigned int, trace_object_event_disable);
+static DEFINE_RAW_SPINLOCK(trace_obj_lock);
+static struct trace_event_file event_trace_file;
+static const int max_args_num = 6;
+static atomic_t trace_object_ref;
+static atomic_t num_traced_obj;
+static int exit_trace_object(void);
+static int init_trace_object(void);
+
+static struct object_instance {
+ void *obj;
+} traced_obj[MAX_TRACED_OBJECT];
+
+static bool object_exist(void *obj)
+{
+ int i, max;
+
+ max = atomic_read(&num_traced_obj);
+ smp_rmb();
+ for (i = 0; i < max; i++) {
+ if (traced_obj[i].obj == obj)
+ return true;
+ }
+ return false;
+}
+
+static bool object_empty(void)
+{
+ return !atomic_read(&num_traced_obj);
+}
+
+static void set_trace_object(void *obj)
+{
+ unsigned long flags;
+
+ if (in_nmi())
+ return;
+
+ if (!obj)
+ return;
+
+ if (object_exist(obj))
+ return;
+
+ /* only this place has write operations */
+ raw_spin_lock_irqsave(&trace_obj_lock, flags);
+ if (atomic_read(&num_traced_obj) == MAX_TRACED_OBJECT) {
+ trace_printk("object_pool is full, can't trace object:0x%px\n", obj);
+ goto out;
+ }
+ traced_obj[atomic_read(&num_traced_obj)].obj = obj;
+ /* make sure the num_traced_obj update always appears after traced_obj update */
+ smp_wmb();
+ atomic_inc(&num_traced_obj);
+out:
+ raw_spin_unlock_irqrestore(&trace_obj_lock, flags);
+}
+
+static void submit_trace_object(unsigned long ip, unsigned long parent_ip,
+ unsigned long object)
+{
+
+ struct trace_buffer *buffer;
+ struct ring_buffer_event *event;
+ struct trace_object_entry *entry;
+ int pc;
+
+ pc = preempt_count();
+ event = trace_event_buffer_lock_reserve(&buffer, &event_trace_file,
+ TRACE_OBJECT, sizeof(*entry), pc);
+ if (!event)
+ return;
+ entry = ring_buffer_event_data(event);
+ entry->ip = ip;
+ entry->parent_ip = parent_ip;
+ entry->object = object;
+
+ event_trigger_unlock_commit(&event_trace_file, buffer, event,
+ entry, pc);
+}
+
+static void
+trace_object_events_call(unsigned long ip, unsigned long parent_ip,
+ struct ftrace_ops *op, struct ftrace_regs *fregs)
+{
+ struct pt_regs *pt_regs = ftrace_get_regs(fregs);
+ unsigned long obj;
+ unsigned int disabled;
+ int n;
+
+ preempt_disable_notrace();
+
+ disabled = this_cpu_inc_return(trace_object_event_disable);
+ if (disabled != 1)
+ goto out;
+
+ if (object_empty())
+ goto out;
+
+ for (n = 0; n < max_args_num; n++) {
+ obj = regs_get_kernel_argument(pt_regs, n);
+ if (object_exist((void *)obj))
+ submit_trace_object(ip, parent_ip, obj);
+ /* The parameters of a function may match multiple objects */
+ }
+out:
+ this_cpu_dec(trace_object_event_disable);
+ preempt_enable_notrace();
+}
+
+static struct ftrace_ops trace_ops = {
+ .func = trace_object_events_call,
+ .flags = FTRACE_OPS_FL_SAVE_REGS,
+};
+
+static void
+trace_object_trigger(struct event_trigger_data *data,
+ struct trace_buffer *buffer, void *rec,
+ struct ring_buffer_event *event)
+{
+
+ struct ftrace_event_field *field = data->private_data;
+ void *obj = NULL;
+
+ memcpy(&obj, rec + field->offset, sizeof(obj));
+ set_trace_object(obj);
+}
+
+static void
+trace_object_trigger_free(struct event_trigger_ops *ops,
+ struct event_trigger_data *data)
+{
+ if (WARN_ON_ONCE(data->ref <= 0))
+ return;
+
+ data->ref--;
+ if (!data->ref)
+ trigger_data_free(data);
+}
+
+static void
+trace_object_count_trigger(struct event_trigger_data *data,
+ struct trace_buffer *buffer, void *rec,
+ struct ring_buffer_event *event)
+{
+ if (!data->count)
+ return;
+
+ if (data->count != -1)
+ (data->count)--;
+
+ trace_object_trigger(data, buffer, rec, event);
+}
+
+static int event_object_trigger_init(struct event_trigger_ops *ops,
+ struct event_trigger_data *data)
+{
+ data->ref++;
+ return 0;
+}
+
+static int
+event_trigger_print(const char *name, struct seq_file *m,
+ void *data, char *filter_str)
+{
+ long count = (long)data;
+
+ seq_puts(m, name);
+
+ if (count == -1)
+ seq_puts(m, ":unlimited");
+ else
+ seq_printf(m, ":count=%ld", count);
+
+ if (filter_str)
+ seq_printf(m, " if %s\n", filter_str);
+ else
+ seq_putc(m, '\n');
+
+ return 0;
+}
+
+static int
+trace_object_trigger_print(struct seq_file *m, struct event_trigger_ops *ops,
+ struct event_trigger_data *data)
+{
+ return event_trigger_print("objtrace", m, (void *)data->count,
+ data->filter_str);
+}
+
+static struct event_trigger_ops objecttrace_trigger_ops = {
+ .trigger = trace_object_trigger,
+ .print = trace_object_trigger_print,
+ .init = event_object_trigger_init,
+ .free = trace_object_trigger_free,
+};
+
+static struct event_trigger_ops objecttrace_count_trigger_ops = {
+ .trigger = trace_object_count_trigger,
+ .print = trace_object_trigger_print,
+ .init = event_object_trigger_init,
+ .free = trace_object_trigger_free,
+};
+
+static struct event_trigger_ops *
+objecttrace_get_trigger_ops(char *cmd, char *param)
+{
+ return param ? &objecttrace_count_trigger_ops : &objecttrace_trigger_ops;
+}
+
+static int register_object_trigger(char *glob,
+ struct event_trigger_data *data,
+ struct trace_event_file *file)
+{
+ struct event_trigger_data *test;
+ int ret = 0;
+
+ lockdep_assert_held(&event_mutex);
+
+ list_for_each_entry(test, &file->triggers, list) {
+ if (test->cmd_ops->trigger_type == data->cmd_ops->trigger_type) {
+ ret = -EEXIST;
+ goto out;
+ }
+ }
+
+ if (data->ops->init) {
+ ret = data->ops->init(data->ops, data);
+ if (ret < 0)
+ goto out;
+ }
+
+ list_add_rcu(&data->list, &file->triggers);
+ ret++;
+
+ update_cond_flag(file);
+ if (trace_event_trigger_enable_disable(file, 1) < 0) {
+ list_del_rcu(&data->list);
+ update_cond_flag(file);
+ ret--;
+ }
+ init_trace_object();
+out:
+ return ret;
+}
+
+static void unregister_object_trigger(char *glob,
+ struct event_trigger_data *test,
+ struct trace_event_file *file)
+{
+ struct event_trigger_data *data;
+ bool unregistered = false;
+
+ lockdep_assert_held(&event_mutex);
+
+ list_for_each_entry(data, &file->triggers, list) {
+ if (data->cmd_ops->trigger_type == test->cmd_ops->trigger_type) {
+ unregistered = true;
+ list_del_rcu(&data->list);
+ trace_event_trigger_enable_disable(file, 0);
+ update_cond_flag(file);
+ break;
+ }
+ }
+
+ if (unregistered) {
+ if (data->ops->free)
+ data->ops->free(data->ops, data);
+ exit_trace_object();
+ }
+}
+
+static int
+event_object_trigger_parse(struct event_command *cmd_ops,
+ struct trace_event_file *file,
+ char *glob, char *cmd, char *param)
+{
+ struct event_trigger_data *trigger_data;
+ struct event_trigger_ops *trigger_ops;
+ struct trace_event_call *call;
+ struct ftrace_event_field *field;
+ char *objtrace_cmd;
+ char *trigger = NULL;
+ char *arg;
+ char *number;
+ int ret;
+
+ ret = -EINVAL;
+ if (!param)
+ goto out;
+
+ /* separate the trigger from the filter (c:a:n [if filter]) */
+ trigger = strsep(¶m, " \t");
+ if (!trigger)
+ goto out;
+ if (param) {
+ param = skip_spaces(param);
+ if (!*param)
+ param = NULL;
+ }
+
+ objtrace_cmd = strsep(&trigger, ":");
+ if (!objtrace_cmd || strcmp(objtrace_cmd, "add"))
+ goto out;
+
+ arg = strsep(&trigger, ":");
+ if (!arg)
+ goto out;
+ call = file->event_call;
+ field = trace_find_event_field(call, arg);
+ if (!field)
+ goto out;
+
+ if (field->size != sizeof(void *))
+ goto out;
+
+ trigger_ops = cmd_ops->get_trigger_ops(cmd, trigger);
+
+ ret = -ENOMEM;
+ trigger_data = kzalloc(sizeof(*trigger_data), GFP_KERNEL);
+ if (!trigger_data)
+ goto out;
+
+ trigger_data->count = -1;
+ trigger_data->ops = trigger_ops;
+ trigger_data->cmd_ops = cmd_ops;
+ trigger_data->private_data = field;
+ INIT_LIST_HEAD(&trigger_data->list);
+ INIT_LIST_HEAD(&trigger_data->named_list);
+
+ if (glob[0] == '!') {
+ cmd_ops->unreg(glob+1, trigger_data, file);
+ kfree(trigger_data);
+ ret = 0;
+ goto out;
+ }
+
+ if (trigger) {
+ number = strsep(&trigger, ":");
+
+ ret = -EINVAL;
+ if (!strlen(number))
+ goto out_free;
+
+ /*
+ * We use the callback data field (which is a pointer)
+ * as our counter.
+ */
+ ret = kstrtoul(number, 0, &trigger_data->count);
+ if (ret)
+ goto out_free;
+ }
+
+ if (!param) /* if param is non-empty, it's supposed to be a filter */
+ goto out_reg;
+
+ if (!cmd_ops->set_filter)
+ goto out_reg;
+
+ ret = cmd_ops->set_filter(param, trigger_data, file);
+ if (ret < 0)
+ goto out_free;
+
+ out_reg:
+ /* Up the trigger_data count to make sure reg doesn't free it on failure */
+ event_object_trigger_init(trigger_ops, trigger_data);
+ ret = cmd_ops->reg(glob, trigger_data, file);
+ /*
+ * The above returns on success the # of functions enabled,
+ * but if it didn't find any functions it returns zero.
+ * Consider no functions a failure too.
+ */
+ if (!ret) {
+ cmd_ops->unreg(glob, trigger_data, file);
+ ret = -ENOENT;
+ } else if (ret > 0)
+ ret = 0;
+
+ /* Down the counter of trigger_data or free it if not used anymore */
+ trace_object_trigger_free(trigger_ops, trigger_data);
+ out:
+ return ret;
+
+ out_free:
+ if (cmd_ops->set_filter)
+ cmd_ops->set_filter(NULL, trigger_data, NULL);
+ kfree(trigger_data);
+ goto out;
+}
+
+static struct event_command trigger_object_cmd = {
+ .name = "objtrace",
+ .trigger_type = ETT_TRACE_OBJECT,
+ .flags = EVENT_CMD_FL_NEEDS_REC,
+ .parse = event_object_trigger_parse,
+ .reg = register_object_trigger,
+ .unreg = unregister_object_trigger,
+ .get_trigger_ops = objecttrace_get_trigger_ops,
+ .set_filter = set_trigger_filter,
+};
+
+__init int register_trigger_object_cmd(void)
+{
+ int ret;
+
+ ret = register_event_command(&trigger_object_cmd);
+ WARN_ON(ret < 0);
+
+ return ret;
+}
+
+static int init_trace_object(void)
+{
+ int ret;
+
+ if (atomic_inc_return(&trace_object_ref) != 1) {
+ ret = 0;
+ goto out;
+ }
+
+ event_trace_file.tr = top_trace_array();
+ if (WARN_ON(!event_trace_file.tr)) {
+ ret = -1;
+ atomic_dec(&trace_object_ref);
+ goto out;
+ }
+ ret = register_ftrace_function(&trace_ops);
+out:
+ return ret;
+}
+
+static int exit_trace_object(void)
+{
+ int ret;
+
+ if (WARN_ON_ONCE(atomic_read(&trace_object_ref) <= 0)) {
+ ret = -1;
+ goto out;
+ }
+
+ if (atomic_dec_return(&trace_object_ref) != 0) {
+ ret = 0;
+ goto out;
+ }
+
+ ret = unregister_ftrace_function(&trace_ops);
+ if (ret) {
+ pr_err("can't unregister ftrace for trace object\n");
+ goto out;
+ }
+ atomic_set(&num_traced_obj, 0);
+out:
+ return ret;
+}
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index 8aa493d25c73..265428154638 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -1547,6 +1547,45 @@ static struct trace_event trace_func_repeats_event = {
.funcs = &trace_func_repeats_funcs,
};
+/* TRACE_OBJECT */
+static enum print_line_t trace_object_print(struct trace_iterator *iter, int flags,
+ struct trace_event *event)
+{
+ struct trace_object_entry *field;
+ struct trace_seq *s = &iter->seq;
+
+ trace_assign_type(field, iter->ent);
+ print_fn_trace(s, field->ip, field->parent_ip, flags);
+ trace_seq_printf(s, " object:0x%lx", field->object);
+ trace_seq_putc(s, '\n');
+
+ return trace_handle_return(s);
+}
+
+static enum print_line_t trace_object_raw(struct trace_iterator *iter, int flags,
+ struct trace_event *event)
+{
+ struct trace_object_entry *field;
+
+ trace_assign_type(field, iter->ent);
+
+ trace_seq_printf(&iter->seq, "%lx %lx\n",
+ field->ip,
+ field->parent_ip);
+
+ return trace_handle_return(&iter->seq);
+}
+
+static struct trace_event_functions trace_object_funcs = {
+ .trace = trace_object_print,
+ .raw = trace_object_raw,
+};
+
+static struct trace_event trace_object_event = {
+ .type = TRACE_OBJECT,
+ .funcs = &trace_object_funcs,
+};
+
static struct trace_event *events[] __initdata = {
&trace_fn_event,
&trace_ctx_event,
@@ -1561,6 +1600,7 @@ static struct trace_event *events[] __initdata = {
&trace_timerlat_event,
&trace_raw_data_event,
&trace_func_repeats_event,
+ &trace_object_event,
NULL
};
--
2.25.1
Using objtrace trigger to get the value of the object which from the kernel
function parameter.
Syntax:
objtrace:add:obj[,offset][:type][:count][if <filter>]
Usage:
# echo 'p bio_add_page arg1=$arg1' > ./kprobe_events
# gdb vmlinux
(gdb) p &(((struct bio *)0)->bi_iter.bi_size)
$1 = (unsigned int *) 0x28
# echo 'objtrace:add:arg1,0x28:u32:1 if comm == "cat"' > ./events/kprobes/ \
p_bio_add_page_0/trigger
# cat /test.txt
Signed-off-by: Jeff Xie <[email protected]>
---
kernel/trace/trace.c | 2 +-
kernel/trace/trace_entries.h | 5 +-
kernel/trace/trace_object.c | 214 +++++++++++++++++++++++++++++++----
kernel/trace/trace_output.c | 6 +-
4 files changed, 197 insertions(+), 30 deletions(-)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index b4513c2bbd52..5f145837d2ff 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -5606,7 +5606,7 @@ static const char readme_msg[] =
"\t disable_hist:<system>:<event>\n"
#endif
#ifdef CONFIG_TRACE_OBJECT
- "\t objtrace:add:obj[:count][if <filter>]\n"
+ "\t objtrace:add:obj[,offset][:type][:count][if <filter>]\n"
#endif
#ifdef CONFIG_STACKTRACE
"\t\t stacktrace\n"
diff --git a/kernel/trace/trace_entries.h b/kernel/trace/trace_entries.h
index bb120d9498a9..2407c45a568c 100644
--- a/kernel/trace/trace_entries.h
+++ b/kernel/trace/trace_entries.h
@@ -413,8 +413,9 @@ FTRACE_ENTRY(object, trace_object_entry,
__field( unsigned long, ip )
__field( unsigned long, parent_ip )
__field( unsigned long, object )
+ __field( unsigned long, value )
),
- F_printk(" %ps <-- %ps object:%lx\n",
- (void *)__entry->ip, (void *)__entry->parent_ip, __entry->object)
+ F_printk(" %ps <-- %ps object:%lx value:%lx\n", (void *)__entry->ip,
+ (void *)__entry->parent_ip, __entry->object, __entry->value)
);
diff --git a/kernel/trace/trace_object.c b/kernel/trace/trace_object.c
index 1eb485c513e9..01821aa6be04 100644
--- a/kernel/trace/trace_object.c
+++ b/kernel/trace/trace_object.c
@@ -18,10 +18,35 @@ static atomic_t num_traced_obj;
static int exit_trace_object(void);
static int init_trace_object(void);
+/*
+ * get the offset from the special object and
+ * the type size of the value
+ */
static struct object_instance {
void *obj;
+ int obj_offset;
+ int obj_value_type_size;
} traced_obj[MAX_TRACED_OBJECT];
+/* objtrace private data */
+struct objtrace_trigger_data {
+ struct ftrace_event_field *field;
+ int obj_offset;
+ int obj_value_type_size;
+};
+
+/* get the type size for the special object */
+struct objtrace_fetch_type {
+ char *name;
+ int type_size;
+};
+
+enum objattr {
+ OBJ_OFFSET,
+ OBJ_VAL_TYPE_SIZE,
+ MAX_OBJ_ATTR
+};
+
static bool object_exist(void *obj)
{
int i, max;
@@ -35,13 +60,37 @@ static bool object_exist(void *obj)
return false;
}
+static int get_object_attr(void *obj, int objattr, int *result)
+{
+ int i, max;
+
+ max = atomic_read(&num_traced_obj);
+ smp_rmb();
+ for (i = 0; i < max; i++) {
+ if (traced_obj[i].obj == obj) {
+ switch (objattr) {
+ case OBJ_OFFSET:
+ *result = traced_obj[i].obj_offset;
+ return 0;
+ case OBJ_VAL_TYPE_SIZE:
+ *result = traced_obj[i].obj_value_type_size;
+ return 0;
+ default:
+ return -EINVAL;
+ }
+ }
+ }
+ return -EINVAL;
+}
+
static bool object_empty(void)
{
return !atomic_read(&num_traced_obj);
}
-static void set_trace_object(void *obj)
+static void set_trace_object(void *obj, int obj_offset, int obj_value_type_size)
{
+ unsigned int traced_objs;
unsigned long flags;
if (in_nmi())
@@ -55,11 +104,14 @@ static void set_trace_object(void *obj)
/* only this place has write operations */
raw_spin_lock_irqsave(&trace_obj_lock, flags);
- if (atomic_read(&num_traced_obj) == MAX_TRACED_OBJECT) {
+ traced_objs = atomic_read(&num_traced_obj);
+ if (traced_objs == MAX_TRACED_OBJECT) {
trace_printk("object_pool is full, can't trace object:0x%px\n", obj);
goto out;
}
- traced_obj[atomic_read(&num_traced_obj)].obj = obj;
+ traced_obj[traced_objs].obj = obj;
+ traced_obj[traced_objs].obj_value_type_size = obj_value_type_size;
+ traced_obj[traced_objs].obj_offset = obj_offset;
/* make sure the num_traced_obj update always appears after traced_obj update */
smp_wmb();
atomic_inc(&num_traced_obj);
@@ -68,7 +120,7 @@ static void set_trace_object(void *obj)
}
static void submit_trace_object(unsigned long ip, unsigned long parent_ip,
- unsigned long object)
+ unsigned long object, unsigned long value)
{
struct trace_buffer *buffer;
@@ -85,19 +137,52 @@ static void submit_trace_object(unsigned long ip, unsigned long parent_ip,
entry->ip = ip;
entry->parent_ip = parent_ip;
entry->object = object;
+ entry->value = value;
event_trigger_unlock_commit(&event_trace_file, buffer, event,
entry, pc);
}
+static inline long get_object_value(unsigned long *val, void *obj, int type_size)
+{
+ char tmp[sizeof(u64)];
+ long ret = 0;
+
+ ret = copy_from_kernel_nofault(tmp, obj, sizeof(tmp));
+ if (ret)
+ return ret;
+ switch (type_size) {
+ case 1: {
+ *val = (unsigned long)*(u8 *)tmp;
+ break;
+ }
+ case 2: {
+ *val = (unsigned long)*(u16 *)tmp;
+ break;
+ }
+ case 4: {
+ *val = (unsigned long)*(u32 *)tmp;
+ break;
+ }
+ case 8: {
+ *val = (unsigned long)*(u64 *)tmp;
+ break;
+ }
+ default:
+ return -EINVAL;
+ }
+
+ return 0;
+}
+
static void
trace_object_events_call(unsigned long ip, unsigned long parent_ip,
struct ftrace_ops *op, struct ftrace_regs *fregs)
{
struct pt_regs *pt_regs = ftrace_get_regs(fregs);
- unsigned long obj;
+ int n, ret, val_type_size, obj_offset;
+ unsigned long obj, val;
unsigned int disabled;
- int n;
preempt_disable_notrace();
@@ -110,8 +195,19 @@ trace_object_events_call(unsigned long ip, unsigned long parent_ip,
for (n = 0; n < max_args_num; n++) {
obj = regs_get_kernel_argument(pt_regs, n);
- if (object_exist((void *)obj))
- submit_trace_object(ip, parent_ip, obj);
+ if (object_exist((void *)obj)) {
+ ret = get_object_attr((void *)obj, OBJ_OFFSET, &obj_offset);
+ if (unlikely(ret) < 0)
+ goto out;
+
+ get_object_attr((void *)obj, OBJ_VAL_TYPE_SIZE, &val_type_size);
+ if (unlikely(ret) < 0)
+ goto out;
+
+ if (get_object_value(&val, (void *)(obj + obj_offset), val_type_size))
+ continue;
+ submit_trace_object(ip, parent_ip, obj, val);
+ }
/* The parameters of a function may match multiple objects */
}
out:
@@ -129,12 +225,14 @@ trace_object_trigger(struct event_trigger_data *data,
struct trace_buffer *buffer, void *rec,
struct ring_buffer_event *event)
{
+ struct objtrace_trigger_data *obj_data = data->private_data;
+ struct ftrace_event_field *field;
+ void *obj;
- struct ftrace_event_field *field = data->private_data;
- void *obj = NULL;
-
+ field = obj_data->field;
memcpy(&obj, rec + field->offset, sizeof(obj));
- set_trace_object(obj);
+ /* set the offset from the special object and the type size of the value*/
+ set_trace_object(obj, obj_data->obj_offset, obj_data->obj_value_type_size);
}
static void
@@ -145,8 +243,10 @@ trace_object_trigger_free(struct event_trigger_ops *ops,
return;
data->ref--;
- if (!data->ref)
+ if (!data->ref) {
+ kfree(data->private_data);
trigger_data_free(data);
+ }
}
static void
@@ -281,6 +381,22 @@ static void unregister_object_trigger(char *glob,
}
}
+static const struct objtrace_fetch_type objtrace_fetch_types[] = {
+ {"u8", 1},
+ {"s8", 1},
+ {"x8", 1},
+ {"u16", 2},
+ {"s16", 2},
+ {"x16", 2},
+ {"u32", 4},
+ {"s32", 4},
+ {"x32", 4},
+ {"u64", 8},
+ {"s64", 8},
+ {"x64", 8},
+ {}
+};
+
static int
event_object_trigger_parse(struct event_command *cmd_ops,
struct trace_event_file *file,
@@ -288,19 +404,22 @@ event_object_trigger_parse(struct event_command *cmd_ops,
{
struct event_trigger_data *trigger_data;
struct event_trigger_ops *trigger_ops;
+ struct objtrace_trigger_data *obj_data;
struct trace_event_call *call;
struct ftrace_event_field *field;
- char *objtrace_cmd;
- char *trigger = NULL;
- char *arg;
- char *number;
- int ret;
+ char *type, *tr, *obj, *tmp, *trigger = NULL;
+ char *number, *objtrace_cmd;
+ int ret, i, def_type_size, obj_value_type_size = 0;
+ long offset = 0;
ret = -EINVAL;
if (!param)
goto out;
- /* separate the trigger from the filter (c:a:n [if filter]) */
+ /*
+ * separate the trigger from the filter:
+ * objtrace:add:OBJ[,OFFS][:TYPE][:COUNT] [if filter]
+ */
trigger = strsep(¶m, " \t");
if (!trigger)
goto out;
@@ -314,33 +433,79 @@ event_object_trigger_parse(struct event_command *cmd_ops,
if (!objtrace_cmd || strcmp(objtrace_cmd, "add"))
goto out;
- arg = strsep(&trigger, ":");
- if (!arg)
+ obj = strsep(&trigger, ":");
+ if (!obj)
goto out;
+
+ tr = strchr(obj, ',');
+ if (!tr)
+ offset = 0;
+ else {
+ *tr++ = '\0';
+ ret = kstrtol(tr, 0, &offset);
+ if (ret)
+ goto out;
+ }
+
+ ret = -EINVAL;
call = file->event_call;
- field = trace_find_event_field(call, arg);
+ field = trace_find_event_field(call, obj);
if (!field)
goto out;
if (field->size != sizeof(void *))
goto out;
+ def_type_size = sizeof(void *);
+ if (!trigger) {
+ obj_value_type_size = def_type_size;
+ goto skip_get_type;
+ }
+ tmp = trigger;
+ type = strsep(&trigger, ":");
+ if (!type)
+ obj_value_type_size = def_type_size;
+ else if (isdigit(type[0])) {
+ obj_value_type_size = def_type_size;
+ trigger = tmp;
+ } else {
+ for (i = 0; objtrace_fetch_types[i].name; i++) {
+ if (strcmp(objtrace_fetch_types[i].name, type) == 0) {
+ obj_value_type_size = objtrace_fetch_types[i].type_size;
+ break;
+ }
+ }
+ }
+ if (!obj_value_type_size)
+ goto out;
+skip_get_type:
trigger_ops = cmd_ops->get_trigger_ops(cmd, trigger);
ret = -ENOMEM;
+ obj_data = kzalloc(sizeof(*obj_data), GFP_KERNEL);
+ if (!obj_data)
+ goto out;
+
+ obj_data->field = field;
+ obj_data->obj_offset = offset;
+ obj_data->obj_value_type_size = obj_value_type_size;
+
trigger_data = kzalloc(sizeof(*trigger_data), GFP_KERNEL);
- if (!trigger_data)
+ if (!trigger_data) {
+ kfree(obj_data);
goto out;
+ }
trigger_data->count = -1;
trigger_data->ops = trigger_ops;
trigger_data->cmd_ops = cmd_ops;
- trigger_data->private_data = field;
+ trigger_data->private_data = obj_data;
INIT_LIST_HEAD(&trigger_data->list);
INIT_LIST_HEAD(&trigger_data->named_list);
if (glob[0] == '!') {
cmd_ops->unreg(glob+1, trigger_data, file);
+ kfree(obj_data);
kfree(trigger_data);
ret = 0;
goto out;
@@ -395,6 +560,7 @@ event_object_trigger_parse(struct event_command *cmd_ops,
out_free:
if (cmd_ops->set_filter)
cmd_ops->set_filter(NULL, trigger_data, NULL);
+ kfree(obj_data);
kfree(trigger_data);
goto out;
}
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index 265428154638..04804f53cadd 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -1557,6 +1557,7 @@ static enum print_line_t trace_object_print(struct trace_iterator *iter, int fla
trace_assign_type(field, iter->ent);
print_fn_trace(s, field->ip, field->parent_ip, flags);
trace_seq_printf(s, " object:0x%lx", field->object);
+ trace_seq_printf(s, " value:0x%lx", field->value);
trace_seq_putc(s, '\n');
return trace_handle_return(s);
@@ -1569,9 +1570,8 @@ static enum print_line_t trace_object_raw(struct trace_iterator *iter, int flags
trace_assign_type(field, iter->ent);
- trace_seq_printf(&iter->seq, "%lx %lx\n",
- field->ip,
- field->parent_ip);
+ trace_seq_printf(&iter->seq, "%lx %lx %lx %lx\n", field->ip,
+ field->parent_ip, field->object, field->value);
return trace_handle_return(&iter->seq);
}
--
2.25.1
Add a series of testcases to illustrate correct and incorrect usage of
objtrace trigger.
Signed-off-by: Jeff Xie <[email protected]>
---
.../ftrace/test.d/trigger/trigger-objtrace.tc | 39 +++++++++++++++++++
1 file changed, 39 insertions(+)
create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-objtrace.tc
diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-objtrace.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-objtrace.tc
new file mode 100644
index 000000000000..d71eb157c51f
--- /dev/null
+++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-objtrace.tc
@@ -0,0 +1,39 @@
+#!/bin/sh
+# SPDX-License-Identifier: GPL-2.0
+# description: event trigger - test objtrace-trigger
+# requires: kprobe_events "objtrace":README
+
+fail() { #msg
+ echo $1
+ exit_fail
+}
+
+echo 'p bio_add_page arg1=$arg1' > kprobe_events
+
+FEATURE=`grep objtrace events/kprobes/p_bio_add_page_0/trigger`
+if [ -z "$FEATURE" ]; then
+ echo "objtrace trigger is not supported"
+ exit_unsupported
+fi
+
+echo "Test objtrace trigger"
+echo 'objtrace:add:arg1,0x28:u32:1 if comm == "cat"' > \
+ events/kprobes/p_bio_add_page_0/trigger
+if [ -z $? ]; then
+ fail "objtrace trigger syntax error"
+fi
+
+echo "Test objtrace semantic errors"
+
+# Being lack of objtrace command
+! echo 'objtrace:arg1,0x28:u32:1' > events/kprobes/p_bio_add_page_0/trigger
+# Bad parameter name
+! echo 'objtrace:add:argx:u32:1' > events/kprobes/p_bio_add_page_0/trigger
+
+echo "reset objtrace trigger"
+
+echo '!objtrace:add:arg1,0x28:u32' > \
+ events/kprobes/p_bio_add_page_0/trigger
+echo '-:p_bio_add_page_0' >> ./kprobe_events
+
+exit 0
--
2.25.1
Added documentation explaining how to use objtrace trigger to get the value
of the object.
Signed-off-by: Jeff Xie <[email protected]>
---
Documentation/trace/events.rst | 83 ++++++++++++++++++++++++++++++++++
1 file changed, 83 insertions(+)
diff --git a/Documentation/trace/events.rst b/Documentation/trace/events.rst
index c47f381d0c00..383fff5ca9ba 100644
--- a/Documentation/trace/events.rst
+++ b/Documentation/trace/events.rst
@@ -546,6 +546,89 @@ The following commands are supported:
See Documentation/trace/histogram.rst for details and examples.
+- objtrace
+
+ This command provides a way to get the value of any object, The object
+ can be obtained from the dynamic event(kprobe_event/uprobe_event) or the
+ static event(tracepoint).
+
+ Usage:
+ When using the kprobe event, only need to set the objtrace(a new trigger),
+ we can get the value of the object. The object is from the setting of the
+ kprobe event.
+
+ For example:
+ For the function bio_add_page():
+
+ int bio_add_page(struct bio *bio, struct page *page,
+ unsigned int len, unsigned int offset)
+
+ Firstly, we can set the base of the object, thus the first string "arg1"
+ stands for the value of the first parameter of this function bio_add_gage(),
+
+ # echo 'p bio_add_page arg1=$arg1' > ./kprobe_events
+
+ Secondly, we can get the value dynamically based on above object.
+
+ find the offset of the bi_size in struct bio:
+ $ gdb vmlinux
+ (gdb) p &(((struct bio *)0)->bi_iter.bi_size)
+ $1 = (unsigned int *) 0x28
+
+ # echo 'objtrace:add:arg1,0x28:u32:1 if comm == "cat"' > ./events/kprobes/ \
+ p_bio_add_page_0/trigger
+
+ # cd /sys/kernel/debug/tracing/
+ # echo 'p bio_add_page arg1=$arg1' > ./kprobe_events
+ # echo 'objtrace:add:arg1,0x28:u32:1 if comm == "cat"' > ./events/kprobes/p_bio_add_page_0/trigger
+
+ # du -sh /test.txt
+ 12.0K /test.txt
+
+ # cat /test.txt > /dev/null
+ # cat ./trace
+ # tracer: nop
+ #
+ # entries-in-buffer/entries-written: 128/128 #P:4
+ #
+ # _-----=> irqs-off/BH-disabled
+ # / _----=> need-resched
+ # | / _---=> hardirq/softirq
+ # || / _--=> preempt-depth
+ # ||| / _-=> migrate-disable
+ # |||| / delay
+ # TASK-PID CPU# ||||| TIMESTAMP FUNCTION
+ # | | | ||||| | |
+ cat-117 [002] ...1. 1.602243: __bio_try_merge_page <-bio_add_page object:0xffff88811bee4000 value:0x0
+ cat-117 [002] ...1. 1.602244: __bio_add_page <-bio_add_page object:0xffff88811bee4000 value:0x0
+ cat-117 [002] ...2. 1.602244: bio_add_page <-ext4_mpage_readpages object:0xffff88811bee4000 value:0x1000
+ cat-117 [002] ...1. 1.602245: __bio_try_merge_page <-bio_add_page object:0xffff88811bee4000 value:0x1000
+ cat-117 [002] ...1. 1.602245: __bio_add_page <-bio_add_page object:0xffff88811bee4000 value:0x1000
+ cat-117 [002] ...2. 1.602245: bio_add_page <-ext4_mpage_readpages object:0xffff88811bee4000 value:0x2000
+ cat-117 [002] ...1. 1.602245: __bio_try_merge_page <-bio_add_page object:0xffff88811bee4000 value:0x2000
+ cat-117 [002] ...1. 1.602245: __bio_add_page <-bio_add_page object:0xffff88811bee4000 value:0x2000
+ cat-117 [002] ...1. 1.602245: submit_bio <-ext4_mpage_readpages object:0xffff88811bee4000 value:0x3000
+ cat-117 [002] ...1. 1.602245: submit_bio_noacct <-ext4_mpage_readpages object:0xffff88811bee4000 value:0x3000
+ cat-117 [002] ...1. 1.602246: __submit_bio <-submit_bio_noacct object:0xffff88811bee4000 value:0x3000
+ cat-117 [002] ...1. 1.602246: submit_bio_checks <-__submit_bio object:0xffff88811bee4000 value:0x3000
+ cat-117 [002] ...1. 1.602246: __cond_resched <-submit_bio_checks object:0xffff88811bee4000 value:0x3000
+ cat-117 [002] ...1. 1.602246: should_fail_bio <-submit_bio_checks object:0xffff88811bee4000 value:0x3000
+ cat-117 [002] ...1. 1.602246: blk_mq_submit_bio <-submit_bio_noacct object:0xffff88811bee4000 value:0x3000
+ cat-117 [002] ...1. 1.602246: blk_attempt_plug_merge <-blk_mq_submit_bio object:0xffff88811bee4000 value:0x3000
+ cat-117 [002] ...1. 1.602246: blk_mq_sched_bio_merge <-blk_mq_submit_bio object:0xffff88811bee4000 value:0x3000
+ cat-117 [002] ...1. 1.602247: __rcu_read_lock <-blk_mq_submit_bio object:0xffff88811bee4000 value:0x3000
+ cat-117 [002] ...1. 1.602247: __rcu_read_unlock <-blk_mq_submit_bio object:0xffff88811bee4000 value:0x3000
+ cat-117 [002] ...1. 1.602247: __blk_mq_alloc_requests <-blk_mq_submit_bio object:0xffff88811bee4000 value:0x3000
+ <idle>-0 [002] d..3. 1.602298: bio_endio <-blk_update_request object:0xffff88811bee4000 value:0x0
+ <idle>-0 [002] d..3. 1.602298: mpage_end_io <-blk_update_request object:0xffff88811bee4000 value:0x0
+ <idle>-0 [002] d..3. 1.602298: __read_end_io <-blk_update_request object:0xffff88811bee4000 value:0x0
+ <idle>-0 [002] d..3. 1.602300: bio_put <-blk_update_request object:0xffff88811bee4000 value:0x0
+ <idle>-0 [002] d..3. 1.602300: bio_free <-blk_update_request object:0xffff88811bee4000 value:0x0
+ <idle>-0 [002] d..3. 1.602300: mempool_free <-blk_update_request object:0xffff88811bee4000 value:0x0
+ <idle>-0 [002] d..3. 1.602300: mempool_free_slab <-blk_update_request object:0xffff88811bee4000 value:0x0
+ <idle>-0 [002] d..3. 1.602300: kmem_cache_free <-blk_update_request object:0xffff88811bee4000 value:0x0
+ ...
+
7. In-kernel trace event API
============================
--
2.25.1
Hi Jeff,
Thank you for updating the series, I'm testing the series and found some
issues. See below;
On Sun, 30 Jan 2022 22:44:26 +0800
Jeff Xie <[email protected]> wrote:
> Introduce a method based on function tracer to trace any object and get
> the value of the object dynamically. the object can be obtained from the
> dynamic event (kprobe_event/uprobe_event) or the static event(tracepoint).
>
> Usage:
> When using the kprobe event, only need to set the objtrace(a new trigger),
> we can get the value of the object. The object is from the setting of the
> kprobe event.
>
> For example:
> For the function bio_add_page():
>
> int bio_add_page(struct bio *bio, struct page *page,
> unsigned int len, unsigned int offset)
>
> Firstly, we can set the base of the object, thus the first string "arg1"
> stands for the value of the first parameter of this function bio_add_gage(),
>
> # echo 'p bio_add_page arg1=$arg1' > ./kprobe_events
>
> Secondly, we can get the value dynamically based on above object.
>
> find the offset of the bi_size in struct bio:
> $ gdb vmlinux
> (gdb) p &(((struct bio *)0)->bi_iter.bi_size)
> $1 = (unsigned int *) 0x28
>
> # echo 'objtrace:add:arg1,0x28:u32:1 if comm == "cat"' > ./events/kprobes/ \
> p_bio_add_page_0/trigger
>
> # cd /sys/kernel/debug/tracing/
> # echo 'p bio_add_page arg1=$arg1' > ./kprobe_events
> # echo 'objtrace:add:arg1,0x28:u32:1 if comm == "cat"' > ./events/kprobes/p_bio_add_page_0/trigger
So doing after this command, I dumped the trigger file.
# cat events/kprobes/p_bio_add_page_0/trigger
objtrace:count=1 if comm == "cat"
This is not correct. All the parameters are dropped. Thus I can not
remove the trigger without knowing the original command.
# echo '!objtrace:count=1 if comm == "cat"' >> ./events/kprobes/p_bio_add_page_0/trigger
sh: write error: Invalid argument
And there are another minor issue is here;
# cd /sys/kernel/debug/tracing/
# echo 'p bio_add_page $arg1 $arg2' > ./kprobe_events
# echo 'objtrace:add:arg1,0x28:u32:1 if comm == "cat"' > ./events/kprobes/p_bio_add_page_0/trigger
# echo '!objtrace:add:arg2' >> events/kprobes/p_bio_add_page_0/trigger
Here, if I passed the "!objtrace:add:<a-field-exists-on-event>" then the objtrace
trigger was removed. But as you can see, the parameter is different.
Anyway, this is a minor issue, since we don't support multiple objtrace trigger
on the same event.
Could you fix these issues (and update the test case to check this?)
Thank you,
>
> # du -sh /test.txt
> 12.0K /test.txt
>
> # cat /test.txt > /dev/null
> # cat ./trace
> # tracer: nop
> #
> # entries-in-buffer/entries-written: 128/128 #P:4
> #
> # _-----=> irqs-off/BH-disabled
> # / _----=> need-resched
> # | / _---=> hardirq/softirq
> # || / _--=> preempt-depth
> # ||| / _-=> migrate-disable
> # |||| / delay
> # TASK-PID CPU# ||||| TIMESTAMP FUNCTION
> # | | | ||||| | |
> cat-117 [002] ...1. 1.602243: __bio_try_merge_page <-bio_add_page object:0xffff88811bee4000 value:0x0
> cat-117 [002] ...1. 1.602244: __bio_add_page <-bio_add_page object:0xffff88811bee4000 value:0x0
> cat-117 [002] ...2. 1.602244: bio_add_page <-ext4_mpage_readpages object:0xffff88811bee4000 value:0x1000
> cat-117 [002] ...1. 1.602245: __bio_try_merge_page <-bio_add_page object:0xffff88811bee4000 value:0x1000
> cat-117 [002] ...1. 1.602245: __bio_add_page <-bio_add_page object:0xffff88811bee4000 value:0x1000
> cat-117 [002] ...2. 1.602245: bio_add_page <-ext4_mpage_readpages object:0xffff88811bee4000 value:0x2000
> cat-117 [002] ...1. 1.602245: __bio_try_merge_page <-bio_add_page object:0xffff88811bee4000 value:0x2000
> cat-117 [002] ...1. 1.602245: __bio_add_page <-bio_add_page object:0xffff88811bee4000 value:0x2000
> cat-117 [002] ...1. 1.602245: submit_bio <-ext4_mpage_readpages object:0xffff88811bee4000 value:0x3000
> cat-117 [002] ...1. 1.602245: submit_bio_noacct <-ext4_mpage_readpages object:0xffff88811bee4000 value:0x3000
> cat-117 [002] ...1. 1.602246: __submit_bio <-submit_bio_noacct object:0xffff88811bee4000 value:0x3000
> cat-117 [002] ...1. 1.602246: submit_bio_checks <-__submit_bio object:0xffff88811bee4000 value:0x3000
> cat-117 [002] ...1. 1.602246: __cond_resched <-submit_bio_checks object:0xffff88811bee4000 value:0x3000
> cat-117 [002] ...1. 1.602246: should_fail_bio <-submit_bio_checks object:0xffff88811bee4000 value:0x3000
> cat-117 [002] ...1. 1.602246: blk_mq_submit_bio <-submit_bio_noacct object:0xffff88811bee4000 value:0x3000
> cat-117 [002] ...1. 1.602246: blk_attempt_plug_merge <-blk_mq_submit_bio object:0xffff88811bee4000 value:0x3000
> cat-117 [002] ...1. 1.602246: blk_mq_sched_bio_merge <-blk_mq_submit_bio object:0xffff88811bee4000 value:0x3000
> cat-117 [002] ...1. 1.602247: __rcu_read_lock <-blk_mq_submit_bio object:0xffff88811bee4000 value:0x3000
> cat-117 [002] ...1. 1.602247: __rcu_read_unlock <-blk_mq_submit_bio object:0xffff88811bee4000 value:0x3000
> cat-117 [002] ...1. 1.602247: __blk_mq_alloc_requests <-blk_mq_submit_bio object:0xffff88811bee4000 value:0x3000
> <idle>-0 [002] d..3. 1.602298: bio_endio <-blk_update_request object:0xffff88811bee4000 value:0x0
> <idle>-0 [002] d..3. 1.602298: mpage_end_io <-blk_update_request object:0xffff88811bee4000 value:0x0
> <idle>-0 [002] d..3. 1.602298: __read_end_io <-blk_update_request object:0xffff88811bee4000 value:0x0
> <idle>-0 [002] d..3. 1.602300: bio_put <-blk_update_request object:0xffff88811bee4000 value:0x0
> <idle>-0 [002] d..3. 1.602300: bio_free <-blk_update_request object:0xffff88811bee4000 value:0x0
> <idle>-0 [002] d..3. 1.602300: mempool_free <-blk_update_request object:0xffff88811bee4000 value:0x0
> <idle>-0 [002] d..3. 1.602300: mempool_free_slab <-blk_update_request object:0xffff88811bee4000 value:0x0
> <idle>-0 [002] d..3. 1.602300: kmem_cache_free <-blk_update_request object:0xffff88811bee4000 value:0x0
> ...
>
> Almost all changelogs were suggested by Masami([email protected])
> and steve([email protected]), thank you all so much.
>
> v8:
> - revert to use per-cpu recursion for the function trace_object_events_call
> - recover the filter when getting the value of the object
> - simplify the implementation for the function get_object_value
> - fix the build error
>
> v7:
> - use fixed-size array for object pool instead of list structure
> - use ftrace_test_recursion_trylock for function trace hook function
> - fix trace_object_ref reference count in the init_trace_object
> - invoke exit_trace_object no matter whether data->ops->free is null
> in the unregister_object_trigger
> - release private_data of event_trigger_data in the trace_object_trigger_free
> - remove [RFC] tag
>
> v6:
> - change the objtrace trigger syntax.
> - add patchset description
> - add <tracefs>/README
>
> v5:
> - add testcasts
> - add check the field->size
> - add lockless to search object
> - describe the object trace more clearly in Kconfig
>
> v4:
> - please ignore the v4 which is the same as v3
>
> v3:
> - change the objfilter to objtrace
> - add a command to the objfilter syntax
> - change to get the value of the object
> - use trace_find_event_field to find the field instead of using argN
> - get data from @rec in the event trigger callback funciton
>
> v2:
> - adding a "objfilter" trigger to update object
>
>
> Jeff Xie (4):
> trace: Add trace any kernel object
> trace/objtrace: get the value of the object
> trace/objtrace: Add testcases for objtrace
> trace/objtrace: Add documentation for objtrace
>
> Documentation/trace/events.rst | 83 +++
> include/linux/trace_events.h | 1 +
> kernel/trace/Kconfig | 10 +
> kernel/trace/Makefile | 1 +
> kernel/trace/trace.c | 3 +
> kernel/trace/trace.h | 8 +
> kernel/trace/trace_entries.h | 18 +
> kernel/trace/trace_events_trigger.c | 1 +
> kernel/trace/trace_object.c | 631 ++++++++++++++++++
> kernel/trace/trace_output.c | 40 ++
> .../ftrace/test.d/trigger/trigger-objtrace.tc | 39 ++
> 11 files changed, 835 insertions(+)
> create mode 100644 kernel/trace/trace_object.c
> create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-objtrace.tc
>
> --
> 2.25.1
>
--
Masami Hiramatsu <[email protected]>
Hi Masami,
On Mon, Jan 31, 2022 at 7:02 PM Masami Hiramatsu <[email protected]> wrote:
>
> Hi Jeff,
>
> Thank you for updating the series, I'm testing the series and found some
> issues. See below;
>
> On Sun, 30 Jan 2022 22:44:26 +0800
> Jeff Xie <[email protected]> wrote:
>
> > Introduce a method based on function tracer to trace any object and get
> > the value of the object dynamically. the object can be obtained from the
> > dynamic event (kprobe_event/uprobe_event) or the static event(tracepoint).
> >
> > Usage:
> > When using the kprobe event, only need to set the objtrace(a new trigger),
> > we can get the value of the object. The object is from the setting of the
> > kprobe event.
> >
> > For example:
> > For the function bio_add_page():
> >
> > int bio_add_page(struct bio *bio, struct page *page,
> > unsigned int len, unsigned int offset)
> >
> > Firstly, we can set the base of the object, thus the first string "arg1"
> > stands for the value of the first parameter of this function bio_add_gage(),
> >
> > # echo 'p bio_add_page arg1=$arg1' > ./kprobe_events
> >
> > Secondly, we can get the value dynamically based on above object.
> >
> > find the offset of the bi_size in struct bio:
> > $ gdb vmlinux
> > (gdb) p &(((struct bio *)0)->bi_iter.bi_size)
> > $1 = (unsigned int *) 0x28
> >
> > # echo 'objtrace:add:arg1,0x28:u32:1 if comm == "cat"' > ./events/kprobes/ \
> > p_bio_add_page_0/trigger
> >
> > # cd /sys/kernel/debug/tracing/
> > # echo 'p bio_add_page arg1=$arg1' > ./kprobe_events
> > # echo 'objtrace:add:arg1,0x28:u32:1 if comm == "cat"' > ./events/kprobes/p_bio_add_page_0/trigger
>
> So doing after this command, I dumped the trigger file.
>
> # cat events/kprobes/p_bio_add_page_0/trigger
> objtrace:count=1 if comm == "cat"
>
> This is not correct. All the parameters are dropped. Thus I can not
> remove the trigger without knowing the original command.
>
> # echo '!objtrace:count=1 if comm == "cat"' >> ./events/kprobes/p_bio_add_page_0/trigger
> sh: write error: Invalid argument
>
> And there are another minor issue is here;
>
> # cd /sys/kernel/debug/tracing/
> # echo 'p bio_add_page $arg1 $arg2' > ./kprobe_events
> # echo 'objtrace:add:arg1,0x28:u32:1 if comm == "cat"' > ./events/kprobes/p_bio_add_page_0/trigger
> # echo '!objtrace:add:arg2' >> events/kprobes/p_bio_add_page_0/trigger
>
> Here, if I passed the "!objtrace:add:<a-field-exists-on-event>" then the objtrace
> trigger was removed. But as you can see, the parameter is different.
> Anyway, this is a minor issue, since we don't support multiple objtrace trigger
> on the same event.
>
> Could you fix these issues (and update the test case to check this?)
Thanks for finding these issues, I will fix them.
> Thank you,
>
> >
> > # du -sh /test.txt
> > 12.0K /test.txt
> >
> > # cat /test.txt > /dev/null
> > # cat ./trace
> > # tracer: nop
> > #
> > # entries-in-buffer/entries-written: 128/128 #P:4
> > #
> > # _-----=> irqs-off/BH-disabled
> > # / _----=> need-resched
> > # | / _---=> hardirq/softirq
> > # || / _--=> preempt-depth
> > # ||| / _-=> migrate-disable
> > # |||| / delay
> > # TASK-PID CPU# ||||| TIMESTAMP FUNCTION
> > # | | | ||||| | |
> > cat-117 [002] ...1. 1.602243: __bio_try_merge_page <-bio_add_page object:0xffff88811bee4000 value:0x0
> > cat-117 [002] ...1. 1.602244: __bio_add_page <-bio_add_page object:0xffff88811bee4000 value:0x0
> > cat-117 [002] ...2. 1.602244: bio_add_page <-ext4_mpage_readpages object:0xffff88811bee4000 value:0x1000
> > cat-117 [002] ...1. 1.602245: __bio_try_merge_page <-bio_add_page object:0xffff88811bee4000 value:0x1000
> > cat-117 [002] ...1. 1.602245: __bio_add_page <-bio_add_page object:0xffff88811bee4000 value:0x1000
> > cat-117 [002] ...2. 1.602245: bio_add_page <-ext4_mpage_readpages object:0xffff88811bee4000 value:0x2000
> > cat-117 [002] ...1. 1.602245: __bio_try_merge_page <-bio_add_page object:0xffff88811bee4000 value:0x2000
> > cat-117 [002] ...1. 1.602245: __bio_add_page <-bio_add_page object:0xffff88811bee4000 value:0x2000
> > cat-117 [002] ...1. 1.602245: submit_bio <-ext4_mpage_readpages object:0xffff88811bee4000 value:0x3000
> > cat-117 [002] ...1. 1.602245: submit_bio_noacct <-ext4_mpage_readpages object:0xffff88811bee4000 value:0x3000
> > cat-117 [002] ...1. 1.602246: __submit_bio <-submit_bio_noacct object:0xffff88811bee4000 value:0x3000
> > cat-117 [002] ...1. 1.602246: submit_bio_checks <-__submit_bio object:0xffff88811bee4000 value:0x3000
> > cat-117 [002] ...1. 1.602246: __cond_resched <-submit_bio_checks object:0xffff88811bee4000 value:0x3000
> > cat-117 [002] ...1. 1.602246: should_fail_bio <-submit_bio_checks object:0xffff88811bee4000 value:0x3000
> > cat-117 [002] ...1. 1.602246: blk_mq_submit_bio <-submit_bio_noacct object:0xffff88811bee4000 value:0x3000
> > cat-117 [002] ...1. 1.602246: blk_attempt_plug_merge <-blk_mq_submit_bio object:0xffff88811bee4000 value:0x3000
> > cat-117 [002] ...1. 1.602246: blk_mq_sched_bio_merge <-blk_mq_submit_bio object:0xffff88811bee4000 value:0x3000
> > cat-117 [002] ...1. 1.602247: __rcu_read_lock <-blk_mq_submit_bio object:0xffff88811bee4000 value:0x3000
> > cat-117 [002] ...1. 1.602247: __rcu_read_unlock <-blk_mq_submit_bio object:0xffff88811bee4000 value:0x3000
> > cat-117 [002] ...1. 1.602247: __blk_mq_alloc_requests <-blk_mq_submit_bio object:0xffff88811bee4000 value:0x3000
> > <idle>-0 [002] d..3. 1.602298: bio_endio <-blk_update_request object:0xffff88811bee4000 value:0x0
> > <idle>-0 [002] d..3. 1.602298: mpage_end_io <-blk_update_request object:0xffff88811bee4000 value:0x0
> > <idle>-0 [002] d..3. 1.602298: __read_end_io <-blk_update_request object:0xffff88811bee4000 value:0x0
> > <idle>-0 [002] d..3. 1.602300: bio_put <-blk_update_request object:0xffff88811bee4000 value:0x0
> > <idle>-0 [002] d..3. 1.602300: bio_free <-blk_update_request object:0xffff88811bee4000 value:0x0
> > <idle>-0 [002] d..3. 1.602300: mempool_free <-blk_update_request object:0xffff88811bee4000 value:0x0
> > <idle>-0 [002] d..3. 1.602300: mempool_free_slab <-blk_update_request object:0xffff88811bee4000 value:0x0
> > <idle>-0 [002] d..3. 1.602300: kmem_cache_free <-blk_update_request object:0xffff88811bee4000 value:0x0
> > ...
> >
> > Almost all changelogs were suggested by Masami([email protected])
> > and steve([email protected]), thank you all so much.
> >
> > v8:
> > - revert to use per-cpu recursion for the function trace_object_events_call
> > - recover the filter when getting the value of the object
> > - simplify the implementation for the function get_object_value
> > - fix the build error
> >
> > v7:
> > - use fixed-size array for object pool instead of list structure
> > - use ftrace_test_recursion_trylock for function trace hook function
> > - fix trace_object_ref reference count in the init_trace_object
> > - invoke exit_trace_object no matter whether data->ops->free is null
> > in the unregister_object_trigger
> > - release private_data of event_trigger_data in the trace_object_trigger_free
> > - remove [RFC] tag
> >
> > v6:
> > - change the objtrace trigger syntax.
> > - add patchset description
> > - add <tracefs>/README
> >
> > v5:
> > - add testcasts
> > - add check the field->size
> > - add lockless to search object
> > - describe the object trace more clearly in Kconfig
> >
> > v4:
> > - please ignore the v4 which is the same as v3
> >
> > v3:
> > - change the objfilter to objtrace
> > - add a command to the objfilter syntax
> > - change to get the value of the object
> > - use trace_find_event_field to find the field instead of using argN
> > - get data from @rec in the event trigger callback funciton
> >
> > v2:
> > - adding a "objfilter" trigger to update object
> >
> >
> > Jeff Xie (4):
> > trace: Add trace any kernel object
> > trace/objtrace: get the value of the object
> > trace/objtrace: Add testcases for objtrace
> > trace/objtrace: Add documentation for objtrace
> >
> > Documentation/trace/events.rst | 83 +++
> > include/linux/trace_events.h | 1 +
> > kernel/trace/Kconfig | 10 +
> > kernel/trace/Makefile | 1 +
> > kernel/trace/trace.c | 3 +
> > kernel/trace/trace.h | 8 +
> > kernel/trace/trace_entries.h | 18 +
> > kernel/trace/trace_events_trigger.c | 1 +
> > kernel/trace/trace_object.c | 631 ++++++++++++++++++
> > kernel/trace/trace_output.c | 40 ++
> > .../ftrace/test.d/trigger/trigger-objtrace.tc | 39 ++
> > 11 files changed, 835 insertions(+)
> > create mode 100644 kernel/trace/trace_object.c
> > create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-objtrace.tc
> >
> > --
> > 2.25.1
> >
>
>
> --
> Masami Hiramatsu <[email protected]>
---
JeffXie