Re: Many warnings on 2.6.29 from your sync_single_inode warning

Re: Many warnings on 2.6.29 from your sync_single_inode warning

[Nick Piggin]

On Tue, May 26, 2009 at 11:06:21AM -0700, Stephen Hemminger wrote:
> The WARN_ON you introduced in     
>  fs: new inode i_state corruption fix
>     
> Triggers every time during our regression test. The regression test runs
> on a VM under VMWare. Any ideas?

Thanks. Adding linux-fsdevel.

I guess you're mounting with -osync or -odirsync, or opening with O_SYNC?

I think it's a false positive. The filesystem code syncs the inode to disk
just after creating it but before doing an unlock_new_inode on it to
clear I_NEW. I believe this should not result in any race, because it is
called by the guy who has created the inode and he never clears I_NEW. The
race came about when pdflush would be able to perform writeout in this
window, and non-atomic updates of i_state would race with the creator when
they are messing with i_state (without inode_lock held, because inode is
new).

We could add some convoluted checks to try to allow for this, but I think
we might as well just rip out the checks...

Would anyone prefer me to try to keep them? If not, I'll send a patch to
rip them out.


> 
> May 26 02:20:59 vyatta ntpd[2792]: ntpd 4.2.4p6@1.1549-o Tue Mar 10 02:08:20 UTC 2009 (1)
> 
> May 26 02:20:59 vyatta ntpd[2793]: Warning: the "dynamic" keyword has been obsoleted and will be removed in the next release 
> 
> May 26 02:20:59 vyatta last message repeated 3 times
> 
> May 25 19:21:55 vyatta kernel: [   99.490294] ------------[ cut here ]------------
> 
> May 25 19:21:55 vyatta kernel: [   99.490314] WARNING: at fs/fs-writeback.c:292 __writeback_single_inode+0x150/0x35f()
> 
> May 25 19:21:55 vyatta kernel: [   99.490349] Hardware name: VMware Virtual Platform
> 
> May 25 19:21:55 vyatta kernel: [   99.490386] Modules linked in: iptable_nat ip6table_filter iptable_filter ip6table_raw ip6_tables xt_NOTRACK iptable_raw ip_tables x_tables nf_nat_pptp nf_conntrack_pptp nf_conntrack_proto_gre nf_nat_h323 nf_conntrack_h323 nf_nat_sip nf_conntrack_sip nf_nat_proto_gre nf_nat_tftp nf_nat_ftp nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_conntrack_tftp nf_conntrack_ftp nf_conntrack ipv6 md_mod parport_pc parport container psmouse serio_raw pcspkr i2c_piix4 i2c_core button shpchp pci_hotplug intel_agp ac agpgart evdev vfat fat ext2 mbcache battery squashfs loop unionfs nls_utf8 isofs nls_base zlib_inflate sg sr_mod cdrom floppy mptspi mptscsih mptbase scsi_transport_spi pcnet32 mii ata_piix pata_acpi ata_generic libata scsi_mod thermal processor fan thermal_sys
 
