Commit 88238513 authored by Steven Rostedt (Google)'s avatar Steven Rostedt (Google)
Browse files

tracing/histogram: Document variable stacktrace 

Add a little documentation (and a useful example) of how a stacktrace can
be used within a histogram variable and synthetic event.

Link: https://lkml.kernel.org/r/20230117152236.320181354@goodmis.org



Cc: Masami Hiramatsu <mhiramat@kernel.org>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Tom Zanussi <zanussi@kernel.org>
Cc: Ross Zwisler <zwisler@google.com>
Cc: Ching-lin Yu <chinglinyu@google.com>
Signed-off-by: default avatarSteven Rostedt (Google) <rostedt@goodmis.org>
parent cc5fc8bf

Documentation/trace/histogram.rst

+129 −0
Original line number Diff line number Diff line
@@ -81,6 +81,7 @@ Documentation written by Tom Zanussi 
	.usecs         display a common_timestamp in microseconds

        .percent       display a number of percentage value

        .graph         display a bar-graph of a value

	.stacktrace    display as a stacktrace (must by a long[] type)

	=============  =================================================



  Note that in general the semantics of a given field aren't
@@ -1786,6 +1787,8 @@ or assigned to a variable and referenced in a subsequent expression:: 
  # echo 'hist:keys=next_pid:us_per_sec=1000000 ...' >> event/trigger

  # echo 'hist:keys=next_pid:timestamp_secs=common_timestamp/$us_per_sec ...' >> event/trigger



Variables can even hold stacktraces, which are useful with synthetic events.



2.2.2 Synthetic Events

----------------------
@@ -1940,6 +1943,132 @@ the ".buckets" modifier and specify a size (in this case groups of 10). 
      Entries: 16

      Dropped: 0



To save stacktraces, create a synthetic event with a field of type "unsigned long[]"

or even just "long[]". For example, to see how long a task is blocked in an

uninterruptible state:



  # cd /sys/kernel/tracing

  # echo 's:block_lat pid_t pid; u64 delta; unsigned long[] stack;' > dynamic_events

  # echo 'hist:keys=next_pid:ts=common_timestamp.usecs,st=stacktrace  if prev_state == 2' >> events/sched/sched_switch/trigger

  # echo 'hist:keys=prev_pid:delta=common_timestamp.usecs-$ts,s=$st:onmax($delta).trace(block_lat,prev_pid,$delta,$s)' >> events/sched/sched_switch/trigger

  # echo 1 > events/synthetic/block_lat/enable

  # cat trace



  # tracer: nop

  #

  # entries-in-buffer/entries-written: 2/2   #P:8

  #

  #                                _-----=> irqs-off/BH-disabled

  #                               / _----=> need-resched

  #                              | / _---=> hardirq/softirq

  #                              || / _--=> preempt-depth

  #                              ||| / _-=> migrate-disable

  #                              |||| /     delay

  #           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION

  #              | |         |   |||||     |         |

            <idle>-0       [005] d..4.   521.164922: block_lat: pid=0 delta=8322 stack=STACK:

  => __schedule+0x448/0x7b0

  => schedule+0x5a/0xb0

  => io_schedule+0x42/0x70

  => bit_wait_io+0xd/0x60

  => __wait_on_bit+0x4b/0x140

  => out_of_line_wait_on_bit+0x91/0xb0

  => jbd2_journal_commit_transaction+0x1679/0x1a70

  => kjournald2+0xa9/0x280

  => kthread+0xe9/0x110

  => ret_from_fork+0x2c/0x50



             <...>-2       [004] d..4.   525.184257: block_lat: pid=2 delta=76 stack=STACK:

  => __schedule+0x448/0x7b0

  => schedule+0x5a/0xb0

  => schedule_timeout+0x11a/0x150

  => wait_for_completion_killable+0x144/0x1f0

  => __kthread_create_on_node+0xe7/0x1e0

  => kthread_create_on_node+0x51/0x70

  => create_worker+0xcc/0x1a0

  => worker_thread+0x2ad/0x380

  => kthread+0xe9/0x110

  => ret_from_fork+0x2c/0x50



A synthetic event that has a stacktrace field may use it as a key in histogram:



  # echo 'hist:delta.buckets=100,stack.stacktrace:sort=delta' > events/synthetic/block_lat/trigger

  # cat events/synthetic/block_lat/hist



  # event histogram

  #

  # trigger info: hist:keys=delta.buckets=100,stacktrace:vals=hitcount:sort=delta.buckets=100:size=2048 [active]

  #



  { delta: ~ 0-99, stacktrace:

           event_hist_trigger+0x464/0x480

           event_triggers_call+0x52/0xe0

           trace_event_buffer_commit+0x193/0x250

           trace_event_raw_event_sched_switch+0xfc/0x150

           __traceiter_sched_switch+0x41/0x60

           __schedule+0x448/0x7b0

           schedule_idle+0x26/0x40

           cpu_startup_entry+0x19/0x20

           start_secondary+0xed/0xf0

           secondary_startup_64_no_verify+0xe0/0xeb

  } hitcount:          6

  { delta: ~ 0-99, stacktrace:

           event_hist_trigger+0x464/0x480

           event_triggers_call+0x52/0xe0

           trace_event_buffer_commit+0x193/0x250

           trace_event_raw_event_sched_switch+0xfc/0x150

           __traceiter_sched_switch+0x41/0x60

           __schedule+0x448/0x7b0

           schedule_idle+0x26/0x40

           cpu_startup_entry+0x19/0x20

           __pfx_kernel_init+0x0/0x10

           arch_call_rest_init+0xa/0x24

           start_kernel+0x964/0x98d

           secondary_startup_64_no_verify+0xe0/0xeb

  } hitcount:          3

  { delta: ~ 0-99, stacktrace:

           event_hist_trigger+0x464/0x480

           event_triggers_call+0x52/0xe0

           trace_event_buffer_commit+0x193/0x250

           trace_event_raw_event_sched_switch+0xfc/0x150

           __traceiter_sched_switch+0x41/0x60

           __schedule+0x448/0x7b0

           schedule+0x5a/0xb0

           worker_thread+0xaf/0x380

           kthread+0xe9/0x110

           ret_from_fork+0x2c/0x50

  } hitcount:          1

  { delta: ~ 100-199, stacktrace:

           event_hist_trigger+0x464/0x480

           event_triggers_call+0x52/0xe0

           trace_event_buffer_commit+0x193/0x250

           trace_event_raw_event_sched_switch+0xfc/0x150

           __traceiter_sched_switch+0x41/0x60

           __schedule+0x448/0x7b0

           schedule_idle+0x26/0x40

           cpu_startup_entry+0x19/0x20

           start_secondary+0xed/0xf0

           secondary_startup_64_no_verify+0xe0/0xeb

  } hitcount:         15

  [..]

  { delta: ~ 8500-8599, stacktrace:

           event_hist_trigger+0x464/0x480

           event_triggers_call+0x52/0xe0

           trace_event_buffer_commit+0x193/0x250

           trace_event_raw_event_sched_switch+0xfc/0x150

           __traceiter_sched_switch+0x41/0x60

           __schedule+0x448/0x7b0

           schedule_idle+0x26/0x40

           cpu_startup_entry+0x19/0x20

           start_secondary+0xed/0xf0

           secondary_startup_64_no_verify+0xe0/0xeb

  } hitcount:          1



  Totals:

      Hits: 89

      Entries: 11

      Dropped: 0



2.2.3 Hist trigger 'handlers' and 'actions'

-------------------------------------------