From nobody Sun Sep 14 18:43:35 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 620FBC677F1 for ; Thu, 19 Jan 2023 00:51:46 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S229818AbjASAvp (ORCPT ); Wed, 18 Jan 2023 19:51:45 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:57872 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S229658AbjASAvn (ORCPT ); Wed, 18 Jan 2023 19:51:43 -0500 Received: from mail-pj1-x1049.google.com (mail-pj1-x1049.google.com [IPv6:2607:f8b0:4864:20::1049]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 9B370613C8 for ; Wed, 18 Jan 2023 16:51:42 -0800 (PST) Received: by mail-pj1-x1049.google.com with SMTP id o16-20020a17090ac71000b00229ba85bc63so265967pjt.7 for ; Wed, 18 Jan 2023 16:51:42 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=20210112; h=cc:to:from:subject:message-id:mime-version:date:from:to:cc:subject :date:message-id:reply-to; bh=SILF59q15LnVQh8plXcv+E/BH5WNM7aTOCdlXngaCY0=; b=StxTGeFH9g3spsNheciX6sSviGPedGFhgWqUlo5a7VSNR2BNRGAsgi2FMiHvAsvfkd hcDQveWxTy3Qk1P2GHTf+mkfdUx/OOfHtJuoe01Lb0iAKLUOhTVkSR/mpPxJV+sWPZY4 mPhoPzrWKQclAIHDLtSaEcN3ctZ7t1Zbcrj81e/kPjVKxyfgtebUYjJPNjFsaeMN1aAJ BlPOGIput9CnBYA6Z+z1lsK/k1mtA+2PvhnoVi0i9KGPCIw2Z8DxOacTpUBrjxJFVpNQ YKu0Uv8eNiy8ym2jBkz1CLYNAmJRbKrRe/+Wx/SP1lA5tDK6ndzHp4N53wyaQAUoKTL8 FIlg== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=cc:to:from:subject:message-id:mime-version:date:x-gm-message-state :from:to:cc:subject:date:message-id:reply-to; bh=SILF59q15LnVQh8plXcv+E/BH5WNM7aTOCdlXngaCY0=; b=cZWxl7I6lf2QMvfyEUuzJBBFbPo9DInSPDaiGdeFDTLuUIYgWbqZop/K7rDfIBTc90 phsu2LSe8jeBLd+UwOw63HMMplkLCqZUbmZDRdv5hn9c4UXUZ6NqXFpsVMlbvsTmYAbL f83NLimllc54gu59Sgb0A4QyO/VT1Am/p9Xp+7DqzaNhsXXPF2Aq61jNQ07hQD6GV+mO Dy6TPamHJDwXRZhvxo1StNIoe4F2d9Tg7e1rTZJHbc/D/prxzlQC3bsJ9ByzctCTB2zN rbpp+Kq1e2ktynAtgUiqDL0SxyttHGKKooJT9l7ZtCR19sfRBAynjYz2aTySs2A0FQxi qOvg== X-Gm-Message-State: AFqh2kqoxaDSshwn1lzPJxfgNbp5As+tV+Sgc6igtYiIMTK7Ci3qsoiC +M+Vx4Yq5Pq0iY3qc5RdmJ+/ATN7mF0/2HVjG/JQ7jvQQNuSIMEYhKs3B6MxTm3X3TDJWkN9Gyk ilt3N/KQFzoGxTBm9FKabmW6aepIbsD3Dalm7G1cBFNrvLZtS1TeAcfLHFcU1GRoWEt4w5ro= X-Google-Smtp-Source: AMrXdXtXiHCaWCI+/F+BpL76DvVXpN6dVV5TefJfKxkgoq2CEaesChCXwsloq2uOK1eEKrhKz13ODPYGnYMd X-Received: from jstultz-noogler2.c.googlers.com ([fda3:e722:ac3:cc00:24:72f4:c0a8:600]) (user=jstultz job=sendgmr) by 2002:a17:90b:1d05:b0:227:1217:9f1d with SMTP id on5-20020a17090b1d0500b0022712179f1dmr999573pjb.196.1674089502005; Wed, 18 Jan 2023 16:51:42 -0800 (PST) Date: Thu, 19 Jan 2023 00:51:38 +0000 Mime-Version: 1.0 X-Mailer: git-send-email 2.39.0.246.g2a6d74b583-goog Message-ID: <20230119005138.759086-1-jstultz@google.com> Subject: [PATCH v3] trace: Add trace points for tasklet entry/exit From: John Stultz To: LKML Cc: Lingutla Chandrasekhar , Steven Rostedt , Masami Hiramatsu , Thomas Gleixner , "Paul E. McKenney" , "Connor O'Brien" , kernel-team@android.com, "J . Avila" , John Stultz 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: Lingutla Chandrasekhar Tasklets are supposed to finish their work quickly and should not block the current running process, but it is not guaranteed that. Currently softirq_entry/exit can be used to know total tasklets execution time, but not helpful to track individual tasklet's execution time. With that we can't find any culprit tasklet function, which is taking more time. Add tasklet_entry/exit trace point support to track individual tasklet execution. Trivial usage example: # echo 1 > /sys/kernel/debug/tracing/events/irq/tasklet_entry/enable # echo 1 > /sys/kernel/debug/tracing/events/irq/tasklet_exit/enable # cat /sys/kernel/debug/tracing/trace # tracer: nop # # entries-in-buffer/entries-written: 4/4 #P:4 # # _-----=3D> irqs-off/BH-disabled # / _----=3D> need-resched # | / _---=3D> hardirq/softirq # || / _--=3D> preempt-depth # ||| / _-=3D> migrate-disable # |||| / delay # TASK-PID CPU# ||||| TIMESTAMP FUNCTION # | | | ||||| | | -0 [003] ..s1. 314.011428: tasklet_entry: tasklet= =3D0xffffa01ef8db2740 function=3Dtcp_tasklet_func -0 [003] ..s1. 314.011432: tasklet_exit: tasklet= =3D0xffffa01ef8db2740 function=3Dtcp_tasklet_func -0 [003] ..s1. 314.017369: tasklet_entry: tasklet= =3D0xffffa01ef8db2740 function=3Dtcp_tasklet_func -0 [003] ..s1. 314.017371: tasklet_exit: tasklet= =3D0xffffa01ef8db2740 function=3Dtcp_tasklet_func This patch has been carried in the Android tree for awhile so I wanted to submit it for review upstream. Feedback would be appreciated! Cc: Steven Rostedt Cc: Masami Hiramatsu Cc: Thomas Gleixner Cc: "Paul E. McKenney" Cc: Connor O'Brien Cc: kernel-team@android.com Reviewed-by: Steven Rostedt (Google) Signed-off-by: Lingutla Chandrasekhar [elavila: Port to android-mainline] Signed-off-by: J. Avila [jstultz: Rebased to upstream, cut unused trace points, added comments for the tracepoints, reworded commit] Signed-off-by: John Stultz --- v2: * Added tasklet pointer to the trace event as suggested by Steven v3: * Minor tweak to commit to show usage and output example --- include/trace/events/irq.h | 47 ++++++++++++++++++++++++++++++++++++++ kernel/softirq.c | 9 ++++++-- 2 files changed, 54 insertions(+), 2 deletions(-) diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h index eeceafaaea4c..a07b4607b663 100644 --- a/include/trace/events/irq.h +++ b/include/trace/events/irq.h @@ -160,6 +160,53 @@ DEFINE_EVENT(softirq, softirq_raise, TP_ARGS(vec_nr) ); =20 +DECLARE_EVENT_CLASS(tasklet, + + TP_PROTO(struct tasklet_struct *t, void *func), + + TP_ARGS(t, func), + + TP_STRUCT__entry( + __field( void *, tasklet) + __field( void *, func) + ), + + TP_fast_assign( + __entry->tasklet =3D t; + __entry->func =3D func; + ), + + TP_printk("tasklet=3D%ps function=3D%ps", __entry->tasklet, __entry->func) +); + +/** + * tasklet_entry - called immediately before the tasklet is run + * @t: tasklet pointer + * @func: tasklet callback or function being run + * + * Used to find individual tasklet execution time + */ +DEFINE_EVENT(tasklet, tasklet_entry, + + TP_PROTO(struct tasklet_struct *t, void *func), + + TP_ARGS(t, func) +); + +/** + * tasklet_exit - called immediately after the tasklet is run + * @t: tasklet pointer + * @func: tasklet callback or function being run + * + * Used to find individual tasklet execution time + */ +DEFINE_EVENT(tasklet, tasklet_exit, + + TP_PROTO(struct tasklet_struct *t, void *func), + + TP_ARGS(t, func) +); + #endif /* _TRACE_IRQ_H */ =20 /* This part must be outside protection */ diff --git a/kernel/softirq.c b/kernel/softirq.c index c8a6913c067d..1b725510dd0f 100644 --- a/kernel/softirq.c +++ b/kernel/softirq.c @@ -793,10 +793,15 @@ static void tasklet_action_common(struct softirq_acti= on *a, if (tasklet_trylock(t)) { if (!atomic_read(&t->count)) { if (tasklet_clear_sched(t)) { - if (t->use_callback) + if (t->use_callback) { + trace_tasklet_entry(t, t->callback); t->callback(t); - else + trace_tasklet_exit(t, t->callback); + } else { + trace_tasklet_entry(t, t->func); t->func(t->data); + trace_tasklet_exit(t, t->func); + } } tasklet_unlock(t); continue; --=20 2.39.0.246.g2a6d74b583-goog