Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
IronPort-SDR: 9ehbhOLqayTXn8g/JUKtpLP4WiLZCvFCbVigUL3NeqYVL4ZdkYtTSnCVCdgJ6hH/N0p7YMxu5r
 9Cv8qHwG5NWoaztu4X2u9HVQ5NzuLjUdRLfj8NEBuvEt3rtG7jlYRKqBX/MYi//dCBlI9DJx/n
 H7q53cgAsxBrUmh/Ts/xIUTOHm83tzCbFjQ24NnFZK+qATRiLMD1TZDQA+lMiLnP94m5A8tLSF
 IXmdgKh/ScBLeLUIvQ7Il39QpgRmu9ryq4MVMKsypAwjFyLY1f9KEm5hwE+rUdDLKaG9sx+I8b
 77Y=
From:   Shinichiro Kawasaki <shinichiro.kawasaki@wdc.com>
To:     Hillf Danton <hdanton@sina.com>
CC:     Damien Le Moal <Damien.LeMoal@wdc.com>,
        Block <linux-block@vger.kernel.org>,
        Jens Axboe <axboe@kernel.dk>,
        Peter Zijlstra <peterz@infradead.org>,
        Tejun Heo <tj@kernel.org>, LKML <linux-kernel@vger.kernel.org>
Subject: Re: WARNING at blktests block/008 in ttwu_queue_wakelist()
Thread-Topic: WARNING at blktests block/008 in ttwu_queue_wakelist()
Thread-Index: AQHXXPwtp5wIJLz/bUO+HXbRCV2UY6sM7DEAgBwKMgCAETyZAA==
Date:   Fri, 9 Jul 2021 03:57:04 +0000
Message-ID: <20210709035704.mvhtxxr6ewootlpz@shindev>
References: <20210609065339.aecrkqc6dj3xgbiw@shindev.dhcp.fujisawa.hgst.com>
 <20210610083200.3832-1-hdanton@sina.com>
 <20210628044346.jo3xzlxhnxuxt7nz@shindev>
In-Reply-To: <20210628044346.jo3xzlxhnxuxt7nz@shindev>
Accept-Language: en-US
Content-Language: en-US
wdcipoutbound: EOP-TRUE
x-ms-exchange-antispam-messagedata-chunkcount: 1
x-ms-exchange-antispam-messagedata-0: =?us-ascii?Q?V9XsRffc/rYYNNJh9W4WNh6TQuuFn9pnAOoApCtxanDlg1IpFZpuLFFUD4hY?=
 =?us-ascii?Q?lfQ+bY+UKS+uuYvr8PoODJ3krqTG6KJ42rDrxW/Fd8/L8AMnOmZcM0oJ9cCw?=
 =?us-ascii?Q?OjNu0hhfHTxMxyPzgmBlE2AjiJuT5OJJZPsARokFo+6/9vW//V7XaefnLlqQ?=
 =?us-ascii?Q?rwEQAztSgOXTjXMKabyPeNmVlW7MI1GhRFt2ogKkCfE7I/nGPLQ8kKTxMlhk?=
 =?us-ascii?Q?g23S9GOVZ2xIpqTPpW9s70LlERdDo3qzNudkK0jdqdRNouDCDK1Hk4ayKaPh?=
 =?us-ascii?Q?D7RYdTh3fZuKDjpD3AlRIuHvzDzLVuRcgpCZP6Y9XF6tSMqBstMJb/6MYA0M?=
 =?us-ascii?Q?rcunJ2cuAE7knwXhjsDUStH0UEB94jTnNI1Xy0VdiJfWFTql7vOl7mMZGFdw?=
 =?us-ascii?Q?clHt57cLVSZEzu5ZoXJ+YrxZZYNjk4eQ9gCFqcxSymMqxypTev81if9w7Iou?=
 =?us-ascii?Q?yNLdeI76hvUCAf2eEjoYLy1JWdDv9IDP0oDP3u9ThlOQX8OzqY9gwsSB7AHZ?=
 =?us-ascii?Q?/O+9Ni7YIXpV6TbkmZCx9pADtM6EyQYXiGaO9kXQS6NnhVe2tQpe6IpvHTYr?=
 =?us-ascii?Q?vFpgJT36YOyHI74QdVH2BGbj7auX6yPnXnZVC5cu6JKUPwdTb14tpc1GXnFT?=
 =?us-ascii?Q?a4yNVBmi9Imgy4Hd6egrqOEHtwryB2aveVYU6Qtmg/VLyV1UhkkYSK2kPtRn?=
 =?us-ascii?Q?xYcAQN+2n+SRWFXHMhsAq8mlrhRBXWeKc1A6rj13bzkRwo4UYYJ9Cp1N8ltS?=
 =?us-ascii?Q?5rup05xuJerose/3cqTqodLHwziSqjf6PY5N72GnDsgCPineBYRj4IO9QSEY?=
 =?us-ascii?Q?86m8GTU61T5BsRdX0+MvjMup9YszYcTWeYQwSOktf0jo38OI+S4YgV/Jro7D?=
 =?us-ascii?Q?osPE2VCTc354KNK7wF+NzT5SszT2Qj/Hf1gMDpRhYHvBtTiOnuA8H+93lnbS?=
 =?us-ascii?Q?Gi1nliGrmmdU9Hv0F8GRzmrlOaja6uk+4hLA6D4ECULDww/oi13fJ0whuRXF?=
 =?us-ascii?Q?cZ4MIUd+8XJKoCKZqfb6cBqzwbKNnXWVu/l1nDllOP/rcfCkoD9aThNWVeGy?=
 =?us-ascii?Q?Le5srIwgYOujEDfcDll8rpcRMz/L1E9igMU/izGcuhHd48Jdnz1eTrQRgcJc?=
 =?us-ascii?Q?rt5x7xWKbsGn1PL+dKx/WMvEeGfmI82tOrk/PGTRy6kBmEB6qb4nWiZwwSzG?=
 =?us-ascii?Q?FrSDhoMqAgsUzPSVjze0Up/vwNRgFrzhI1U2gxdUhRE9zM206xCDU7AKNBEx?=
 =?us-ascii?Q?t/KfYn1/mPalVoZoQ464jOogEfaFUbV+xMHajiDqocvOgCXY2f/XwptA8YNV?=
 =?us-ascii?Q?LeGZbBpGANFuwGAVpQIw2hAKSGKt18f/NQN5+7v6Zh7jKw=3D=3D?=
