FYI - I could reproduce with above C reproduer on my setup 5.17-rc3.
I was also able to hit it with XFS <below stack shows that>
So here is some initial analysis on this one. I haven't completely debugged it
though. I am just putting my observations here for others too.
It seems iomap_dio_rw is getting called with a negative iocb->ki_pos value.
(I haven't yet looked into when can this happen. Is it due to negative loop
device mapping range offset or something?)
i.e.
(gdb) p iocb->ki_pos
$101 = -
2147483648
(gdb) p /x iocb->ki_pos
$102 = 0xffffffff80000000
(gdb)
This when passed to ->iomap_begin() sometimes is resulting into iomap->offset
which is a positive value and hence hitting below warn_on_once in
iomap_iter_done().
WARN_ON_ONCE(iter->iomap.offset > iter->pos)
1. So I think the question here is what does it mean when xfs/ext4_file_read_iter()
is called with negative iocb->ki_pos value?
2. Also when can iocb->ki_pos be negative?
<Stack Track on XFS>
======================
[ 998.417802] ------------[ cut here ]------------
[ 998.420195] WARNING: CPU: 0 PID: 1579 at fs/iomap/iter.c:33
iomap_iter+0x301/0x320
[ 998.424610] Modules linked in:
[ 998.425683] CPU: 0 PID: 1579 Comm: kworker/u2:5 Tainted:
G W 5.17.0-rc3+ #0
[ 998.428085] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.13.0-1ubuntu1 04
[ 998.430830] Workqueue: loop0 loop_rootcg_workfn
[ 998.432300] RIP: 0010:iomap_iter+0x301/0x320
[ 998.433647] Code: 89 f2 e8 72 f1 ff ff 65 ff 0d bb d0 ce 7e 0f 85 c4 fe ff ff
e8 2f 3e cdc
[ 998.438518] RSP: 0018:ffffc90000c13b30 EFLAGS: 00010307
[ 998.440490] RAX: 0000000000010000 RBX: ffffc90000c13bc0 RCX: 000000000000000c
[ 998.442576] RDX: ffffffff80000000 RSI: 0000000000001000 RDI: 0000000000000000
[ 998.444625] RBP: ffffc90000c13b50 R08: 0000000000000003 R09: ffff88814ceb9b00
[ 998.446768] R10: ffff88815122e000 R11: 000000000000000f R12: ffffffff82657c90
[ 998.453038] R13: ffffc90000c13be8 R14: ffffc90000c13c30 R15: ffffffff82657c90
[ 998.455533] FS: 0000000000000000(0000) GS:ffff88852bc00000(0000)
knlGS:0000000000000000
[ 998.458136] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 998.460069] CR2: 00007ffff4443000 CR3: 0000000105e7e000 CR4: 00000000000006f0
[ 998.462447] Call Trace:
[ 998.463108] <TASK>
[ 998.464510] __iomap_dio_rw+0x25b/0x840
[ 998.466005] iomap_dio_rw+0xe/0x30
[ 998.467476] xfs_file_dio_read+0xb9/0xf0
[ 998.469044] xfs_file_read_iter+0xc1/0xe0
[ 998.470623] lo_rw_aio+0x27a/0x2a0
[ 998.472042] loop_process_work+0x2c7/0x8c0
[ 998.473621] ? finish_task_switch+0xbc/0x260
[ 998.475232] ? __switch_to+0x2cf/0x480
[ 998.476832] loop_rootcg_workfn+0x1b/0x20
[ 998.478431] process_one_work+0x1b7/0x380
[ 998.479958] worker_thread+0x4d/0x380
[ 998.481440] ? process_one_work+0x380/0x380
[ 998.482992] kthread+0xff/0x130
[ 998.484420] ? kthread_complete_and_exit+0x20/0x20
[ 998.486122] ret_from_fork+0x22/0x30
[ 998.487616] </TASK>
[ 998.488199] ---[ end trace 0000000000000000 ]---
-ritesh