> 
> May 25 19:21:55 vyatta kernel: [   99.490713] Pid: 3483, comm: mkdir Not tainted 2.6.29-1-586-vyatta #1
> 
> May 25 19:21:55 vyatta kernel: [   99.490755] Call Trace:
> 
> May 25 19:21:55 vyatta kernel: [   99.491060]  [<c0122288>] warn_slowpath+0x80/0xb6
> 
> May 25 19:21:55 vyatta kernel: [   99.491093]  [<c02d8a8d>] schedule+0x688/0x6f3
> 
> May 25 19:21:55 vyatta kernel: [   99.491103]  [<c0137eea>] getnstimeofday+0x51/0xd7
> 
> May 25 19:21:55 vyatta kernel: [   99.491111]  [<c01343ad>] ktime_get_ts+0x22/0x49
> 
> May 25 19:21:55 vyatta kernel: [   99.491119]  [<c0152d90>] delayacct_end+0x70/0x77
> 
> May 25 19:21:55 vyatta kernel: [   99.491123]  [<c0152de8>] __delayacct_blkio_end+0x2f/0x32
> 
> May 25 19:21:55 vyatta kernel: [   99.491127]  [<c02d8b63>] io_schedule+0x6b/0x87
> 
> May 25 19:21:55 vyatta kernel: [   99.491131]  [<c02d8e69>] __wait_on_bit+0x50/0x58
> 
> May 25 19:21:55 vyatta kernel: [   99.491142]  [<c015abb8>] sync_page+0x0/0x36
> 
> May 25 19:21:55 vyatta kernel: [   99.491148]  [<c019020c>] __writeback_single_inode+0x150/0x35f
> 
> May 25 19:21:55 vyatta kernel: [   99.491152]  [<c01317dd>] wake_bit_function+0x0/0x3c
> 
> May 25 19:21:55 vyatta kernel: [   99.491157]  [<c015fa39>] write_one_page+0xa3/0xb8
> 
> May 25 19:21:55 vyatta kernel: [   99.491161]  [<c0190434>] sync_inode+0x19/0x23
> 
> May 25 19:21:55 vyatta kernel: [   99.491562]  [<d09bdfe4>] ext2_sync_inode+0x26/0x2c [ext2]
> 
> May 25 19:21:55 vyatta kernel: [   99.491577]  [<d09bca65>] ext2_make_empty+0x165/0x17b [ext2]
> 
> May 25 19:21:55 vyatta kernel: [   99.491589]  [<d09bfc8a>] ext2_mkdir+0x9c/0x105 [ext2]
> 
> May 25 19:21:55 vyatta kernel: [   99.491607]  [<c0183231>] vfs_mkdir+0x51/0x95
> 
> May 25 19:21:55 vyatta kernel: [   99.491613]  [<c01842e8>] sys_mkdirat+0x97/0xd0
> 
> May 25 19:21:55 vyatta kernel: [   99.491621]  [<c016d78b>] remove_vma+0x3e/0x43
> 
> May 25 19:21:55 vyatta kernel: [   99.491625]  [<c016e351>] do_munmap+0x1ed/0x207
> 
> May 25 19:21:55 vyatta kernel: [   99.491633]  [<c0184330>] sys_mkdir+0xf/0x13
> 
> May 25 19:21:55 vyatta kernel: [   99.491638]  [<c0102f12>] syscall_call+0x7/0xb
> 
> May 25 19:21:55 vyatta kernel: [   99.491746] ---[ end trace 70fa05fb7550612c ]---
> 
> May 25 19:21:55 vyatta kernel: [   99.513627] ------------[ cut here ]------------
> 
> May 25 19:21:55 vyatta kernel: [   99.513633] WARNING: at fs/fs-writeback.c:317 __writeback_single_inode+0x202/0x35f()
> 
> May 25 19:21:55 vyatta kernel: [   99.513636] Hardware name: VMware Virtual Platform
> 
> May 25 19:21:55 vyatta kernel: [   99.513638] Modules linked in: iptable_nat ip6table_filter iptable_filter ip6table_raw ip6_tables xt_NOTRACK iptable_raw ip_tables x_tables nf_nat_pptp nf_conntrack_pptp nf_conntrack_proto_gre nf_nat_h323 nf_conntrack_h323 nf_nat_sip nf_conntrack_sip nf_nat_proto_gre nf_nat_tftp nf_nat_ftp nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_conntrack_tftp nf_conntrack_ftp nf_conntrack ipv6 md_mod parport_pc parport container psmouse serio_raw pcspkr i2c_piix4 i2c_core button shpchp pci_hotplug intel_agp ac agpgart evdev vfat fat ext2 mbcache battery squashfs loop unionfs nls_utf8 isofs nls_base zlib_inflate sg sr_mod cdrom floppy mptspi mptscsih mptbase scsi_transport_spi pcnet32 mii ata_piix pata_acpi ata_generic libata scsi_mod thermal processor fan thermal_sys
 