Content-Type: text/plain; charset="us-ascii"
Content-ID: <5CB45D3A1BC71B4CA3CC5C8F6BEB86C9@namprd04.prod.outlook.com>
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0
X-OriginatorOrg: wdc.com
X-MS-Exchange-CrossTenant-AuthAs: Internal
X-MS-Exchange-CrossTenant-AuthSource: SJ0PR04MB7184.namprd04.prod.outlook.com
X-MS-Exchange-CrossTenant-Network-Message-Id: 6acb048f-81f7-47fc-8d0c-08d9428d9d7d
X-MS-Exchange-CrossTenant-originalarrivaltime: 09 Jul 2021 03:57:04.8353
 (UTC)
X-MS-Exchange-CrossTenant-fromentityheader: Hosted
X-MS-Exchange-CrossTenant-id: b61c8803-16f3-4c35-9b17-6f65f441df86
X-MS-Exchange-CrossTenant-mailboxtype: HOSTED
X-MS-Exchange-CrossTenant-userprincipalname: KN+m3GZwtthuAxzgaMXGxCqMTu2B9pDnmQznmQKxGy3ejLOvfzF3EM/mLf4X2YVCtrk/VpshNm+P2vwwH8UETK3afZtj99ZMKwE/y3CFWDw=
X-MS-Exchange-Transport-CrossTenantHeadersStamped: BY5PR04MB6582
Precedence: bulk
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org

On Jun 28, 2021 / 13:43, Shin'ichiro Kawasaki wrote:
> On Jun 10, 2021 / 16:32, Hillf Danton wrote:
> > On Wed, 9 Jun 2021 06:55:59 +0000 Damien Le Moal wrote:
> > >+ Jens and linux-kernel
> > >
> > >On 2021/06/09 15:53, Shinichiro Kawasaki wrote:
> > >> Hi there,
> > >>=20
> > >> Let me share a blktests failure. When I ran blktests on the kernel v=
5.13-rc5,
> > >> block/008 failed. A WARNING below was the cause of the failure.
> > >>=20
> > >>     WARNING: CPU: 1 PID: 135817 at kernel/sched/core.c:3175 ttwu_que=
ue_wakelist+0x284/0x2f0
> > >>=20
> > >> I'm trying to recreate the failure repeating the test case, but so f=
ar, I am
> > >> not able to. This failure looks rare, but actually, I observed it 3 =
times in
> > >> the past one year.
> > >>=20
> > >> 1) Oct/2020, kernel: v5.9-rc7  test dev: dm-flakey on AHCI-SATA SMR =
HDD, log [1]
> > >> 2) Mar/2021, kernel: v5.12-rc2 test dev: AHCI-SATA SMR HDD, log [2]
> > >> 3) Jun/2021, kernel: v5.13-rc5 test dev: dm-linear on null_blk zoned=
, log [3]
> > >>=20
> > >> The test case block/008 does IO during CPU hotplug, and the WARNING =
in
> > >> ttwu_queue_wakelist() checks "WARN_ON_ONCE(cpu =3D=3D smp_processor_=
id())".
> > >> So it is likely that the test case triggers the warning, but I don't=
 have
