Received: by 2002:a05:7412:d1aa:b0:fc:a2b0:25d7 with SMTP id ba42csp1373339rdb; Tue, 30 Jan 2024 17:19:50 -0800 (PST) X-Google-Smtp-Source: AGHT+IFkaeuU35MoMi9AQWuM/H3VRVWYwQKgFxyMwg7F5+cOrm5j4nq/eTBd4sQvpnGdfGIHpy4c X-Received: by 2002:a05:6214:2b05:b0:686:acae:e0b5 with SMTP id jx5-20020a0562142b0500b00686acaee0b5mr316984qvb.57.1706663990118; Tue, 30 Jan 2024 17:19:50 -0800 (PST) ARC-Seal: i=2; a=rsa-sha256; t=1706663990; cv=pass; d=google.com; s=arc-20160816; b=Kvkss4SaVxtku9QdEB77/3T435iQglDHMLNRO1cu6hJnc6pRTDFwg9AFKOzQ7AVE/n PWOxsLNInfRFODhEiN6VJidzisMRkt4dOy/G9/oZw/AIrlSxcqNXG4YWItzcrX2qIQWr rhDk0QosphSFEabX9sIwHk0hmY4QTYvwe0sKUf4W0LgrKEeOn54ywr4MKvqfJ02l0x0G aEn1ToSQ1H5xvVtpAvuF9f+8dxAdHKbDydWt/gh9Qc7i01jHwa2fubrjylH347qD54M6 0TUwDzXpyOB7rIuLTj42tHhvlEetFWFeDdBB+yUbOLrwJXSB2Ti3fazpJijCeJFzui+Y UeWA== ARC-Message-Signature: i=2; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=content-transfer-encoding:in-reply-to:from:references:cc:to:subject :user-agent:mime-version:list-unsubscribe:list-subscribe:list-id :precedence:date:message-id:dkim-signature; bh=QNcnZ4YTCX16sFr0xVxV0BBzhklTzrouZKUQMVBhs6A=; fh=rKuPJzxHrBrgnq9uEIO7gkDFd86A7azC3mBL4+jx3KY=; b=VSqz1O7ouw5L0pX1NZxltPs18ULKafRnMmeF2j9Y/KxZmTRSEgFzaKE+qI6F7fS/8p +BuhkQXp81Oxybg4RR2Tt3Wbx8LnIEOkkqNzKP9NA/IzJQ7cqnoDF0bLLCu/q46E11rG 3uYIVd0IBzxUke6wYaq6kEfEEIoW4QVZR8BtYW+dF0s8rJ0gVjZw6SnmPbJcqrq3KE8+ s+uAf3Rj6vjFKL6OfWVeRSiVU9/5r3mc7+4RSBtO0p6NfqBDWXDTzoaNLCVd3PjIXpmB C2hpXRPkro2+wQMo1ELSA00b/5wjMOn49LJfHIH6JjTP6X2+9urvvg0G/fgUSvwRpwO9 lQ4Q==; dara=google.com ARC-Authentication-Results: i=2; mx.google.com; dkim=pass header.i=@linux.alibaba.com header.s=default header.b=vpfqMJWs; arc=pass (i=1 spf=pass spfdomain=linux.alibaba.com dkim=pass dkdomain=linux.alibaba.com dmarc=pass fromdomain=linux.alibaba.com); spf=pass (google.com: domain of linux-kernel+bounces-45580-linux.lists.archive=gmail.com@vger.kernel.org designates 147.75.199.223 as permitted sender) smtp.mailfrom="linux-kernel+bounces-45580-linux.lists.archive=gmail.com@vger.kernel.org"; dmarc=pass (p=NONE sp=NONE dis=NONE) header.from=linux.alibaba.com X-Forwarded-Encrypted: i=1; AJvYcCXxF85xnVecrFYhpA9m+9Pp98WzdLoj7z2525V11Zgtfz5Dk3cJLVWAgmQpLQD5LJ94Vc0RhQNiw3hU/WtD4Vdvg9i75J28NxIlnXkGZA== Return-Path: Received: from ny.mirrors.kernel.org (ny.mirrors.kernel.org. [147.75.199.223]) by mx.google.com with ESMTPS id x14-20020a05620a098e00b0078400fab7aesi4948467qkx.108.2024.01.30.17.19.49 for (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Tue, 30 Jan 2024 17:19:50 -0800 (PST) Received-SPF: pass (google.com: domain of linux-kernel+bounces-45580-linux.lists.archive=gmail.com@vger.kernel.org designates 147.75.199.223 as permitted sender) client-ip=147.75.199.223; Authentication-Results: mx.google.com; dkim=pass header.i=@linux.alibaba.com header.s=default header.b=vpfqMJWs; arc=pass (i=1 spf=pass spfdomain=linux.alibaba.com dkim=pass dkdomain=linux.alibaba.com dmarc=pass fromdomain=linux.alibaba.com); spf=pass (google.com: domain of linux-kernel+bounces-45580-linux.lists.archive=gmail.com@vger.kernel.org designates 147.75.199.223 as permitted sender) smtp.mailfrom="linux-kernel+bounces-45580-linux.lists.archive=gmail.com@vger.kernel.org"; dmarc=pass (p=NONE sp=NONE dis=NONE) header.from=linux.alibaba.com Received: from smtp.subspace.kernel.org (wormhole.subspace.kernel.org [52.25.139.140]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by ny.mirrors.kernel.org (Postfix) with ESMTPS id CBF991C24A28 for ; Wed, 31 Jan 2024 01:19:49 +0000 (UTC) Received: from localhost.localdomain (localhost.localdomain [127.0.0.1]) by smtp.subspace.kernel.org (Postfix) with ESMTP id 78E66111E; Wed, 31 Jan 2024 01:19:44 +0000 (UTC) Authentication-Results: smtp.subspace.kernel.org; dkim=pass (1024-bit key) header.d=linux.alibaba.com header.i=@linux.alibaba.com header.b="vpfqMJWs" Received: from out30-111.freemail.mail.aliyun.com (out30-111.freemail.mail.aliyun.com [115.124.30.111]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by smtp.subspace.kernel.org (Postfix) with ESMTPS id A6ABB7FA for ; Wed, 31 Jan 2024 01:19:39 +0000 (UTC) Authentication-Results: smtp.subspace.kernel.org; arc=none smtp.client-ip=115.124.30.111 ARC-Seal:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1706663983; cv=none; b=Oo7F86Bs4jBHj1DpS6I+ORPIqB7bwzrCS5JjxDGwi9eY4NH3z2glNPAOaDEYNHGS2uLrIlRSBVWfwejR3FdzsCaFvNjgYo31f4i0BMGkmz/kIZ9Q68Ukdgak8W9PLMvIlSzVBGp1kfKwFrP8aIwT7KIS0bcyDMQdhF76H7eWMhc= ARC-Message-Signature:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1706663983; c=relaxed/simple; bh=wXpIbBYsw5piRhsl6RgdldRPIgSDaSHdiHt8JrNeyDQ=; h=Message-ID:Date:MIME-Version:Subject:To:Cc:References:From: In-Reply-To:Content-Type; b=gpm4gtnPtkUKXGS9gksPfJkghFcJuIsY2gMl7/KL7ckEUU/S1AlfuIWLsNCV8rWoCGAEL58993NICbTEj9sgfp8WjK81zN3t+k+1GhET4Cj7h4lSVRB7I76h5ceYi6pCfSFzSXQD5VIgd6tO5OwUPUZFVTkaKzUla8twanN5gJc= ARC-Authentication-Results:i=1; smtp.subspace.kernel.org; dmarc=pass (p=none dis=none) header.from=linux.alibaba.com; spf=pass smtp.mailfrom=linux.alibaba.com; dkim=pass (1024-bit key) header.d=linux.alibaba.com header.i=@linux.alibaba.com header.b=vpfqMJWs; arc=none smtp.client-ip=115.124.30.111 Authentication-Results: smtp.subspace.kernel.org; dmarc=pass (p=none dis=none) header.from=linux.alibaba.com Authentication-Results: smtp.subspace.kernel.org; spf=pass smtp.mailfrom=linux.alibaba.com DKIM-Signature:v=1; a=rsa-sha256; c=relaxed/relaxed; d=linux.alibaba.com; s=default; t=1706663977; h=Message-ID:Date:MIME-Version:Subject:To:From:Content-Type; bh=QNcnZ4YTCX16sFr0xVxV0BBzhklTzrouZKUQMVBhs6A=; b=vpfqMJWsCq61e9ix34Qd8yuhvnJULeWM4vqeXinIxT7tPBIv92uHrDUiUu9BXidLE0X4aDjmdNQgc+4EZ00nm9XitLbCMIASFM5kZZI6QTKx3CfPMr+FmhP1Ey/sj7sDkfJDAurRF9K73lLweLEhpvQxYSbfptP893HbA3leqeM= X-Alimail-AntiSpam:AC=PASS;BC=-1|-1;BR=01201311R151e4;CH=green;DM=||false|;DS=||;FP=0|-1|-1|-1|0|-1|-1|-1;HT=ay29a033018046050;MF=liusong@linux.alibaba.com;NM=1;PH=DS;RN=7;SR=0;TI=SMTPD_---0W.hOH5._1706663975; Received: from 30.178.80.124(mailfrom:liusong@linux.alibaba.com fp:SMTPD_---0W.hOH5._1706663975) by smtp.aliyun-inc.com; Wed, 31 Jan 2024 09:19:36 +0800 Message-ID: Date: Wed, 31 Jan 2024 09:19:35 +0800 Precedence: bulk X-Mailing-List: linux-kernel@vger.kernel.org List-Id: List-Subscribe: List-Unsubscribe: MIME-Version: 1.0 User-Agent: Mozilla Thunderbird Subject: Re: [PATCHv2 1/2] watchdog/softlockup: low-overhead detection of interrupt storm To: Bitao Hu , dianders@chromium.org, akpm@linux-foundation.org, pmladek@suse.com, lecopzer.chen@mediatek.com, kernelfans@gmail.com Cc: linux-kernel@vger.kernel.org References: <20240130074744.45759-1-yaoma@linux.alibaba.com> <20240130074744.45759-2-yaoma@linux.alibaba.com> From: Liu Song In-Reply-To: <20240130074744.45759-2-yaoma@linux.alibaba.com> Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 8bit 在 2024/1/30 15:47, Bitao Hu 写道: > The following softlockup is caused by interrupt storm, but it cannot be > identified from the call tree. Because the call tree is just a snapshot > and doesn't fully capture the behavior of the CPU during the soft lockup. > watchdog: BUG: soft lockup - CPU#28 stuck for 23s! [fio:83921] > ... > Call trace: > __do_softirq+0xa0/0x37c > __irq_exit_rcu+0x108/0x140 > irq_exit+0x14/0x20 > __handle_domain_irq+0x84/0xe0 > gic_handle_irq+0x80/0x108 > el0_irq_naked+0x50/0x58 > > Therefore,I think it is necessary to report CPU utilization during the > softlockup_thresh period (report once every sample_period, for a total > of 5 reportings), like this: > watchdog: BUG: soft lockup - CPU#28 stuck for 23s! [fio:83921] > CPU#28 Utilization every 4s during lockup: > #1: 0% system, 0% softirq, 100% hardirq, 0% idle > #2: 0% system, 0% softirq, 100% hardirq, 0% idle > #3: 0% system, 0% softirq, 100% hardirq, 0% idle > #4: 0% system, 0% softirq, 100% hardirq, 0% idle > #5: 0% system, 0% softirq, 100% hardirq, 0% idle > ... > > This would be helpful in determining whether an interrupt storm has > occurred or in identifying the cause of the softlockup. The criteria for > determination are as follows: > a. If the hardirq utilization is high, then interrupt storm should be > considered and the root cause cannot be determined from the call tree. > b. If the softirq utilization is high, then we could analyze the call > tree but it may cannot reflect the root cause. > c. If the system utilization is high, then we could analyze the root > cause from the call tree. > > Signed-off-by: Bitao Hu > --- > kernel/watchdog.c | 72 +++++++++++++++++++++++++++++++++++++++++++++++ > 1 file changed, 72 insertions(+) > > diff --git a/kernel/watchdog.c b/kernel/watchdog.c > index 81a8862295d6..0efe9604c3c2 100644 > --- a/kernel/watchdog.c > +++ b/kernel/watchdog.c > @@ -23,6 +23,8 @@ > #include > #include > #include > +#include > +#include > > #include > #include > @@ -441,6 +443,73 @@ static int is_softlockup(unsigned long touch_ts, > return 0; > } > > +#ifdef CONFIG_IRQ_TIME_ACCOUNTING > +#define NUM_STATS_GROUPS 5 > +#define STATS_SYSTEM 0 > +#define STATS_SOFTIRQ 1 > +#define STATS_HARDIRQ 2 > +#define STATS_IDLE 3 > +#define NUM_STATS_PER_GROUP 4 This is a set of related numbers; wouldn't it be better to use an enum? > +static DEFINE_PER_CPU(u16, cpustat_old[NUM_STATS_PER_GROUP]); > +static DEFINE_PER_CPU(u8, cpustat_utilization[NUM_STATS_GROUPS][NUM_STATS_PER_GROUP]); > +static DEFINE_PER_CPU(u8, cpustat_tail); > +static enum cpu_usage_stat idx_to_stat[NUM_STATS_PER_GROUP] = { > + CPUTIME_SYSTEM, CPUTIME_SOFTIRQ, CPUTIME_IRQ, CPUTIME_IDLE > +}; To be honest, I'm not particularly fond of the name 'idx_to_stat' as the concept of an index is already implied by the nature of an array, so adding 'idx' is redundant. I suggest shortening the name. > + > +static void update_cpustat(void) > +{ > + u8 i; > + u16 *old = this_cpu_ptr(cpustat_old); > + u8 (*utilization)[NUM_STATS_PER_GROUP] = this_cpu_ptr(cpustat_utilization); > + u8 tail = this_cpu_read(cpustat_tail); > + struct kernel_cpustat kcpustat; > + u64 *cpustat = kcpustat.cpustat; > + u16 sample_period_ms = sample_period >> 24LL; /* 2^24ns ~= 16.8ms */ There are two instances where right shift operations are used; it is suggested to employ a helper macro for a more comfortable look. > + > + kcpustat_cpu_fetch(&kcpustat, smp_processor_id()); > + for (i = STATS_SYSTEM; i < NUM_STATS_PER_GROUP; i++) { > + /* > + * We don't need nanosecond resolution. A granularity of 16ms is > + * sufficient for our precision, allowing us to use u16 to store > + * cpustats, which will roll over roughly every ~1000 seconds. > + * 2^24 ~= 16 * 10^6 > + */ > + cpustat[idx_to_stat[i]] = lower_16_bits(cpustat[idx_to_stat[i]] >> 24LL); > + utilization[tail][i] = 100 * (u16)(cpustat[idx_to_stat[i]] - old[i]) > + / sample_period_ms; > + old[i] = cpustat[idx_to_stat[i]]; > + } > + this_cpu_write(cpustat_tail, (tail + 1) % NUM_STATS_GROUPS); > +} > + > +static void print_cpustat(void) > +{ > + u8 i, j; > + u8 (*utilization)[NUM_STATS_PER_GROUP] = this_cpu_ptr(cpustat_utilization); > + u8 tail = this_cpu_read(cpustat_tail); > + u64 sample_period_second = sample_period; > + > + do_div(sample_period_second, NSEC_PER_SEC); > + /* > + * We do not want the "watchdog: " prefix on every line, > + * hence we use "printk" instead of "pr_crit". > + */ > + printk(KERN_CRIT "CPU#%d Utilization every %llus during lockup:\n", > + smp_processor_id(), sample_period_second); > + for (j = STATS_SYSTEM, i = tail; j < NUM_STATS_GROUPS; > + j++, i = (i + 1) % NUM_STATS_GROUPS) { > + printk(KERN_CRIT "\t#%d: %3u%% system,\t%3u%% softirq,\t" > + "%3u%% hardirq,\t%3u%% idle\n", j+1, > + utilization[i][STATS_SYSTEM], utilization[i][STATS_SOFTIRQ], > + utilization[i][STATS_HARDIRQ], utilization[i][STATS_IDLE]); > + } > +} > +#else > +static inline void update_cpustat(void) { } > +static inline void print_cpustat(void) { } > +#endif > + > /* watchdog detector functions */ > static DEFINE_PER_CPU(struct completion, softlockup_completion); > static DEFINE_PER_CPU(struct cpu_stop_work, softlockup_stop_work); > @@ -504,6 +573,8 @@ static enum hrtimer_restart watchdog_timer_fn(struct hrtimer *hrtimer) > */ > period_ts = READ_ONCE(*this_cpu_ptr(&watchdog_report_ts)); > > + update_cpustat(); > + > /* Reset the interval when touched by known problematic code. */ > if (period_ts == SOFTLOCKUP_DELAY_REPORT) { > if (unlikely(__this_cpu_read(softlockup_touch_sync))) { > @@ -539,6 +610,7 @@ static enum hrtimer_restart watchdog_timer_fn(struct hrtimer *hrtimer) > pr_emerg("BUG: soft lockup - CPU#%d stuck for %us! [%s:%d]\n", > smp_processor_id(), duration, > current->comm, task_pid_nr(current)); > + print_cpustat(); > print_modules(); > print_irqtrace_events(current); > if (regs)