Re: [btrfs] WARNING: CPU: 0 PID: 6379 at fs/direct-io.c:293 dio_complete+0x1d4/0x220

[Fengguang Wu <fengguang.wu@intel.com>]

Hi Eryu,

On Mon, Oct 30, 2017 at 03:44:29PM +0800, Eryu Guan wrote:
>Hi Fengguang,
>
>On Mon, Oct 30, 2017 at 08:20:21AM +0100, Fengguang Wu wrote:
>> CC fsdevel.
>>
>> On Sun, Oct 29, 2017 at 11:51:55PM +0100, Fengguang Wu wrote:
>> > Hi Linus,
>> >
>> > Up to now we see the below boot error/warnings when testing v4.14-rc6.
>> >
>> > They hit the RC release mainly due to various imperfections in 0day's
>> > auto bisection. So I manually list them here and CC the likely easy to
>> > debug ones to the corresponding maintainers in the followup emails.
>> >
>> > boot_successes: 4700
>> > boot_failures: 247
>>
>> [...]
>>
>> > WARNING:at_fs/direct-io.c:#dio_complete: 7
>> > WARNING:at_fs/iomap.c:#iomap_dio_complete: 3
>> > WARNING:at_fs/iomap.c:#iomap_dio_rw: 1
>>
>> The first warning happens on btrfs and is bisected to this commit.
>> The other 2 warnings happen on xfs.
>
>I noticed that the warnings are triggered by generic/095 and
>generic/208, they're known to generate such warnings and I think these
>warnings are kind of 'known issue', please see comments above
>_filter_aiodio_dmesg() in fstests/common/filter.
>
>Please make sure your local fstests contains the following 3 commits:
>
>ca93e26865ab common: move _filter_xfs_dmesg() to common/filter
>5aa662733ab0 common: turn _filter_xfs_dmesg() into _filter_aiodio_dmesg()
>228aee780f13 generic/036,208: whitelist [iomap_]dio_complete() WARNs

OK.

>we filtered out such warnings in fstests on purpose so the affected
>tests won't fail because of such dmesg warnings.

We may also teach 0day robot to ignore the warning when running the
above 2 fstests.

The more generic way of filtering may be to inject a dmesg line like

        THIS TEST WILL TRIGGER KERNEL WARNING, PLEASE IGNORE.

just before the specific tests startup. Then 3rd party dmesg parsing
scripts can handle such purpose-made warnings in a uniform way.

Thanks,
Fengguang