> > >> clear view why and how the warning was triggered. It was observed on=
 various
> > >> block devices, so I would like to ask linux-block experts if anyone =
can tell
> > >> what is going on. Comments will be appreciated.
> >=20
> > [...]
> >=20
> > >> [40041.712804][T135817] ------------[ cut here ]------------
> > >> [40041.718489][T135817] WARNING: CPU: 1 PID: 135817 at kernel/sched/=
core.=3D
> > >c:3175 ttwu_queue_wakelist+0x284/0x2f0
> > >> [40041.728311][T135817] Modules linked in: null_blk dm_flakey iscsi_=
targe=3D
> > >t_mod tcm_loop target_core_pscsi target_core_file target_core_iblock n=
ft_fi=3D
> > >b_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv=
4 nf_=3D
> > >reject_ipv6 nft_reject nft_ct nft_chain_nat ip6table_nat ip6table_mang=
le ip=3D
> > >6table_raw ip6table_security iptable_nat nf_nat nf_conntrack nf_defrag=
_ipv6=3D
> > > nf_defrag_ipv4 iptable_mangle iptable_raw bridge iptable_security stp=
 llc =3D
> > >ip_set rfkill nf_tables target_core_user target_core_mod nfnetlink ip6=
table=3D
> > >_filter ip6_tables iptable_filter sunrpc intel_rapl_msr intel_rapl_com=
mon x=3D
> > >86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass =
iTCO_=3D
> > >wdt intel_pmc_bxt iTCO_vendor_support rapl intel_cstate intel_uncore j=
oydev=3D
> > > lpc_ich i2c_i801 i2c_smbus ses enclosure mei_me mei ipmi_ssif ioatdma=
 wmi =3D
> > >acpi_ipmi ipmi_si ipmi_devintf ipmi_msghandler acpi_power_meter acpi_p=
ad zr=3D
> > >am ip_tables ast drm_vram_helper drm_kms_helper syscopyarea sysfillrec=
t crc=3D
> > >32c_intel sysimgblt
> > >> [40041.728481][T135817]  fb_sys_fops cec drm_ttm_helper ttm ghash_cl=
mulni=3D
> > >_intel drm igb mpt3sas nvme dca i2c_algo_bit nvme_core raid_class scsi=
_tran=3D
> > >sport_sas pkcs8_key_parser [last unloaded: null_blk]
> > >> [40041.832215][T135817] CPU: 1 PID: 135817 Comm: fio Not tainted 5.1=
3.0-r=3D
> > >c5+ #1
> > >> [40041.839262][T135817] Hardware name: Supermicro Super Server/X10SR=
L-F, =3D
> > >BIOS 3.2 11/22/2019
> > >> [40041.847434][T135817] RIP: 0010:ttwu_queue_wakelist+0x284/0x2f0
> > >> [40041.853266][T135817] Code: 34 24 e8 6f 71 64 00 4c 8b 44 24 10 48=
 8b 4=3D
> > >c 24 08 8b 34 24 e9 a1 fe ff ff e8 a8 71 64 00 e9 66 ff ff ff e8 be 71=
 64 0=3D
