From nobody Sun Sep 14 08:41:53 2025 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id E8030C54E94 for ; Wed, 25 Jan 2023 17:14:25 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S236184AbjAYROX (ORCPT ); Wed, 25 Jan 2023 12:14:23 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:38678 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S236084AbjAYRN7 (ORCPT ); Wed, 25 Jan 2023 12:13:59 -0500 Received: from ams.source.kernel.org (ams.source.kernel.org [145.40.68.75]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id DC355EB59 for ; Wed, 25 Jan 2023 09:13:54 -0800 (PST) Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by ams.source.kernel.org (Postfix) with ESMTPS id B0A0BB81B60 for ; Wed, 25 Jan 2023 17:13:42 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 366E7C433B4; Wed, 25 Jan 2023 17:13:41 +0000 (UTC) Received: from rostedt by gandalf.local.home with local (Exim 4.96) (envelope-from ) id 1pKjLA-004Nu9-0u; Wed, 25 Jan 2023 12:13:40 -0500 Message-ID: <20230125171340.102429648@goodmis.org> User-Agent: quilt/0.66 Date: Wed, 25 Jan 2023 12:13:01 -0500 From: Steven Rostedt To: linux-kernel@vger.kernel.org Cc: Masami Hiramatsu , Andrew Morton , Tom Zanussi , Ross Zwisler , Ching-lin Yu Subject: [for-next][PATCH 09/12] tracing/histogram: Document variable stacktrace References: <20230125171252.431857411@goodmis.org> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset="utf-8" From: "Steven Rostedt (Google)" 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 Cc: Andrew Morton Cc: Tom Zanussi Cc: Ross Zwisler Cc: Ching-lin Yu Signed-off-by: Steven Rostedt (Google) --- Documentation/trace/histogram.rst | 129 ++++++++++++++++++++++++++++++ 1 file changed, 129 insertions(+) diff --git a/Documentation/trace/histogram.rst b/Documentation/trace/histog= ram.rst index f95459aa984f..5c391328b9bb 100644 --- a/Documentation/trace/histogram.rst +++ b/Documentation/trace/histogram.rst @@ -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) =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D =20 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 subsequ= ent expression:: # echo 'hist:keys=3Dnext_pid:us_per_sec=3D1000000 ...' >> event/trigger # echo 'hist:keys=3Dnext_pid:timestamp_secs=3Dcommon_timestamp/$us_per_s= ec ...' >> event/trigger =20 +Variables can even hold stacktraces, which are useful with synthetic event= s. + 2.2.2 Synthetic Events ---------------------- =20 @@ -1940,6 +1943,132 @@ the ".buckets" modifier and specify a size (in this= case groups of 10). Entries: 16 Dropped: 0 =20 +To save stacktraces, create a synthetic event with a field of type "unsign= ed 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;' > dyna= mic_events + # echo 'hist:keys=3Dnext_pid:ts=3Dcommon_timestamp.usecs,st=3Dstacktrace= if prev_state =3D=3D 2' >> events/sched/sched_switch/trigger + # echo 'hist:keys=3Dprev_pid:delta=3Dcommon_timestamp.usecs-$ts,s=3D$st:= onmax($delta).trace(block_lat,prev_pid,$delta,$s)' >> events/sched/sched_sw= itch/trigger + # echo 1 > events/synthetic/block_lat/enable + # cat trace + + # tracer: nop + # + # entries-in-buffer/entries-written: 2/2 #P:8 + # + # _-----=3D> irqs-off/BH-disabled + # / _----=3D> need-resched + # | / _---=3D> hardirq/softirq + # || / _--=3D> preempt-depth + # ||| / _-=3D> migrate-disable + # |||| / delay + # TASK-PID CPU# ||||| TIMESTAMP FUNCTION + # | | | ||||| | | + -0 [005] d..4. 521.164922: block_lat: pid=3D0 de= lta=3D8322 stack=3DSTACK: + =3D> __schedule+0x448/0x7b0 + =3D> schedule+0x5a/0xb0 + =3D> io_schedule+0x42/0x70 + =3D> bit_wait_io+0xd/0x60 + =3D> __wait_on_bit+0x4b/0x140 + =3D> out_of_line_wait_on_bit+0x91/0xb0 + =3D> jbd2_journal_commit_transaction+0x1679/0x1a70 + =3D> kjournald2+0xa9/0x280 + =3D> kthread+0xe9/0x110 + =3D> ret_from_fork+0x2c/0x50 + + <...>-2 [004] d..4. 525.184257: block_lat: pid=3D2 de= lta=3D76 stack=3DSTACK: + =3D> __schedule+0x448/0x7b0 + =3D> schedule+0x5a/0xb0 + =3D> schedule_timeout+0x11a/0x150 + =3D> wait_for_completion_killable+0x144/0x1f0 + =3D> __kthread_create_on_node+0xe7/0x1e0 + =3D> kthread_create_on_node+0x51/0x70 + =3D> create_worker+0xcc/0x1a0 + =3D> worker_thread+0x2ad/0x380 + =3D> kthread+0xe9/0x110 + =3D> ret_from_fork+0x2c/0x50 + +A synthetic event that has a stacktrace field may use it as a key in histo= gram: + + # echo 'hist:delta.buckets=3D100,stack.stacktrace:sort=3Ddelta' > events= /synthetic/block_lat/trigger + # cat events/synthetic/block_lat/hist + + # event histogram + # + # trigger info: hist:keys=3Ddelta.buckets=3D100,stacktrace:vals=3Dhitcou= nt:sort=3Ddelta.buckets=3D100:size=3D2048 [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' ------------------------------------------- =20 --=20 2.39.0