[REGRESSION] xfstests #269 without journal failure against 'dev' branch

[REGRESSION] xfstests #269 without journal failure against 'dev' branch

[Zheng Liu]

Hi Ted,

There is a regression in 'dev' branch of ext4.  I can trigger it by
xfstests #269 in my desktop with a SSD when journal is disabled.  I
run this test case in 3.8-rc7 and it is ok.  So I think this is a
regression in 'dev' branch.

I know you are on vacation and maybe you don't have time to take a look
at it.  But I think I need to let you know, and other folks might take a
look at it.

Enjoy your vacation. :-)

                                                - Zheng

FSTYP         -- ext4
PLATFORM      -- Linux/x86_64 lz-desktop 3.8.0-rc3+
MKFS_OPTIONS  -- -O ^has_journal /dev/sda2
MOUNT_OPTIONS -- -o acl,user_xattr /dev/sda2 /mnt/sda2

269 32s ... [failed, exit status 1] - output mismatch (see 269.out.bad)
    --- 269.out	2013-02-07 22:56:14.000000000 +0800
    +++ 269.out.bad	2013-02-17 22:09:21.000000000 +0800
    @@ -3,3 +3,4 @@
     Run fsstress
     
     Run dd writers in parallel
    +_check_generic_filesystem: filesystem on /dev/sda2 is inconsistent (see
269.full)
     ...
     (Run 'diff -u 269.out 269.out.bad' to see the entire diff)
Ran: 269
Failures: 269
Failed 1 of 1 tests

wenqing: run xfstest 269
kernel: EXT4-fs (sda2): mounted filesystem without journal. Opts: acl,user_xattr
kernel: EXT4-fs (sda2): ext4_da_update_reserve_space: ino 1166, allocated 1 with
only 0 reserved metadata blocks
kernel:
kernel: ------------[ cut here ]------------
kernel: WARNING: at fs/ext4/inode.c:359 ext4_da_update_reserve_space+0x10f/0x21b
[ext4]()
kernel: Hardware name: OptiPlex 780                 
kernel: Modules linked in: ext4 jbd2 crc16 cpufreq_ondemand acpi_cpufreq mperf
ipv6 dm_mirror dm_region_hash dm_log dm_mod parport_pc parport dcdbas serio_raw
sg button pcspkr i2c_i801 i2c_core ehci_pci ehci_hcd e1000e ext3 jbd sd_mod ahci
libahci libata scsi_mod uhci_hcd
kernel: Pid: 2860, comm: flush-8:0 Not tainted 3.8.0-rc3+ #3
kernel: Call Trace:
kernel: [<ffffffff82031d5c>] warn_slowpath_common+0x85/0x9d
kernel: [<ffffffff82031d8e>] warn_slowpath_null+0x1a/0x1c
kernel: [<ffffffffa0203fa8>] ext4_da_update_reserve_space+0x10f/0x21b [ext4]
kernel: [<ffffffffa022b9a5>] ext4_ext_map_blocks+0xdad/0xf68 [ext4]
kernel: [<ffffffff820ba234>] ? release_pages+0x169/0x178
kernel: [<ffffffffa020557b>] ? write_cache_pages_da+0x107/0x416 [ext4]
kernel: [<ffffffffa02049ac>] ext4_map_blocks+0x135/0x1ef [ext4]
kernel: [<ffffffffa02051ad>] mpage_da_map_and_submit+0x111/0x3d8 [ext4]
kernel: [<ffffffffa0226265>] ? ext4_ext_index_trans_blocks+0x17/0x3a [ext4]
kernel: [<ffffffffa0205c12>] ext4_da_writepages+0x388/0x530 [ext4]
kernel: [<ffffffff821161cd>] ? __getblk+0x2d/0x264
kernel: [<ffffffff820b8465>] do_writepages+0x20/0x29
kernel: [<ffffffff8210f9ff>] __writeback_single_inode+0x48/0x119
kernel: [<ffffffff82110be8>] writeback_sb_inodes+0x1ec/0x2fd
kernel: [<ffffffff82110f4d>] wb_writeback+0x131/0x230
kernel: [<ffffffff821110e1>] wb_do_writeback+0x95/0x1ea
kernel: [<ffffffff8237ced9>] ? schedule_timeout+0x158/0x178
kernel: [<ffffffff8203f7c5>] ? add_timer_on+0xae/0xae
kernel: [<ffffffff821112f8>] bdi_writeback_thread+0xc2/0x1e2
kernel: [<ffffffff82111236>] ? wb_do_writeback+0x1ea/0x1ea
kernel: [<ffffffff82111236>] ? wb_do_writeback+0x1ea/0x1ea
kernel: [<ffffffff8204e9f3>] kthread+0xb5/0xbd
kernel: [<ffffffff8204e93e>] ? kthread_freezable_should_stop+0x65/0x65
kernel: [<ffffffff8238615c>] ret_from_fork+0x7c/0xb0
kernel: [<ffffffff8204e93e>] ? kthread_freezable_should_stop+0x65/0x65
kernel: ---[ end trace 72c02955946d0799 ]---
kernel: EXT4-fs (sda1): mounted filesystem without journal. Opts: acl,user_xattr