> > >0 eb a0 <0f> 0b 45 31 ff e9 cb fe ff ff 48 89 04 24 e8 49 71 64 00 48 =
8b 04=3D
> > >
> > >> [40041.872793][T135817] RSP: 0018:ffff888106bff348 EFLAGS: 00010046
> > >> [40041.878800][T135817] RAX: 0000000000000001 RBX: ffff888117ec3240 =
RCX: =3D
> > >ffff888811440000
> > >> [40041.886711][T135817] RDX: 0000000000000000 RSI: 0000000000000001 =
RDI: =3D
> > >ffffffffb603d6e8
> > >> [40041.894625][T135817] RBP: 0000000000000001 R08: ffffffffb603d6e8 =
R09: =3D
> > >ffffffffb6ba6167
> > >> [40041.902537][T135817] R10: fffffbfff6d74c2c R11: 0000000000000001 =
R12: =3D
> > >0000000000000000
> > >> [40041.910451][T135817] R13: ffff88881145fd00 R14: 0000000000000001 =
R15: =3D
> > >ffff888811440001
> > >> [40041.918364][T135817] FS:  00007f8eabf14b80(0000) GS:ffff888811440=
000(0=3D
> > >000) knlGS:0000000000000000
> > >> [40041.927229][T135817] CS:  0010 DS: 0000 ES: 0000 CR0: 00000000800=
50033=3D
> > >
> > >> [40041.933756][T135817] CR2: 000055ce81e2cc78 CR3: 000000011be92005 =
CR4: =3D
> > >00000000001706e0
> > >> [40041.941669][T135817] Call Trace:
> > >> [40041.944895][T135817]  ? lock_is_held_type+0x98/0x110
> > >> [40041.949860][T135817]  try_to_wake_up+0x6f9/0x15e0
> >=20
> > 2) __queue_work
> >      raw_spin_lock(&pwq->pool->lock) with irq disabled
> >      insert_work
> >        wake_up_worker(pool);
> >          wake_up_process first_idle_worker(pool);
> >=20
> > Even if waker is lucky enough running on worker's CPU, what is weird is=
 an
> > idle worker can trigger the warning, given
> >=20
> > 	if (smp_load_acquire(&p->on_cpu) &&
> > 	    ttwu_queue_wakelist(p, task_cpu(p), wake_flags | WF_ON_CPU))
> > 		goto unlock;
> >=20
> > because p->on_cpu must have been false for quite a while.
> >=20
> > Is there any chance for CPU hotplug to make a difference?
> >=20
> > Thoughts are welcome.
> >=20
> > Hillf
>=20
> Hillf, thank you very much for the comments, and sorry about this late re=
ply.
>=20
> I walked through related functions to understand your comments and, but I=
 have
> to say that I still don't have enough background knowledge to provide val=
uable
> comments back to you. I understand that the waker and the wakee are on sa=
me CPU,
> and it is weird that p->on_cpu is true. This looks indicating that the ta=
sk
> scheduler failing to control task status on task migration triggered by C=
PU
> hotplugs, but as far as I read comments in kernel/sched/core.c, CPU hotpl=
ug and
> task migration are folded into the design and implementation.
>=20
> The blktests test case block/008 runs I/Os to a test target block device =
30
> seconds. During this I/O, it repeats offlining CPUs and onlining CPUs: wh=
en
> there are N CPUs are available, it offlines N-1 CPUs to have only one onl=
ine
> CPU, then onlines all CPUs again. It repeats this online and offline unti=
l I/O
> workload completes. When the only one CPU is online, the waker and the wa=
kee can
> be on the same CPU. Or, one of the waker or the wakee might have been mig=
rated
> from other CPUs to the only one online CPU. But still it is not clear for=
 me why
> it results in the WARNING.
>=20
> Now I'm trying to recreate the failure. By repeating test cases in "block
> group" on the kernel v5.13-rc5, I was able to recreate the failure. It to=
ok 3 to
> 5 hours to recreate it. The test target block device used was a null_blk =
with
> rather unique configuration (zoned device with zone capacity smaller than=
 zone
> size). I will try to confirm the failure recreation with latest kernel ve=
rsion
> and other block devices.

I tried some device setups, and found that dm-linear device on null_blk
recreates the warning  consistently. In case anyone wishes to recreate it, =
let
me share the bash script below which I used. I tried it several times on th=
e
kernel v5.13, and all tries recreated the warning. With my system (nproc is=
 8),
it took from 3 to 6 hours to recreate.

---------------------------------------------------------------------------=
-----
#!/bin/bash

# create a null_blk device
declare sysfs=3D/sys/kernel/config/nullb/nullb0
modprobe null_blk nr_devices=3D0
mkdir "${sysfs}"
echo 1024 > "${sysfs}"/size
echo 1 > "${sysfs}"/memory_backed
echo 1 > "${sysfs}"/power
sleep 1

# create a dm-linear device on the null_blk device
echo "0 $((0x2000 * 4)) linear /dev/nullb0 0" | dmsetup create test
sleep 1

# run blktests, block/008 many times
git clone https://github.com/osandov/blktests.git
cd blktests
echo "TEST_DEVS=3D( /dev/mapper/test )" > config
for ((i=3D0;i<1000;i++)); do
        echo $i;
        if ! ./check block/008; then
                break;
        fi
done

--=20
Best Regards,
Shin'ichiro Kawasaki=