> 
> May 25 19:21:55 vyatta kernel: [   99.513784] Pid: 3483, comm: mkdir Tainted: G        W  2.6.29-1-586-vyatta #1
> 
> May 25 19:21:55 vyatta kernel: [   99.513788] Call Trace:
> 
> May 25 19:21:55 vyatta kernel: [   99.513794]  [<c0122288>] warn_slowpath+0x80/0xb6
> 
> May 25 19:21:55 vyatta kernel: [   99.513799]  [<c015a7a6>] find_get_pages_tag+0x35/0xd5
> 
> May 25 19:21:55 vyatta kernel: [   99.513805]  [<c02d8b63>] io_schedule+0x6b/0x87
> 
> May 25 19:21:55 vyatta kernel: [   99.513810]  [<c0161053>] pagevec_lookup_tag+0x1b/0x22
> 
> May 25 19:21:55 vyatta kernel: [   99.513814]  [<c015b4ac>] wait_on_page_writeback_range+0x9d/0xde
> 
> May 25 19:21:55 vyatta kernel: [   99.513819]  [<c0194e37>] __wait_on_buffer+0x16/0x18
> 
> May 25 19:21:55 vyatta kernel: [   99.513827]  [<c01951e3>] sync_dirty_buffer+0x54/0x87
> 
> May 25 19:21:55 vyatta kernel: [   99.513841]  [<d09be355>] ext2_update_inode+0x28a/0x2c4 [ext2]
> 
> May 25 19:21:55 vyatta kernel: [   99.513846]  [<c01902be>] __writeback_single_inode+0x202/0x35f
> 
> May 25 19:21:55 vyatta kernel: [   99.513851]  [<c015fa39>] write_one_page+0xa3/0xb8
> 
> May 25 19:21:55 vyatta kernel: [   99.513855]  [<c0190434>] sync_inode+0x19/0x23
> 
> May 25 19:21:55 vyatta kernel: [   99.513867]  [<d09bdfe4>] ext2_sync_inode+0x26/0x2c [ext2]
> 
> May 25 19:21:55 vyatta kernel: [   99.513879]  [<d09bca65>] ext2_make_empty+0x165/0x17b [ext2]
> 
> May 25 19:21:55 vyatta kernel: [   99.513890]  [<d09bfc8a>] ext2_mkdir+0x9c/0x105 [ext2]
> 
> May 25 19:21:55 vyatta kernel: [   99.513897]  [<c0183231>] vfs_mkdir+0x51/0x95
> 
> May 25 19:21:55 vyatta kernel: [   99.513901]  [<c01842e8>] sys_mkdirat+0x97/0xd0
> 
> May 25 19:21:55 vyatta kernel: [   99.513905]  [<c016d78b>] remove_vma+0x3e/0x43
> 
> May 25 19:21:55 vyatta kernel: [   99.513909]  [<c016e351>] do_munmap+0x1ed/0x207
> 
> May 25 19:21:55 vyatta kernel: [   99.513914]  [<c0184330>] sys_mkdir+0xf/0x13
> 
> May 25 19:21:55 vyatta kernel: [   99.513918]  [<c0102f12>] syscall_call+0x7/0xb
> 
> May 25 19:21:55 vyatta kernel: [   99.513921] ---[ end trace 70fa05fb7550612d ]---

Re: Many warnings on 2.6.29 from your sync_single_inode warning

[Stephen Hemminger]

On Thu, 28 May 2009 08:03:33 +0200
Nick Piggin <npiggin@suse.de> wrote:

> On Tue, May 26, 2009 at 11:06:21AM -0700, Stephen Hemminger wrote:
> > The WARN_ON you introduced in     
> >  fs: new inode i_state corruption fix
> >     
> > Triggers every time during our regression test. The regression test runs
> > on a VM under VMWare. Any ideas?
> 
> Thanks. Adding linux-fsdevel.
> 
> I guess you're mounting with -osync or -odirsync, or opening with O_SYNC?
> 
> I think it's a false positive. The filesystem code syncs the inode to disk
> just after creating it but before doing an unlock_new_inode on it to
> clear I_NEW. I believe this should not result in any race, because it is
> called by the guy who has created the inode and he never clears I_NEW. The
> race came about when pdflush would be able to perform writeout in this
> window, and non-atomic updates of i_state would race with the creator when
> they are messing with i_state (without inode_lock held, because inode is
> new).
> 
> We could add some convoluted checks to try to allow for this, but I think
> we might as well just rip out the checks...
> 
> Would anyone prefer me to try to keep them? If not, I'll send a patch to
> rip them out.

You are right the file system is mounted on a virtual floppy device with -o sync.
That explains it.

This also explains why it only shows up in regression system (developers usually
install the software).  The floppy is useful for saving configuration when
running off live cd.