Re: [REGRESSION] xfstests #269 without journal failure against 'dev' branch

[Theodore Ts'o]

[-- Attachment #1: Type: text/plain, Size: 7605 bytes --]

On Mon, Feb 18, 2013 at 01:09:18AM +0800, Zheng Liu wrote:
> Hi Ted,
> 
> There is a regression in 'dev' branch of ext4.  I can trigger it by
> xfstests #269 in my desktop with a SSD when journal is disabled.  I
> run this test case in 3.8-rc7 and it is ok.  So I think this is a
> regression in 'dev' branch.

Hmm, I'm not seeing it on my auto run:

BEGIN TEST: Ext4 4k block w/ no journal Sun Feb 17 06:48:55 EST 2013
Ran: 001 002 005 006 007 011 013 014 015 020 053 062 069 070 074 075 076 079 083 088 089 091 100 105 112 113 117 120 123 124 125 126 127 128 129 130 131 132 133 135 141 169 184 192 193 198 204 207 208 209 210 211 212 213 214 215 219 221 223 224 225 226 228 230 231 232 233 234 235 236 237 239 240 243 245 246 247 248 249 255 256 257 258 263 269 270 271 272 273 274 275 277 285 289
Failures: 274
END TEST: Ext4 4k block w/ no journal Sun Feb 17 08:01:06 EST 2013

Is this failing for you reliably?  I've double checked all of my test
runs, and I've never seen test 269 fail for me with the standard 4k no
journal test run.  Of course, I'm not using an SSD for my tests, so
that may explain the difference.  I have seen the warning before, but
it's not a regression, so it on my "we need to examine this closely
but it's not yet a showstopper list":

127 [ 3553.596006] EXT4-fs warning (device vdb): ext4_da_update_reserve_space:360: ino 2628, allocated 1 with only 0 reserved metadata blocks (releasing 1 blocks with reserved 16 data blocks)

Attached below was my latest auto test run (this doesn't have your
latest extent status tree patches, since I ran it last night).  It
*did* fail on test 269 with dioread_nolock, but in a different way
than what you reported.  Instead of resulting in a corrupt file
system, it actually caused a kernel BUG to get triggered.  (See
attached):

       	      	     	  	   	       - Ted

[    0.000000] Linux version 3.8.0-rc3-00054-g7b690cf (tytso@closure) (gcc version 4.7.2 (Debian 4.7.2-4) ) #895 SMP Sun Feb 17 02:42:02 EST 2013
FSTESTCFG is "all"
FSTESTSET is "-g auto"
BEGIN TEST: Ext4 4k block Sun Feb 17 02:43:08 EST 2013
Ran: 001 002 005 006 007 011 013 014 015 020 053 062 068 069 070 074 075 076 079 083 088 089 091 100 105 112 113 117 120 123 124 125 126 127 128 129 130 131 132 133 135 141 169 184 192 193 198 204 207 208 209 210 211 212 213 214 215 219 221 223 224 225 226 228 230 231 232 233 234 235 236 237 239 240 243 245 246 247 248 249 255 256 257 258 263 269 270 271 272 273 274 275 277 280 285 289
Failures: 274 280
END TEST: Ext4 4k block Sun Feb 17 05:00:59 EST 2013
BEGIN TEST: Ext4 4k block w/nodelalloc, no flex_bg, and no extents Sun Feb 17 05:01:21 EST 2013
Ran: 001 002 005 006 007 011 013 014 015 020 053 062 068 069 070 074 075 076 079 083 088 089 091 100 105 112 113 117 120 123 124 125 126 127 128 129 130 131 132 133 135 141 169 184 192 193 198 204 207 208 209 210 211 212 215 219 221 224 225 226 230 231 232 233 234 235 236 237 239 240 245 246 247 248 249 255 256 257 258 263 269 270 271 272 273 275 277 280 285 289
Failures: 255 280 285
END TEST: Ext4 4k block w/nodelalloc, no flex_bg, and no extents Sun Feb 17 06:48:53 EST 2013
BEGIN TEST: Ext4 4k block w/ no journal Sun Feb 17 06:48:55 EST 2013
Ran: 001 002 005 006 007 011 013 014 015 020 053 062 069 070 074 075 076 079 083 088 089 091 100 105 112 113 117 120 123 124 125 126 127 128 129 130 131 132 133 135 141 169 184 192 193 198 204 207 208 209 210 211 212 213 214 215 219 221 223 224 225 226 228 230 231 232 233 234 235 236 237 239 240 243 245 246 247 248 249 255 256 257 258 263 269 270 271 272 273 274 275 277 285 289
Failures: 274
END TEST: Ext4 4k block w/ no journal Sun Feb 17 08:01:06 EST 2013
BEGIN TEST: Ext4 1k block Sun Feb 17 08:01:27 EST 2013
Ran: 001 002 005 006 007 011 013 014 015 020 053 062 068 069 070 074 075 076 079 083 088 089 091 100 105 112 113 117 120 123 124 125 126 127 128 129 130 131 132 133 135 141 169 184 192 193 198 204 207 208 209 210 211 212 213 214 215 219 221 223 224 225 226 228 230 231 232 233 234 235 236 237 239 240 243 245 246 247 248 249 255 256 257 258 263 269 270 271 272 273 274 275 277 280 285 289
Failures: 274 280
END TEST: Ext4 1k block Sun Feb 17 11:36:11 EST 2013
BEGIN TEST: Ext4 4k block w/nodelalloc and no flex_bg Sun Feb 17 11:36:14 EST 2013
Ran: 001 002 005 006 007 011 013 014 015 020 053 062 068 069 070 074 075 076 079 083 088 089 091 100 105 112 113 117 120 123 124 125 126 127 128 129 130 131 132 133 135 141 169 184 192 193 198 204 207 208 209 210 211 212 213 214 215 219 221 223 224 225 226 228 230 231 232 233 234 235 236 237 239 240 243 245 246 247 248 249 255 256 257 258 263 269 270 271 272 273 274 275 277 280 285 289
Failures: 223 274 280
END TEST: Ext4 4k block w/nodelalloc and no flex_bg Sun Feb 17 13:12:19 EST 2013
BEGIN TEST: Ext4 4k block w/metadata_csum Sun Feb 17 13:12:22 EST 2013
Ran: 001 002 005 006 007 011 013 014 015 020 053 062 068 069 070 074 075 076 079 083 088 089 091 100 105 112 113 117 120 123 124 125 126 127 128 129 130 131 132 133 135 141 169 184 192 193 198 204 207 208 209 210 211 212 213 214 215 219 221 223 224 225 226 228 230 231 232 233 234 235 236 237 239 240 243 245 246 247 248 249 255 256 257 258 263 269 270 271 272 273 274 275 277 280 285 289
Failures: 274 280
END TEST: Ext4 4k block w/metadata_csum Sun Feb 17 14:49:53 EST 2013
BEGIN TEST: Ext4 4k block w/dioread_nolock Sun Feb 17 14:49:54 EST 2013
...
269 76s ...[50834.086303] BUG: unable to handle kernel NULL pointer dereference at   (null)
[50834.088266] IP: [<c016fd26>] cwq_activate_delayed_work+0x1a/0x33
[50834.088266] *pdpt = 00000000263ec001 *pde = 0000000000000000 
[50834.088266] Oops: 0000 [#1] SMP DEBUG_PAGEALLOC
[50834.088266] Modules linked in:
[50834.088266] Pid: 6, comm: kworker/u:0 Tainted: G        W    3.8.0-rc3-00054-g7b690cf #895 Bochs Bochs
[50834.088266] EIP: 0060:[<c016fd26>] EFLAGS: 00010046 CPU: 1
[50834.088266] EIP is at cwq_activate_delayed_work+0x1a/0x33
[50834.088266] EAX: 00000000 EBX: c2cc58bc ECX: 00001200 EDX: 00001200
[50834.088266] ESI: 00000000 EDI: 00000000 EBP: f64b7e94 ESP: f64b7e8c
[50834.088266]  DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
[50834.088266] CR0: 8005003b CR2: 00000000 CR3: 29f77000 CR4: 000006f0
[50834.088266] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[50834.088266] DR6: ffff0ff0 DR7: 00000400
[50834.088266] Process kworker/u:0 (pid: 6, ti=f64b6000 task=f64b4160 task.ti=f64b6000)
[50834.088266] Stack:
[50834.088266]  e9ae9400 00000000 f64b7ea4 c016fd74 d8bff644 00000000 f64b7efc c01712c9
[50834.088266]  f64b45d0 f5427bc0 f5427bc0 0019a806 c0e453b0 c027a7e0 c0e45380 e9ae9400
[50834.088266]  c0e452c0 c0e453f0 f6435540 c13975e8 c0f298e8 00000000 c0a73c8d 00000001
[50834.088266] Call Trace:
[50834.088266]  [<c016fd74>] cwq_dec_nr_in_flight+0x35/0x69
[50834.088266]  [<c01712c9>] process_one_work+0x2ce/0x330
[50834.088266]  [<c027a7e0>] ? ext4_end_bio+0x1b1/0x1b1
[50834.088266]  [<c01715ae>] worker_thread+0xff/0x18d
[50834.088266]  [<c01714af>] ? rescuer_thread+0x15e/0x15e
[50834.088266]  [<c0174d7f>] kthread+0x79/0x7e
[50834.088266]  [<c019c55a>] ? trace_hardirqs_on+0xb/0xd
[50834.088266]  [<c080fcb7>] ret_from_kernel_thread+0x1b/0x28
[50834.088266]  [<c0174d06>] ? __kthread_parkme+0x59/0x59
[50834.088266] Code: c6 04 89 75 f0 75 c7 eb e6 89 19 58 5b 5e 5f 5d c3 55 89 e5 56 53 3e 8d 74 26 00 89 c3 e8 d1 f2 ff ff 89 c6 89 d8 e8 17 f9 ff ff <8b> 16 31 c9 89 d8 83 c2 08 e8 81 ff ff ff 0f ba 33 01 ff 46 4c
[50834.088266] EIP: [<c016fd26>] cwq_activate_delayed_work+0x1a/0x33 SS:ESP 0068:f64b7e8c
[50834.088266] CR2: 0000000000000000
[50834.088266] ---[ end trace 749b7ebbf8d88a3e ]---





[-- Attachment #2: log.201302170242.bz2 --]
[-- Type: application/octet-stream, Size: 37189 bytes --]

Re: [REGRESSION] xfstests #269 without journal failure against 'dev' branch

[Zheng Liu]

On Sun, Feb 17, 2013 at 11:57:47PM -0500, Theodore Ts'o wrote:
> On Mon, Feb 18, 2013 at 01:09:18AM +0800, Zheng Liu wrote:
> > Hi Ted,
> > 
> > There is a regression in 'dev' branch of ext4.  I can trigger it by
> > xfstests #269 in my desktop with a SSD when journal is disabled.  I
> > run this test case in 3.8-rc7 and it is ok.  So I think this is a
> > regression in 'dev' branch.
> 
> Hmm, I'm not seeing it on my auto run:
> 
> BEGIN TEST: Ext4 4k block w/ no journal Sun Feb 17 06:48:55 EST 2013
> Ran: 001 002 005 006 007 011 013 014 015 020 053 062 069 070 074 075 076 079 083 088 089 091 100 105 112 113 117 120 123 124 125 126 127 128 129 130 131 132 133 135 141 169 184 192 193 198 204 207 208 209 210 211 212 213 214 215 219 221 223 224 225 226 228 230 231 232 233 234 235 236 237 239 240 243 245 246 247 248 249 255 256 257 258 263 269 270 271 272 273 274 275 277 285 289
> Failures: 274
> END TEST: Ext4 4k block w/ no journal Sun Feb 17 08:01:06 EST 2013
> 
> Is this failing for you reliably?  I've double checked all of my test
> runs, and I've never seen test 269 fail for me with the standard 4k no
> journal test run.  Of course, I'm not using an SSD for my tests, so
> that may explain the difference.  I have seen the warning before, but
> it's not a regression, so it on my "we need to examine this closely
> but it's not yet a showstopper list":

Today I run xfstest #269 serveral times (maybe 30 times I guess) against
different commits.  To be honest, It couldn't be always reproduced.  I
summarize the result here.

9fff24aa, I never trigger the regression against this commit.
1139575a, the regression is triggered only one time.
7eedefe8, the regression can be triggered three or four times.
7b690cfa, I could trigger it about six times.

I also run the same test case in another machine, which is almost the
same previous one except that it only has a HDD.  The regression could be
triggered in commit 7eedefe8.  But I don't think this commit can causes
this regression.

In general I agree with you that we need to take care of it but it's not
yet urgent.

Regards,
                                                - Zheng

Re: [REGRESSION] xfstests #269 without journal failure against 'dev' branch

[Theodore Ts'o]

I was able to reproduce the failure reliably by using a 5G tmpfs file
for the VM's disk file, and bisected this down to:

    ext4: support simple conversion of extent-mapped inodes to use i_blocks
    
    In order to make it simpler to test the code which support
    i_blocks/indirect-mapped inodes, support the conversion of inodes
    which are less than 12 blocks and which are contained in no more than
    a single extent.
    
    The primary intended use of this code is to converting freshly created
    zero-length files and empty directories.
    
    Note that the version of chattr in e2fsprogs 1.42.7 and earlier has a
    check that prevents the clearing of the extent flag.  A simple patch
    which allows "chattr -e <file>" to work will be checked into the
    e2fsprogs git repository.
    
    Signed-off-by: "Theodore Ts'o" <tytso@mit.edu>

I don't think this is actually causing the problem, but rather
exposing a latent bug in fs/ext4/indirect.c.  From some code
inspection that I did investigating the resize2fs bug, it's pretty
clear that indirect.c codepath has some bugs dealing with ENOSPC
conditions when allocating indirect metadata blocks.

Xfstests #269 runs fsstress in parallel with ENOSPC hitters, and one
of the things fsstress does is to call the FS_IOC_SETFLAGS with random
values, so with this commit, we are migrating some small files to use
indirect block..  I suspect that when we then do some writes to these
small files and they hit an ENOSPC condition, it causes the file
system corruption.

I patched ext4_ind_migrate() to log an ext4_warning and then return
-ENOSPC, and confirmed that (a) with ext4_end_migrate() disabled, the
fs corruption problem went away, and (b) fsstress is calling
FS_IOC_SETFLAGS with completely random values, and thus causing us to
migrate some of the extent-mapped files to indirect block mapped
files.

Given that extents->indirect migration isn't really that important, I
propose we deal with this by dropping the above commit for now.  It's
clear we need to fix up fs/ext4/indirect.c, especially as more
distro's consider using ext4 to support ext3 file systems.  So after
we fix the ENOSPC bugs I've noticed in ext4_alloc_branch(), we can try
introducing the extent->indirect migration feature again for the next
merge window.

Zheng, thanks for calling this bug to our attention, and thanks for
your extensive testing efforts!

       	      	  	       	      - Ted

Re: [REGRESSION] xfstests #269 without journal failure against 'dev' branch

[Zheng Liu]

On Thu, Feb 21, 2013 at 02:44:48PM -0500, Theodore Ts'o wrote:
> I was able to reproduce the failure reliably by using a 5G tmpfs file
> for the VM's disk file, and bisected this down to:
> 
>     ext4: support simple conversion of extent-mapped inodes to use i_blocks
>     
>     In order to make it simpler to test the code which support
>     i_blocks/indirect-mapped inodes, support the conversion of inodes
>     which are less than 12 blocks and which are contained in no more than
>     a single extent.
>     
>     The primary intended use of this code is to converting freshly created
>     zero-length files and empty directories.
>     
>     Note that the version of chattr in e2fsprogs 1.42.7 and earlier has a
>     check that prevents the clearing of the extent flag.  A simple patch
>     which allows "chattr -e <file>" to work will be checked into the
>     e2fsprogs git repository.
>     
>     Signed-off-by: "Theodore Ts'o" <tytso@mit.edu>
> 
> I don't think this is actually causing the problem, but rather
> exposing a latent bug in fs/ext4/indirect.c.  From some code
> inspection that I did investigating the resize2fs bug, it's pretty
> clear that indirect.c codepath has some bugs dealing with ENOSPC
> conditions when allocating indirect metadata blocks.
> 
> Xfstests #269 runs fsstress in parallel with ENOSPC hitters, and one
> of the things fsstress does is to call the FS_IOC_SETFLAGS with random
> values, so with this commit, we are migrating some small files to use
> indirect block..  I suspect that when we then do some writes to these
> small files and they hit an ENOSPC condition, it causes the file
> system corruption.
> 
> I patched ext4_ind_migrate() to log an ext4_warning and then return
> -ENOSPC, and confirmed that (a) with ext4_end_migrate() disabled, the
> fs corruption problem went away, and (b) fsstress is calling
> FS_IOC_SETFLAGS with completely random values, and thus causing us to
> migrate some of the extent-mapped files to indirect block mapped
> files.
> 
> Given that extents->indirect migration isn't really that important, I
> propose we deal with this by dropping the above commit for now.  It's
> clear we need to fix up fs/ext4/indirect.c, especially as more
> distro's consider using ext4 to support ext3 file systems.  So after
> we fix the ENOSPC bugs I've noticed in ext4_alloc_branch(), we can try
> introducing the extent->indirect migration feature again for the next
> merge window.
> 
> Zheng, thanks for calling this bug to our attention, and thanks for
> your extensive testing efforts!

Hi Ted,

Thanks for your explanation.  I agree with you that we could drop this
patch temporarily and take it back after we fix the ENOSPC bug in
ext4_alloc_branch().

Regards,
                                                - Zheng