Re: [bug report] WARNING: CPU: 1 PID: 1386 at block/blk-mq-sched.c:432 blk_mq_sched_insert_request+0x54/0x178

Jens Axboe
2021-11-02T19:02:14Z

On 11/2/21 1:00 PM, Steffen Maier wrote:
> On 11/2/21 07:42, Yi Zhang wrote:
>> Below WARNING was triggered with blktests srp/001 on the latest
>> linux-block/for-next, and it cannot be reproduced with v5.15, pls help
>> check it, thanks.
>>
>> 88d2c6ab15f7 (origin/for-next) Merge branch 'for-5.16/block' into for-next
>
> Same warning here with a slightly different stack trace.
> It breaks root-fs on zfcp-attached SCSI disks for us, because we run our CI
> intentionally with panic_on_warn.
>
>> [ 9.031740] ------------[ cut here ]------------
>> [ 9.031743] WARNING: CPU: 13 PID: 196 at block/blk-mq-sched.c:432 blk_mq_sched_insert_request+0x54/0x178
>> [ 9.031751] Modules linked in: nft_reject_inet(E) nf_reject_ipv4(E) nf_reject_ipv6(E) nft_reject(E) dm_service_time(E) nft_ct(E) nft_chain_nat(E) nf_nat(E) nf_conntrack(E) nf_defrag_ipv6(E) nf_defrag_ipv4(E) ip_set(E) nf_tables(E) nfnetlink(E) sunrpc(E) zfcp(E) scsi_transport_fc(E) dm_multipath(E) scsi_dh_rdac(E) scsi_dh_emc(E) scsi_dh_alua(E) s390_trng(E) vfio_ccw(E) mdev(E) vfio_iommu_type1(E) zcrypt_cex4(E) vfio(E) eadm_sch(E) sch_fq_codel(E) configfs(E) ip_tables(E) x_tables(E) ghash_s390(E) prng(E) aes_s390(E) des_s390(E) libdes(E) sha3_512_s390(E) sha3_256_s390(E) sha512_s390(E) sha256_s390(E) sha1_s390(E) sha_common(E) pkey(E) zcrypt(E) rng_core(E) autofs4(E)
>> [ 9.031785] CPU: 13 PID: 196 Comm: kworker/13:2 Tainted: G E 5.16.0-20211102.rc0.git0.9febf1194306.300.fc34.s390x+next #1
>> [ 9.031789] Hardware name: IBM 3906 M04 704 (LPAR)
>> [ 9.031791] Workqueue: kaluad alua_rtpg_work [scsi_dh_alua]
>> [ 9.031795] Krnl PSW : 0704e00180000000 000000006558e948 (blk_mq_sched_insert_request+0x58/0x178)
>> [ 9.031800] R:0 T:1 IO:1 EX:1 Key:0 M:1 W:0 P:0 AS:3 CC:2 PM:0 RI:0 EA:3
>> [ 9.031803] Krnl GPRS: 0000000000000080 00000000000004c6 00000000ade56000 0000000000000001
>> [ 9.031806] 0000000000000001 0000000000000000 00000000a2d6a400 0000000084003c00
>> [ 9.031808] 0000000000000000 0000000000000001 0000000000000001 00000000ade56000
>> [ 9.031810] 000000008aef0000 000003ff7af59400 000003800e3d7b00 000003800e3d7a90
>> [ 9.031817] Krnl Code: 000000006558e93c: a71effff chi %r1,-1
>> 000000006558e940: a7840004 brc 8,000000006558e948
>> #000000006558e944: af000000 mc 0,0
>> >000000006558e948: 5810b01c l %r1,28(%r11)
>> 000000006558e94c: ec213bbb0055 risbg %r2,%r1,59,187,0
>> 000000006558e952: a7740057 brc 7,000000006558ea00
>> 000000006558e956: 5810b018 l %r1,24(%r11)
>> 000000006558e95a: c01b000000ff nilf %r1,255
>> [ 9.031833] Call Trace:
>> [ 9.031835] [<000000006558e948>] blk_mq_sched_insert_request+0x58/0x178
>> [ 9.031838] [<000000006557effe>] blk_execute_rq+0x56/0xd8
>> [ 9.031841] [<0000000065768708>] __scsi_execute+0x118/0x240
>> [ 9.031847] [<000003ff803c3788>] alua_rtpg+0x120/0x8f8 [scsi_dh_alua]
>> [ 9.031849] [<000003ff803c402c>] alua_rtpg_work+0xcc/0x648 [scsi_dh_alua]
>> [ 9.031852] [<0000000064f024d2>] process_one_work+0x1fa/0x470
>> [ 9.031856] [<0000000064f02c74>] worker_thread+0x64/0x498
>> [ 9.031859] [<0000000064f0a894>] kthread+0x17c/0x188
>> [ 9.031861] [<0000000064e933c4>] __ret_from_fork+0x3c/0x58
>> [ 9.031864] [<0000000065a71cea>] ret_from_fork+0xa/0x40
>> [ 9.031868] Last Breaking-Event-Address:
>> [ 9.031869] [<000000006557ef72>] blk_execute_rq_nowait+0x82/0x98
>> [ 9.031871] Kernel panic - not syncing: panic_on_warn set ...

I'm looking into this one, it's a bit puzzling. The WARN is:

WARN_ON(e && (rq->tag != BLK_MQ_NO_TAG));

which is "we have an elevator", yet the tag isn't initialized to BLK_MQ_NO_TAG.
That seems to hint at the initialization changes there, but nothing sticks out
there for me.

I'll keep looking.

--
Jens Axboe