From mboxrd@z Thu Jan 1 00:00:00 1970 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 1B1C5C433FE for ; Wed, 9 Nov 2022 08:46:09 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S229927AbiKIIqH (ORCPT ); Wed, 9 Nov 2022 03:46:07 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:56186 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S229591AbiKIIqF (ORCPT ); Wed, 9 Nov 2022 03:46:05 -0500 Received: from szxga08-in.huawei.com (szxga08-in.huawei.com [45.249.212.255]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 94F3D10E; Wed, 9 Nov 2022 00:46:04 -0800 (PST) Received: from dggpemm500023.china.huawei.com (unknown [172.30.72.55]) by szxga08-in.huawei.com (SkyGuard) with ESMTP id 4N6dpk4Bqvz15MRQ; Wed, 9 Nov 2022 16:45:50 +0800 (CST) Received: from dggpemm500006.china.huawei.com (7.185.36.236) by dggpemm500023.china.huawei.com (7.185.36.83) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.31; Wed, 9 Nov 2022 16:46:02 +0800 Received: from [10.174.178.55] (10.174.178.55) by dggpemm500006.china.huawei.com (7.185.36.236) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256) id 15.1.2375.31; Wed, 9 Nov 2022 16:46:02 +0800 Subject: Re: [PATCH] rcu: Illustrate the stall information of CONFIG_RCU_CPU_STALL_CPUTIME=y From: "Leizhen (ThunderTown)" To: CC: Frederic Weisbecker , Neeraj Upadhyay , Josh Triplett , "Steven Rostedt" , Mathieu Desnoyers , Lai Jiangshan , Joel Fernandes , , , Robert Elliott References: <20221107152935.167-1-thunder.leizhen@huawei.com> <20221108204640.GJ3907045@paulmck-ThinkPad-P17-Gen-1> <61c45ec1-69ec-0e65-6a48-1329e66ec30f@huawei.com> Message-ID: <31c1dfb1-623f-4a9e-7f2c-48b83dd4490d@huawei.com> Date: Wed, 9 Nov 2022 16:46:01 +0800 User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64; rv:60.0) Gecko/20100101 Thunderbird/60.7.0 MIME-Version: 1.0 In-Reply-To: <61c45ec1-69ec-0e65-6a48-1329e66ec30f@huawei.com> Content-Type: text/plain; charset="utf-8" Content-Language: en-US Content-Transfer-Encoding: 7bit X-Originating-IP: [10.174.178.55] X-ClientProxiedBy: dggems701-chm.china.huawei.com (10.3.19.178) To dggpemm500006.china.huawei.com (7.185.36.236) X-CFilter-Loop: Reflected Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On 2022/11/9 10:09, Leizhen (ThunderTown) wrote: > > > On 2022/11/9 4:46, Paul E. McKenney wrote: >> On Mon, Nov 07, 2022 at 11:29:35PM +0800, Zhen Lei wrote: >>> Describes how to quickly determine the RCU stall fault type based on the >>> extra output information during CONFIG_RCU_CPU_STALL_CPUTIME=y. >>> >>> Signed-off-by: Zhen Lei >> >> Hearing no objections, I queued the following for further review. >> >> This commit might of course need to change based on your ongoing >> discussion with Robert. I that case, please feel free to send me a >> replacment patch or to send me an incremental patch that I can fold into >> this patch. Either way works. > > I'll issue incremental patches on the basis of your adjustment! This will > make it clearer and save your time in reviewing. I found that Patch 4/4 had one line of description that needed to be changed, so I had to switch to method 1. > > Thanks for your help. I really admire your verbal skills. Your improved > description is much better than mine. > >> >> Thanx, Paul >> >> ------------------------------------------------------------------------ >> >> commit b05c2a06ff8a1267b7e8dc812e3944119535d6b6 >> Author: Zhen Lei >> Date: Mon Nov 7 23:29:35 2022 +0800 >> >> doc: Document CONFIG_RCU_CPU_STALL_CPUTIME=y stall information >> >> This commit doucments how to quickly determine the bug causing a given >> RCU CPU stall fault warning based on the output information provided >> by CONFIG_RCU_CPU_STALL_CPUTIME=y. >> >> [ paulmck: Apply wordsmithing. ] >> >> Signed-off-by: Zhen Lei >> Signed-off-by: Paul E. McKenney >> >> diff --git a/Documentation/RCU/stallwarn.rst b/Documentation/RCU/stallwarn.rst >> index dfa4db8c0931e..bd8cf6c640984 100644 >> --- a/Documentation/RCU/stallwarn.rst >> +++ b/Documentation/RCU/stallwarn.rst >> @@ -390,3 +390,82 @@ for example, "P3421". >> >> It is entirely possible to see stall warnings from normal and from >> expedited grace periods at about the same time during the same run. >> + >> +RCU_CPU_STALL_CPUTIME >> +===================== >> + >> +In kernels built with CONFIG_RCU_CPU_STALL_CPUTIME=y or booted with >> +rcupdate.rcu_cpu_stall_cputime=1, the following additional information >> +is supplied with each RCU CPU stall warning:: >> + >> +rcu: hardirqs softirqs csw/system >> +rcu: number: 624 45 0 >> +rcu: cputime: 69 1 2425 ==> 2500(ms) >> + >> +These statistics are collected during the second half of the rcu stall >> +timeout. The values in row "number:" are the number of hard interrupts, >> +number of soft interrupts, and number of context switches on the stalled >> +CPU. The first three values in row "cputime:" indicate the CPU time in >> +milliseconds consumed by hard interrupts, soft interrupts, and tasks >> +on the stalled CPU. The last number is the measurement interval, again >> +in milliseconds. Because user-mode tasks normally do not cause RCU CPU >> +stalls, these tasks are typically kernel tasks, which is why only the >> +system CPU time are considered. >> + >> +The following describes four typical scenarios: >> + >> +1. A CPU looping with interrupts disabled.:: >> + >> + rcu: hardirqs softirqs csw/system >> + rcu: number: 0 0 0 >> + rcu: cputime: 0 0 0 ==> 2500(ms) >> + >> + Because interrupts have been disabled throughout the measurement >> + interval, there are no interrupts and no context switches. >> + Furthermore, because CPU time consumption was measured using interrupt >> + handlers, the system CPU consumption is misleadingly measured as zero. >> + This scenario will normally also have "(0 ticks this GP)" printed on >> + this CPU's summary line. >> + >> +2. A CPU looping with bottom halves disabled. >> + >> + This is similar to the previous example, but with non-zero number of >> + and CPU time consumed by hard interrupts, along with non-zero CPU >> + time consumed by in-kernel execution.:: >> + >> + rcu: hardirqs softirqs csw/system >> + rcu: number: 624 0 0 >> + rcu: cputime: 49 0 2446 ==> 2500(ms) >> + >> + The fact that there are zero softirqs gives a hint that these were >> + disabled, perhaps via local_bh_disable(). It is of course possible >> + that there were no softirqs, perhaps because all events that would >> + result in softirq execution are confined to other CPUs. In this case, >> + the diagnosis should continue as shown in the next example. >> + >> +3. A CPU looping with preemption disabled. >> + >> + Here, only the number of context switches is zero.:: >> + >> + rcu: hardirqs softirqs csw/system >> + rcu: number: 624 45 0 >> + rcu: cputime: 69 1 2425 ==> 2500(ms) >> + >> + This situation hints that the stalled CPU was looping with preemption >> + disabled. >> + >> +4. No looping, but massive hard and soft interrupts.:: >> + >> + rcu: hardirqs softirqs csw/system >> + rcu: number: xx xx 0 >> + rcu: cputime: xx xx 0 ==> 2500(ms) >> + >> + Here, the number and CPU time of hard interrupts are all non-zero, >> + but the number of context switches and the in-kernel CPU time consumed >> + are zero. The number and cputime of soft interrupts will usually be >> + non-zero, but could be zero, for example, if the CPU was spinning >> + within a single hard interrupt handler. >> + >> + If this type of RCU CPU stall warning can be reproduced, you can >> + narrow it down by looking at /proc/interrupts or by writing code to >> + trace each interrupt, for example, by referring to show_interrupts(). >> . >> > -- Regards, Zhen Lei