>>
>> commit 332391a9935da939319e473b4680e173df75afcf
>> Author:     Lukas Czerner <lczerner@redhat.com>
>> AuthorDate: Thu Sep 21 08:16:29 2017 -0600
>> Commit:     Jens Axboe <axboe@kernel.dk>
>> CommitDate: Mon Sep 25 08:56:05 2017 -0600
>>
>>    fs: Fix page cache inconsistency when mixing buffered and AIO DIO
>>
>>    Currently when mixing buffered reads and asynchronous direct writes it
>>    is possible to end up with the situation where we have stale data in the
>>    page cache while the new data is already written to disk. This is
>>    permanent until the affected pages are flushed away. Despite the fact
>>    that mixing buffered and direct IO is ill-advised it does pose a thread
>>    for a data integrity, is unexpected and should be fixed.
>>
>>    Fix this by deferring completion of asynchronous direct writes to a
>>    process context in the case that there are mapped pages to be found in
>>    the inode. Later before the completion in dio_complete() invalidate
>>    the pages in question. This ensures that after the completion the pages
>>    in the written area are either unmapped, or populated with up-to-date
>>    data. Also do the same for the iomap case which uses
>>    iomap_dio_complete() instead.
>>
>>    This has a side effect of deferring the completion to a process context
>>    for every AIO DIO that happens on inode that has pages mapped. However
>>    since the consensus is that this is ill-advised practice the performance
>>    implication should not be a problem.
>>
>>    This was based on proposal from Jeff Moyer, thanks!
>>
>>    Reviewed-by: Jan Kara <jack@suse.cz>
>>    Reviewed-by: Darrick J. Wong <darrick.wong@oracle.com>
>>    Reviewed-by: Jeff Moyer <jmoyer@redhat.com>
>>    Signed-off-by: Lukas Czerner <lczerner@redhat.com>
>>    Signed-off-by: Jens Axboe <axboe@kernel.dk>
>> ---
>> fs/direct-io.c | 47 ++++++++++++++++++++++++++++++++++++++++++-----
>> fs/iomap.c     | 29 ++++++++++++++++-------------
>> mm/filemap.c   |  6 ++++++
>> 3 files changed, 64 insertions(+), 18 deletions(-)
>>
>> The call traces are:
>>
>> [  334.461955] BTRFS info (device vdb): has skinny extents
>> [  334.463231] BTRFS info (device vdb): flagging fs with big metadata feature
>> [  334.469746] BTRFS info (device vdb): creating UUID tree
>> [  336.190840] ------------[ cut here ]------------
>> [  336.193338] WARNING: CPU: 0 PID: 6379 at fs/direct-io.c:293 dio_complete+0x1d4/0x220
>> [  336.196925] Modules linked in: btrfs xor zstd_decompress zstd_compress xxhash raid6_pq dm_mod rpcsec_gss_krb5 auth_rpcgss nfsv4 dns_resolver sr_mod cdrom sg ata_generic pata_acpi ppdev snd_pcm snd_timer snd soundcore serio_raw parport_pc pcspkr parport floppy ata_piix libata i2c_piix4 ip_tables
>> [  336.203746] CPU: 0 PID: 6379 Comm: kworker/0:0 Not tainted 4.14.0-rc6 #1
>> [  336.204799] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
>> [  336.207480] Workqueue: dio/vdb dio_aio_complete_work
>> [  336.208373] task: ffff880079094a80 task.stack: ffffc90000950000
>> [  336.210495] RIP: 0010:dio_complete+0x1d4/0x220
>> [  336.211288] RSP: 0018:ffffc90000953e20 EFLAGS: 00010286
>> [  336.213145] RAX: 00000000fffffff0 RBX: ffff8800aae8c780 RCX: ffffc90000953c70
>> [  336.214232] RDX: 0000000080000000 RSI: 00000000000002b4 RDI: ffffffff81cb9ccb
>> [  336.216605] RBP: ffffc90000953e48 R08: 0000000000000000 R09: ffff880079c8b6c0
>> [  336.217726] R10: 0000000000000074 R11: 0000000000000000 R12: 0000000000002000
>> [  336.220141] R13: 0000000000002000 R14: 0000000000000003 R15: 0000000000074000
>> [  336.221232] FS:  0000000000000000(0000) GS:ffff88013fc00000(0000) knlGS:0000000000000000
>> [  336.223915] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [  336.224885] CR2: 000055e9eae6b750 CR3: 00000000752c7000 CR4: 00000000000006f0
>> [  336.227202] Call Trace:
>> [  336.227750]  dio_aio_complete_work+0x19/0x20
>> [  336.228536]  process_one_work+0x198/0x3e0
>> [  336.230396]  worker_thread+0x4e/0x3e0
>> [  336.231064]  kthread+0x114/0x150
>> [  336.232489]  ? process_one_work+0x3e0/0x3e0
>> [  336.233250]  ? kthread_create_on_node+0x40/0x40
>> [  336.234929]  ? kthread_create_on_node+0x40/0x40
>> [  336.235754]  ret_from_fork+0x25/0x30
>> [  336.237322] Code: 8b 78 30 48 83 7f 58 00 0f 84 e9 fe ff ff 4b 8d 54 27 ff 4c 89 fe 48 c1 fe 0c 48 c1 fa 0c e8 64 58 f3 ff 85 c0 0f 84 cc fe ff ff <0f> ff e9 c5 fe ff ff 8b 50 20 f6 c2 10 0f 84 e5 fe ff ff 48 8b
>> [  336.240031] ---[ end trace 3d29f0720cd16ad3 ]---
>> [  378.043462] generic/095       [failed, exit status 1] - output mismatch (see /lkp/benchmarks/xfstests/results//generic/095.out.bad)
>> [  378.043465]
>>
>>
>> [  121.160532] run fstests generic/117 at 2017-10-25 05:27:29
>> [  123.275347] XFS (vdd): Mounting V5 Filesystem
>> [  123.280579] XFS (vdd): Ending clean mount
>> [  163.043220] XFS (vdd): Unmounting Filesystem
>> [  163.258872] generic/117       42s
>> [  163.258875]
>> [  164.009187] run fstests generic/208 at 2017-10-25 05:28:12
>> [  164.344046] ------------[ cut here ]------------
>> [  164.345164] WARNING: CPU: 1 PID: 86 at fs/iomap.c:755 iomap_dio_complete+0xe5/0x100
>> [  164.347193] Modules linked in: xfs dm_mod rpcsec_gss_krb5 auth_rpcgss nfsv4 dns_resolver sr_mod cdrom sg ata_generic pata_acpi ppdev snd_pc
>> m snd_timer snd soundcore parport_pc pcspkr serio_raw floppy parport ata_piix i2c_piix4 libata ip_tables
>> [  164.351698] CPU: 1 PID: 86 Comm: kworker/1:2 Not tainted 4.14.0-rc6 #1
>> [  164.353111] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
>> [  164.361199] Workqueue: dio/vda iomap_dio_complete_work
>> [  164.362418] task: ffff88007f8b8000 task.stack: ffffc90000a4c000
>> [  164.363666] RIP: 0010:iomap_dio_complete+0xe5/0x100
>> [  164.364923] RSP: 0018:ffffc90000a4fe08 EFLAGS: 00010286
>> [  164.366065] RAX: 00000000fffffff0 RBX: ffff88007a5fba80 RCX: ffffc90000a4fc58
>> [  164.367281] RDX: 0000000080000000 RSI: 00000000000002b4 RDI: ffffffff81cb9ccb
>> [  164.368330] RBP: ffffc90000a4fe30 R08: 0000000000000000 R09: ffff8800750eeb58
>> [  164.369503] R10: 0000000000001ffe R11: 0000000000000000 R12: 0000000002000000
>> [  164.370573] R13: ffff8800b8d27780 R14: ffff8800b8869058 R15: 0000000000000000
>> [  164.371674] FS:  0000000000000000(0000) GS:ffff88013fc80000(0000) knlGS:0000000000000000
>> [  164.373136] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [  164.387036] CR2: 00007f5ee028e000 CR3: 000000007a1ff000 CR4: 00000000000006e0
>> [  164.388119] Call Trace:
>> [  164.388581]  iomap_dio_complete_work+0x25/0x80
>> [  164.389385]  process_one_work+0x198/0x3e0
>> [  164.390054]  worker_thread+0x4e/0x3e0
>> [  164.390699]  kthread+0x114/0x150
>> [  164.391341]  ? process_one_work+0x3e0/0x3e0
>> [  164.392038]  ? kthread_create_on_node+0x40/0x40
>> [  164.392922]  ret_from_fork+0x25/0x30
>> [  164.393506] Code: e0 eb 9f 48 8b 77 18 e9 78 ff ff ff 4c 89 fa 48 03 53 18 4c 89 fe 48 c1 fe 0c 48 83 ea 01 48 c1 fa 0c e8 0f 93 f0 ff 85 c
>> 0 74 93 <0f> ff eb 8f 4c 63 67 28 e9 54 ff ff ff 0f 1f 40 00 66 2e 0f 1f
>> [  164.396264] ---[ end trace 77984c98cc2335de ]---
>> [  364.297438] generic/208       200s
>> [  364.297442]
>> [  365.772872] XFS (vda): Unmounting Filesystem
>> [  366.507546] XFS (vda): Mounting V5 Filesystem
>> [  366.519283] XFS (vda): Ending clean mount
>>
>>
>> [  370.264428] run fstests generic/095 at 2017-10-25 05:38:44
>> [  370.392041] XFS (vdd): Unmounting Filesystem
>> [  372.641826] XFS (vdd): Mounting V5 Filesystem
>> [  372.648446] XFS (vdd): Ending clean mount
>> [  373.277786] ------------[ cut here ]------------
>> [  373.279820] ------------[ cut here ]------------
>> [  373.279826] WARNING: CPU: 2 PID: 29166 at fs/iomap.c:1016 iomap_dio_rw+0x346/0x360
>> [  373.279827] Modules linked in: xfs dm_mod rpcsec_gss_krb5 auth_rpcgss nfsv4 dns_resolver sr_mod cdrom sg ata_generic pata_acpi ppdev snd_pcm snd_timer snd soundcore serio_raw pcspkr i2c_piix4 ata_piix parport_pc parport floppy libata ip_tables
>> [  373.279842] CPU: 2 PID: 29166 Comm: fio Not tainted 4.14.0-rc6 #1
>> [  373.279843] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
>> [  373.279844] task: ffff88008bd34a80 task.stack: ffffc900065f8000
>> [  373.279846] RIP: 0010:iomap_dio_rw+0x346/0x360
>> [  373.279847] RSP: 0000:ffffc900065fbd40 EFLAGS: 00010286
>> [  373.279848] RAX: 00000000fffffff0 RBX: ffffc900065fbe98 RCX: ffffc900065fbb90
>> [  373.279848] RDX: 0000000080000000 RSI: 00000000000002b4 RDI: ffffffff81cb9ccb
>> [  373.279849] RBP: ffffc900065fbdd0 R08: 0000000000000000 R09: 00007f6fe0948000
>> [  373.279850] R10: ffff88013ffd2000 R11: 0000000000000400 R12: 000000000005f400
>> [  373.279850] R13: ffffc900065fbe70 R14: ffff88007a6fb7e0 R15: 0000000000000011
>> [  373.279852] FS:  00007f6fb3ce1700(0000) GS:ffff88013fd00000(0000) knlGS:0000000000000000
>> [  373.279852] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [  373.279853] CR2: 00007f6fe088ac00 CR3: 0000000078eb7000 CR4: 00000000000006e0
>> [  373.279856] Call Trace:
>> [  373.279913]  ? xfs_file_aio_write_checks+0x137/0x190 [xfs]
>> [  373.279933]  xfs_file_dio_aio_write+0xec/0x260 [xfs]
>> [  373.279952]  ? xfs_file_dio_aio_write+0xec/0x260 [xfs]
>> [  373.279970]  xfs_file_write_iter+0x98/0x150 [xfs]
>> [  373.279972]  __vfs_write+0xd3/0x150
>> [  373.279974]  vfs_write+0xc7/0x1b0
>> [  373.279975]  SyS_pwrite64+0x76/0x90
>> [  373.279977]  entry_SYSCALL_64_fastpath+0x1a/0xa5
>> [  373.279979] RIP: 0033:0x7f6fcc3019d3
>> [  373.279979] RSP: 002b:00007f6fb3cdeb20 EFLAGS: 00000293 ORIG_RAX: 0000000000000012
>> [  373.279980] RAX: ffffffffffffffda RBX: 00007f6fb3ce1700 RCX: 00007f6fcc3019d3
>> [  373.279981] RDX: 0000000000000400 RSI: 000055e925caac00 RDI: 0000000000000004
>> [  373.279982] RBP: 00007f6fe095fee0 R08: 0000000000000000 R09: 00007f6fb3ce1700
>> [  373.279982] R10: 000000000005f400 R11: 0000000000000293 R12: 0000000000000000
>> [  373.279983] R13: 00007f6fe095fe2f R14: 0000000000000003 R15: 00007f6fe095fee0
>> [  373.279984] Code: 21 00 00 f6 58 2b 81 49 c7 44 24 08 00 00 00 00 4c 89
>> f7 e8 ed ec ff ff e9 13 fe ff ff 48 8d 7d a0 e8 2f a9 13 00 e9 33 ff ff ff
>> <0f> ff e9 6a fe ff ff 48 c7 c0 f4 ff ff ff e9 f2 fd ff ff 90 90 [
>> 373.279998] ---[ end trace 01e002a8aa01ae25 ]---
>> [  373.334858] WARNING: CPU: 3 PID: 29158 at fs/iomap.c:755 iomap_dio_complete+0xe5/0x100
>> [  373.336817] Modules linked in: xfs dm_mod rpcsec_gss_krb5 auth_rpcgss nfsv4 dns_resolver sr_mod cdrom sg ata_generic pata_acpi ppdev snd_pcm snd_timer snd soundcore serio_raw pcspkr i2c_piix4 ata_piix parport_pc parport floppy libata ip_tables
>> [  373.341916] CPU: 3 PID: 29158 Comm: fio Tainted: G        W       4.14.0-rc6 #1
>> [  373.344151] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
>> [  373.346702] task: ffff88008bd32540 task.stack: ffffc900065c8000
>> [  373.348512] RIP: 0010:iomap_dio_complete+0xe5/0x100
>> [  373.349999] RSP: 0018:ffffc900065cbd08 EFLAGS: 00010286
>> [  373.351604] RAX: 00000000fffffff0 RBX: ffff88007a5611e0 RCX: ffffc900065cbb58
>> [  373.353690] RDX: 0000000080000000 RSI: 00000000000002b4 RDI: ffffffff81cb9ccb
>> [  373.355693] RBP: ffffc900065cbd30 R08: 0000000000000000 R09: 00007f6fe08cb000
>> [  373.357775] R10: ffffc900065cb8c8 R11: 0000000000000207 R12: 0000000000000400
>> [  373.359837] R13: ffffc900065cbe70 R14: ffff8800787657d8 R15: 0000000000002400
>> [  373.361878] FS:  00007f6fe095aa80(0000) GS:ffff88013fd80000(0000) knlGS:0000000000000000
>> [  373.364333] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [  373.366071] CR2: 00007f6fcc38c1ee CR3: 000000007949a000 CR4: 00000000000006e0
>> [  373.368170] Call Trace:
>> [  373.369165]  ? iomap_dio_rw+0x2a6/0x360
>> [  373.370467]  iomap_dio_rw+0x333/0x360
>> [  373.371768]  xfs_file_dio_aio_write+0xec/0x260 [xfs]
>> [  373.373069]  ? xfs_file_dio_aio_write+0xec/0x260 [xfs]
>> [  373.374410]  xfs_file_write_iter+0x98/0x150 [xfs]
>> [  373.375820]  __vfs_write+0xd3/0x150
>> [  373.377096]  vfs_write+0xc7/0x1b0
>> [  373.378436]  SyS_pwrite64+0x76/0x90
>> [  373.379897]  entry_SYSCALL_64_fastpath+0x1a/0xa5
>> [  373.381488] RIP: 0033:0x7f6fcc3019d3
>> [  373.382781] RSP: 002b:00007f6fe0957ea0 EFLAGS: 00000293 ORIG_RAX: 0000000000000012
>> [  373.385064] RAX: ffffffffffffffda RBX: 000055e925cb07f0 RCX: 00007f6fcc3019d3
>> [  373.386913] RDX: 0000000000000400 RSI: 000055e925ca9800 RDI: 0000000000000005
>> [  373.388911] RBP: 0000000000000005 R08: 0000000000000000 R09: 00007f6fe095aa80
>> [  373.390588] R10: 0000000000002400 R11: 0000000000000293 R12: 00007f6fe095aa80
>> [  373.392296] R13: 00007f6fe0957ec0 R14: 0000000000000003 R15: 000055e925caf360
>> [  373.394229] Code: e0 eb 9f 48 8b 77 18 e9 78 ff ff ff 4c 89 fa 48 03 53
>> 18 4c 89 fe 48 c1 fe 0c 48 83 ea 01 48 c1 fa 0c e8 0f 93 f0 ff 85 c0 74 93
>> <0f> ff eb 8f 4c 63 67 28 e9 54 ff ff ff 0f 1f 40 00 66 2e 0f 1f [
>> 373.398812] ---[ end trace 01e002a8aa01ae26 ]---
>> [  392.887639] XFS (vdd): Unmounting Filesystem
>> [  392.985715] generic/095	 [failed, exit status 1] - output mismatch (see /lkp/benchmarks/xfstests/results//generic/095.out.bad)
>>
>> Thanks,
>> Fengguang
>