Re: [PATCH v14 4/4] Documentation: trace/objtrace: Add documentation for objtrace

[Joel Fernandes <joel@joelfernandes.org>]

On Tue, Jun 28, 2022 at 10:55:52PM +0800, Jeff Xie wrote:
> Add documentation explaining how to use objtrace trigger to get the value
> of the object.
> 
> Cc: Jonathan Corbet <corbet@lwn.net>
> Cc: Bagas Sanjaya <bagasdotme@gmail.com>
> Cc: linux-doc@vger.kernel.org
> Signed-off-by: Jeff Xie <xiehuan09@gmail.com>
> Reviewed-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
> ---
> Changelog:
> v14:
> - make documentation more readable and fix literal code block by Bagas Sanjaya
> 
>  Documentation/trace/events.rst | 87 ++++++++++++++++++++++++++++++++++
>  1 file changed, 87 insertions(+)
> 
> diff --git a/Documentation/trace/events.rst b/Documentation/trace/events.rst
> index c47f381d0c00..c15f1d25d4a0 100644
> --- a/Documentation/trace/events.rst
> +++ b/Documentation/trace/events.rst
> @@ -546,6 +546,93 @@ 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, by only need to set the objtrace (a new
> +  trigger), we can get the value of object that is set by kprobe event.
> +
> +  For example, for the function bio_add_page():
> +
> +  .. code-block:: c
> +
> +     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 as first parameter (arg1) to
> +  to the function:
> +
> +  .. code-block::
> +
> +     # echo 'p bio_add_page arg1=$arg1' > ./kprobe_events
> +
> +  Secondly, we can get the value dynamically based on the object:
> +
> +  .. code-block::
> +
> +     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

No offense but this documentation is not well written and hard to read.

Admittedly though I am just casually browsing through, so apologies.

So basically, 0x28 is the offset of the u32 within the bio, that you want to
track down, as it passes through functions?

The example is good, but I suggest breakdown each of the commands separated
by ':' and document those as well.

Cool feature though, I can see myself using it for something (dunno what yet) :)

thanks,

 - Joel



> +
> +     # 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
>