From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753545AbdJaAKu (ORCPT ); Mon, 30 Oct 2017 20:10:50 -0400 Received: from mga11.intel.com ([192.55.52.93]:48071 "EHLO mga11.intel.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753286AbdJaAKs (ORCPT ); Mon, 30 Oct 2017 20:10:48 -0400 X-ExtLoop1: 1 X-IronPort-AV: E=Sophos;i="5.44,321,1505804400"; d="scan'208";a="915622182" Date: Tue, 31 Oct 2017 01:10:41 +0100 From: Fengguang Wu To: Eryu Guan Cc: Lukas Czerner , Jan Kara , "Darrick J. Wong" , Jeff Moyer , Jens Axboe , Linus Torvalds , Linux Kernel Mailing List , linux-fsdevel Subject: Re: [btrfs] WARNING: CPU: 0 PID: 6379 at fs/direct-io.c:293 dio_complete+0x1d4/0x220 Message-ID: <20171031001041.5qjzn5pjertpdc3e@wfg-t540p.sh.intel.com> References: <20171029225155.qcum5i75awrt5tzm@wfg-t540p.sh.intel.com> <20171030072021.gcgpaolo5m3myuln@wfg-t540p.sh.intel.com> <20171030074429.GC3283@eguan.usersys.redhat.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii; format=flowed Content-Disposition: inline In-Reply-To: <20171030074429.GC3283@eguan.usersys.redhat.com> User-Agent: NeoMutt/20170609 (1.8.3) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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 >> AuthorDate: Thu Sep 21 08:16:29 2017 -0600 >> Commit: Jens Axboe >> 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 >> Reviewed-by: Darrick J. Wong >> Reviewed-by: Jeff Moyer >> Signed-off-by: Lukas Czerner >> Signed-off-by: Jens Axboe >> --- >> 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 >