2022-06-06 16:27:24

by Jeff Xie

[permalink] [raw]
Subject: [PATCH v12 0/4] trace: Introduce objtrace trigger to trace the kernel object

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.

v12:
- use the %zu to print the sizeof
Reported-by: kernel test robot <[email protected]>
Suggested-by: Nathan Chancellor <[email protected]>

v11:
- remove useless atomic counting methods for num_traced_obj
- make array objtrace_fetch_types null terminated
- add raw_spin_lock_init for obj_data_lock

v10:
- support ftrace instances
- use trace_buffer_lock_reserve instead of trace_event_buffer_lock_reserve
- a lot of cleanup work has been done mainly for event_object_trigger_parse

v9:
- fix objtrace trigger output was incomplete
- fix the objtrace trigger was removed when using the existed parameter on
event.
- add testcase for the second fix above.

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 | 11 +
kernel/trace/trace.h | 21 +
kernel/trace/trace_entries.h | 18 +
kernel/trace/trace_events_trigger.c | 5 +-
kernel/trace/trace_object.c | 615 ++++++++++++++++++
kernel/trace/trace_output.c | 40 ++
.../ftrace/test.d/trigger/trigger-objtrace.tc | 41 ++
11 files changed, 844 insertions(+), 2 deletions(-)
create mode 100644 kernel/trace/trace_object.c
create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-objtrace.tc

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 | 11 +
kernel/trace/trace.h | 21 +
kernel/trace/trace_entries.h | 18 +
kernel/trace/trace_events_trigger.c | 5 +-
kernel/trace/trace_object.c | 615 ++++++++++++++++++
kernel/trace/trace_output.c | 40 ++
.../ftrace/test.d/trigger/trigger-objtrace.tc | 41 ++
11 files changed, 844 insertions(+), 2 deletions(-)
create mode 100644 kernel/trace/trace_object.c
create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-objtrace.tc


base-commit: b39181f7c6907dc66ff937b74758671fa6ba430c
--
2.25.1


2022-06-06 16:27:26

by Jeff Xie

[permalink] [raw]
Subject: [PATCH v12 4/4] trace/objtrace: Add documentation for objtrace

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..0dc475160133 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

2022-06-21 02:01:19

by Jeff Xie

[permalink] [raw]
Subject: Re: [PATCH v12 0/4] trace: Introduce objtrace trigger to trace the kernel object

Hi Steve and Masami,

I wonder if there are any suggestions for this v12 ;-)

On Tue, Jun 7, 2022 at 12:10 AM 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
>
> # 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.
>
> v12:
> - use the %zu to print the sizeof
> Reported-by: kernel test robot <[email protected]>
> Suggested-by: Nathan Chancellor <[email protected]>
>
> v11:
> - remove useless atomic counting methods for num_traced_obj
> - make array objtrace_fetch_types null terminated
> - add raw_spin_lock_init for obj_data_lock
>
> v10:
> - support ftrace instances
> - use trace_buffer_lock_reserve instead of trace_event_buffer_lock_reserve
> - a lot of cleanup work has been done mainly for event_object_trigger_parse
>
> v9:
> - fix objtrace trigger output was incomplete
> - fix the objtrace trigger was removed when using the existed parameter on
> event.
> - add testcase for the second fix above.
>
> 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 | 11 +
> kernel/trace/trace.h | 21 +
> kernel/trace/trace_entries.h | 18 +
> kernel/trace/trace_events_trigger.c | 5 +-
> kernel/trace/trace_object.c | 615 ++++++++++++++++++
> kernel/trace/trace_output.c | 40 ++
> .../ftrace/test.d/trigger/trigger-objtrace.tc | 41 ++
> 11 files changed, 844 insertions(+), 2 deletions(-)
> create mode 100644 kernel/trace/trace_object.c
> create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-objtrace.tc
>
> 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 | 11 +
> kernel/trace/trace.h | 21 +
> kernel/trace/trace_entries.h | 18 +
> kernel/trace/trace_events_trigger.c | 5 +-
> kernel/trace/trace_object.c | 615 ++++++++++++++++++
> kernel/trace/trace_output.c | 40 ++
> .../ftrace/test.d/trigger/trigger-objtrace.tc | 41 ++
> 11 files changed, 844 insertions(+), 2 deletions(-)
> create mode 100644 kernel/trace/trace_object.c
> create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-objtrace.tc
>
>
> base-commit: b39181f7c6907dc66ff937b74758671fa6ba430c
> --
> 2.25.1
>
Thanks,
JeffXie

2022-06-25 16:27:54

by Masami Hiramatsu

[permalink] [raw]
Subject: Re: [PATCH v12 4/4] trace/objtrace: Add documentation for objtrace

Hi Jeff,

OK, this looks good to me.

Reviewed-by: Masami Hiramatsu (Google) <[email protected]>

And just a note that please add 'Documentation:' tag to the title
and Cc to [email protected] and Jonathan Corbet too since
this is a patch for the Documentation/*.

Thank you,

On Tue, 7 Jun 2022 00:09:43 +0800
Jeff Xie <[email protected]> wrote:

> 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..0dc475160133 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
>


--
Masami Hiramatsu (Google) <[email protected]>

2022-06-25 17:37:11

by Jeff Xie

[permalink] [raw]
Subject: Re: [PATCH v12 4/4] trace/objtrace: Add documentation for objtrace

Hi Masami,

On Sun, Jun 26, 2022 at 12:10 AM Masami Hiramatsu <[email protected]> wrote:
>
> Hi Jeff,
>
> OK, this looks good to me.
>
> Reviewed-by: Masami Hiramatsu (Google) <[email protected]>
>
> And just a note that please add 'Documentation:' tag to the title
> and Cc to [email protected] and Jonathan Corbet too since
> this is a patch for the Documentation/*.

Thanks for the reminder, I will do it like this in my next version.

> Thank you,
>
> On Tue, 7 Jun 2022 00:09:43 +0800
> Jeff Xie <[email protected]> wrote:
>
> > 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..0dc475160133 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
> >
>
>
> --
> Masami Hiramatsu (Google) <[email protected]>

Thanks,
JeffXie