From nobody Mon Sep 15 03:56:28 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 32068C63797 for ; Tue, 17 Jan 2023 04:41:28 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S235450AbjAQEl0 (ORCPT ); Mon, 16 Jan 2023 23:41:26 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:59386 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S235362AbjAQElL (ORCPT ); Mon, 16 Jan 2023 23:41:11 -0500 Received: from dfw.source.kernel.org (dfw.source.kernel.org [IPv6:2604:1380:4641:c500::1]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 655211A48D; Mon, 16 Jan 2023 20:41:03 -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 dfw.source.kernel.org (Postfix) with ESMTPS id F280C611B6; Tue, 17 Jan 2023 04:41:02 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 60D40C4339B; Tue, 17 Jan 2023 04:41:02 +0000 (UTC) Received: from rostedt by gandalf.local.home with local (Exim 4.96) (envelope-from ) id 1pHdmP-001rt8-1K; Mon, 16 Jan 2023 23:41:01 -0500 Message-ID: <20230117044101.274203396@goodmis.org> User-Agent: quilt/0.66 Date: Mon, 16 Jan 2023 23:40:14 -0500 From: Steven Rostedt To: linux-kernel@vger.kernel.org, linux-trace-kernel@vger.kernel.org Cc: Masami Hiramatsu , Andrew Morton , Ross Zwisler Subject: [PATCH 4/5] tracing/histogram: Document variable stacktrace References: <20230117044010.838685230@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. Signed-off-by: Steven Rostedt (Google) --- Documentation/trace/histogram.rst | 49 +++++++++++++++++++++++++++++++ 1 file changed, 49 insertions(+) diff --git a/Documentation/trace/histogram.rst b/Documentation/trace/histog= ram.rst index f95459aa984f..5b7f985f35d9 100644 --- a/Documentation/trace/histogram.rst +++ b/Documentation/trace/histogram.rst @@ -1786,6 +1786,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 +1942,53 @@ 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 + 2.2.3 Hist trigger 'handlers' and 'actions' ------------------------------------------- =20 --=20 2.39.0