lists.openwall.net   lists  /  announce  owl-users  owl-dev  john-users  john-dev  passwdqc-users  yescrypt  popa3d-users  /  oss-security  kernel-hardening  musl  sabotage  tlsify  passwords  /  crypt-dev  xvendor  /  Bugtraq  Full-Disclosure  linux-kernel  linux-netdev  linux-ext4  linux-hardening  linux-cve-announce  PHC 
Open Source and information security mailing list archives
 
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [thread-next>] [day] [month] [year] [list]
Message-ID: <20130207220536.GA16092@wallace>
Date:	Thu, 7 Feb 2013 17:05:36 -0500
From:	Eric Whitney <enwlinux@...il.com>
To:	linux-ext4@...r.kernel.org
Cc:	tytso@....edu
Subject: ext4 xfstests-bld results for 3.8-rc6 on Pandaboard ES

These are the results of a run of Ted Ts'o's xfstests-bld test harness against
ext4 on a Pandaboard ES running a 3.8-rc6 kernel.  The harness contains
several test suites exercising various combinations of ext4 mount options.
Each segment of the text below describes the mount options used in each
scenario (although not noted, the block_validity option was also used in all
cases), a list of xfstests run, and notes discussing any failures reported by 
the suite or found in the syslog.

Code built from the tips of the e2fsprogs and xfstests master branches was
used for this testing rather than that found in the xfstests-bld tree.

With one exception noted below, the test results taken on the Pandaboard (ARM
processor) are the same as those observed from a run on an x86-64 KVM guest.

Thanks,
Eric


BEGIN TEST: Ext4 4k block Fri Feb  1 13:08:25 EST 2013
Ran: 001 002 005 006 007 011 013 014 015 020 053 062 069 070 075 076 079 088
 091 105 112 113 117 120 123 124 126 128 129 130 131 135 141 169 184 193 198
 207 210 211 212 213 214 215 219 221 223 225 228 230 235 236 237 240 243 245
 246 247 248 249 255 256 257 258 263 271 277 289 294
Passed all 69 tests
END TEST: Ext4 4k block Fri Feb  1 14:07:45 EST 2013


BEGIN TEST: Ext4 4k block w/nodelalloc, no flex_bg, and no extents Fri Feb  1
 14:08:14 EST 2013
Ran: 001 002 005 006 007 011 013 014 015 020 053 062 069 070 075 076 079 088
 091 105 112 113 117 120 123 124 126 128 129 130 131 135 141 169 184 193 198
 207 210 211 212 215 219 221 225 230 235 236 237 240 245 246 247 248 249 257
 258 263 271 277 289 294
Passed all 62 tests
END TEST: Ext4 4k block w/nodelalloc, no flex_bg, and no extents Fri Feb  1 
 14:38:05 EST 2013


BEGIN TEST: Ext4 4k block w/ no journal Fri Feb  1 14:38:10 EST 2013
Ran: 001 002 005 006 007 011 013 014 015 020 053 062 069 070 075 076 079 088
 091 105 112 113 117 120 123 124 126 128 129 130 131 135 141 169 184 193 198
 207 210 211 212 213 214 215 219 221 223 225 228 230 235 236 237 240 243 245
 246 247 248 249 255 256 257 258 263 271 277 289 294
Passed all 69 tests
END TEST: Ext4 4k block w/ no journal Fri Feb  1 15:33:29 EST 2013


BEGIN TEST: Ext4 1k block Fri Feb  1 15:33:52 EST 2013
Ran: 001 002 005 006 007 011 013 014 015 020 053 062 069 070 075 076 079 088
 091 105 112 113 117 120 123 124 126 128 129 130 131 135 141 169 184 193 198
 207 210 211 212 213 214 215 219 221 223 225 228 230 235 236 237 240 243 245
 246 247 248 249 255 256 257 258 263 271 277 289 294
Passed all 69 tests
END TEST: Ext4 1k block Fri Feb  1 16:05:38 EST 2013


BEGIN TEST: Ext4 4k block w/nodelalloc and no flex_bg Fri Feb  1 16:05:45 EST
 2013
Ran: 001 002 005 006 007 011 013 014 015 020 053 062 069 070 075 076 079 088
 091 105 112 113 117 120 123 124 126 128 129 130 131 135 141 169 184 193 198
 207 210 211 212 213 214 215 219 221 223 225 228 230 235 236 237 240 243 245
 246 247 248 249 255 256 257 258 263 271 277 289 294
Failures: 223
END TEST: Ext4 4k block w/nodelalloc and no flex_bg Fri Feb  1 16:36:47 EST
 2013

Notes:

1) This is a sample of the 223 failure output (also seen on x86-64);  the
complete test log contains numerous additional mismatches of the same sort:

223 54s ...	[15:33:09] [15:34:11] - output mismatch (see 223.out.bad)
    --- 223.out	2012-12-23 14:52:52.897392805 -0500
    +++ 223.out.bad	2013-02-06 15:34:11.750303000 -0500
    @@ -204,47 +204,47 @@
     SCRATCH_MNT/file-1-131072-falloc: well-aligned
     SCRATCH_MNT/file-1-131072-write: well-aligned
     SCRATCH_MNT/file-2-131072-falloc: well-aligned
    -SCRATCH_MNT/file-2-131072-write: well-aligned
    +SCRATCH_MNT/file-2-131072-write: Start block 33296 not multiple of sunit 32
     SCRATCH_MNT/file-3-131072-falloc: well-aligned
     SCRATCH_MNT/file-3-131072-write: well-aligned
     ...


BEGIN TEST: Ext4 4k block w/metadata_csum Fri Feb  1 16:36:54 EST 2013
Ran: 001 002 005 006 007 011 013 014 015 020 053 062 069 070 075 076 079 088
 091 105 112 113 117 120 123 124 126 128 129 130 131 135 141 169 184 193 198
 207 210 211 212 213 214 215 219 221 223 225 228 230 235 236 237 240 243 245
 246 247 248 249 255 256 257 258 263 271 277 289 294
Passed all 69 tests
END TEST: Ext4 4k block w/metadata_csum Fri Feb  1 17:09:01 EST 2013


BEGIN TEST: Ext4 4k block w/dioread_nolock Fri Feb  1 17:09:01 EST 2013
Ran: 001 002 005 006 007 011 013 014 015 020 053 062 069 070 075 076 079 088
 091 105 112 113 117 120 123 124 126 128 129 130 131 135 141 169 184 193 198
 207 210 211 212 213 214 215 219 221 223 225 228 230 235 236 237 240 243 245
 246 247 248 249 255 256 257 258 263 271 277 289 294
Passed all 69 tests
END TEST: Ext4 4k block w/dioread_nolock Fri Feb  1 18:05:12 EST 2013

Notes:

1) 113 produces lockdep warnings on 3.8-rc6 that I've only seen on the
Pandaboard so far (this is the only testing anomaly on -rc6 that appears to be
unique to it).  I've seen them on both the Pandaboard and x86-64 in past -rc's,
and the signature has varied over time with different rc's.  The lockdep
warning is lengthy, so I've placed it at the end of this report.


BEGIN TEST: Ext4 4k block w/data=journal Fri Feb  1 18:05:32 EST 2013
Ran: 001 002 005 006 007 011 013 014 015 020 053 062 069 070 075 076 079 088
 091 105 112 113 117 120 123 124 126 128 129 130 131 135 141 169 184 193 198
 207 210 211 212 213 214 215 219 221 223 225 228 230 235 236 237 240 243 245
 246 247 248 249 255 256 257 258 263 271 277 289 294
Failures: 223
END TEST: Ext4 4k block w/data=journal Fri Feb  1 19:01:44 EST 2013

Notes:

1) The following message appears in the syslog when xfstest 246 is run (also
seen on x86-64):

JBD2: Spotted dirty metadata buffer (dev = sda1, blocknr = 160256). There's a
risk of filesystem corruption in case of system crash.

2) This is a sample of the 223 failure output (also seen on x86-64);  the
complete test log contains numerous additional mismatches of the same sort:
223 61s ...	[15:48:55] [15:50:18] - output mismatch (see 223.out.bad)
    --- 223.out	2012-12-23 14:52:52.897392805 -0500
    +++ 223.out.bad	2013-02-06 15:50:18.437803000 -0500
    @@ -204,45 +204,45 @@
     SCRATCH_MNT/file-1-131072-falloc: well-aligned
     SCRATCH_MNT/file-1-131072-write: well-aligned
     SCRATCH_MNT/file-2-131072-falloc: well-aligned
    -SCRATCH_MNT/file-2-131072-write: well-aligned
    +SCRATCH_MNT/file-2-131072-write: Start block 33296 not multiple of sunit 32
     SCRATCH_MNT/file-3-131072-falloc: well-aligned
     SCRATCH_MNT/file-3-131072-write: well-aligned
     ...


BEGIN TEST: Ext4 4k block w/bigalloc Fri Feb  1 19:02:10 EST 2013
Ran: 001 002 005 006 007 011 013 014 015 020 053 062 069 070 075 076 079 088
 091 105 112 113 117 120 123 124 126 128 129 130 131 135 141 169 184 193 198
 207 210 211 212 213 214 215 219 221 223 225 228 230 235 236 237 240 243 245
 246 247 248 249 257 258 263 271 277 289 294
Failures: 015 219 235
END TEST: Ext4 4k block w/bigalloc Fri Feb  1 19:21:22 EST 2013

Notes:

1) This is all of the 015 failure output (also seen on x86-64):

015 6s ...	[17:23:07] [17:23:12] - output mismatch (see 015.out.bad)
    --- 015.out	2012-12-23 14:52:52.530205305 -0500
    +++ 015.out.bad	2013-02-06 17:23:12.390928000 -0500
    @@ -4,4 +4,5 @@
     check free space:
     delete fill:
     check free space:
    -   !!! free space is in range
    +   !!! free space has value of 0
    +free space is NOT in range 43655.04 .. 44536.96
     ...

Multiple bursts of messages similar to this sample appear in the syslog when
015 is run:

EXT4-fs (sda2): delayed block allocation failed for inode 12 at logical offset 11056 with max blocks 2048 with error -28
EXT4-fs (sda2): This should not happen!! Data will be lost
EXT4-fs (sda2): Total free blocks count 0
EXT4-fs (sda2): Free/Dirty block details
EXT4-fs (sda2): free_blocks=0
EXT4-fs (sda2): dirty_blocks=42992
EXT4-fs (sda2): Block reservation details
EXT4-fs (sda2): i_reserved_data_blocks=998
EXT4-fs (sda2): i_reserved_meta_blocks=1689
EXT4-fs (sda2): delayed block allocation failed for inode 12 at logical offset 13105 with max blocks 2048 with error -28
EXT4-fs (sda2): This should not happen!! Data will be lost

Occasionally (maybe 20% of the time), 015 will lead to a stall where the test
makes no further forward progress.  This happens at the end of the test when
a file used to consume available free space on the filesystem is deleted.
The rm is left in the D state, a flusher thread continues to run and
accumulate time, and I/O is continuously written to the storage device at a
slow rate.


2) This is all of the 219 failure output (also seen on x86-64):

--- 219.out	2013-02-01 12:46:06.672838718 -0500
+++ 219.out.bad	2013-02-07 12:36:14.734678000 -0500
@@ -16,7 +16,7 @@
   Size: 49152        Filetype: Regular File
   File: "SCRATCH_MNT/mmap"
   Size: 49152        Filetype: Regular File
-Usage OK (type=u)
+Too many blocks used (type=u)
 
 ### test group accounting
 
@@ -34,4 +34,4 @@
   Size: 49152        Filetype: Regular File
   File: "SCRATCH_MNT/mmap"
   Size: 49152        Filetype: Regular File
-Usage OK (type=g)
+Too many blocks used (type=g)


3) This is all of the 235 failure output (also seen on x86-64):

--- 235.out	2012-12-23 14:52:52.905205305 -0500
+++ 235.out.bad	2013-02-07 12:40:53.750303000 -0500
@@ -21,7 +21,7 @@
                         Block limits                File limits
 User            used    soft    hard  grace    used  soft  hard  grace
 ----------------------------------------------------------------------
-fsgqa     --       8       0       0              1     0     0       
+fsgqa     --      64       0       0              1     0     0       
 
 
 *** Report for group quotas on device SCRATCH_DEV
@@ -29,6 +29,6 @@
                         Block limits                File limits
 Group           used    soft    hard  grace    used  soft  hard  grace
 ----------------------------------------------------------------------
-fsgqa     --       8       0       0              1     0     0       
+fsgqa     --      64       0       0              1     0     0       


4) When 225 is run, one or more instances of the following warning will be
posted to the syslog (also on x86-64):

WARNING: at fs/ext4/inode.c:362 ext4_da_update_reserve_space+0x214/0x280()
Modules linked in:
[<c0016d18>] (unwind_backtrace+0x0/0x104) from [<c059e450>] (dump_stack+0x20/0x24)
[<c059e450>] (dump_stack+0x20/0x24) from [<c0037c68>] (warn_slowpath_common+0x5c/0x74)
[<c0037c68>] (warn_slowpath_common+0x5c/0x74) from [<c0037cac>] (warn_slowpath_null+0x2c/0x34)
[<c0037cac>] (warn_slowpath_null+0x2c/0x34) from [<c01af4f4>] (ext4_da_update_reserve_space+0x214/0x280)
[<c01af4f4>] (ext4_da_update_reserve_space+0x214/0x280) from [<c01dc928>] (ext4_ext_map_blocks+0xc10/0x153c)
[<c01dc928>] (ext4_ext_map_blocks+0xc10/0x153c) from [<c01af624>] (ext4_map_blocks+0xc4/0x230)
[<c01af624>] (ext4_map_blocks+0xc4/0x230) from [<c01b3c6c>] (mpage_da_map_and_submit+0xa0/0x598)
[<c01b3c6c>] (mpage_da_map_and_submit+0xa0/0x598) from [<c01b494c>] (ext4_da_writepages+0x2d8/0x564)
[<c01b494c>] (ext4_da_writepages+0x2d8/0x564) from [<c00e38cc>] (do_writepages+0x34/0x48)
[<c00e38cc>] (do_writepages+0x34/0x48) from [<c00d9b64>] (__filemap_fdatawrite_range+0x5c/0x64)
[<c00d9b64>] (__filemap_fdatawrite_range+0x5c/0x64) from [<c00d9ba4>] (filemap_fdatawrite+0x38/0x40)
[<c00d9ba4>] (filemap_fdatawrite+0x38/0x40) from [<c00d9bdc>] (filemap_write_and_wait+0x30/0x54)
[<c00d9bdc>] (filemap_write_and_wait+0x30/0x54) from [<c0128864>] (do_vfs_ioctl+0x498/0x5d8)
[<c0128864>] (do_vfs_ioctl+0x498/0x5d8) from [<c0128a18>] (sys_ioctl+0x74/0x94)
[<c0128a18>] (sys_ioctl+0x74/0x94) from [<c000e3c0>] (ret_fast_syscall+0x0/0x3c)



Here's the lockdep report for xfstest 113 run in the dioread_nolock scenario
as mentioned above (the taint is due to an unrelated warning from the clk
subsystem believed to be unique to 3.8 on Pandaboards/OMAP):

[ INFO: possible circular locking dependency detected ]
3.8.0-rc6 #1 Tainted: G        W   
-------------------------------------------------------
aio-stress/8597 is trying to acquire lock:
 (&mm->mmap_sem){++++++}, at: [<c00f1928>] get_user_pages_fast+0x48/0x88

but task is already holding lock:
 (&ei->i_data_sem){++++.+}, at: [<c01ae2a8>] ext4_direct_IO+0x3d4/0x450
 
which lock already depends on the new lock.
 
 
the existing dependency chain (in reverse order) is:
 
-> #1 (&ei->i_data_sem){++++.+}:
       [<c008c190>] __lock_acquire+0x162c/0x1b04
       [<c008cb70>] lock_acquire+0x9c/0x114
       [<c05a4f78>] down_read+0x40/0x50
       [<c01af6dc>] ext4_map_blocks+0x17c/0x230
       [<c01b1b6c>] _ext4_get_block+0x84/0x164
       [<c01b1d2c>] ext4_get_block+0x34/0x3c
       [<c0153bfc>] do_mpage_readpage+0x4d8/0x754
       [<c0153f50>] mpage_readpages+0xd8/0x134
       [<c01aedf4>] ext4_readpages+0x4c/0x54
       [<c00e3cbc>] __do_page_cache_readahead+0x1e8/0x2b0
       [<c00e408c>] ra_submit+0x38/0x40
       [<c00db0d4>] filemap_fault+0x3b4/0x490
       [<c00fb220>] __do_fault+0x78/0x4a8
       [<c00fe36c>] handle_pte_fault+0x80/0x6f8
       [<c00fea8c>] handle_mm_fault+0xa8/0xd8
       [<c05a91bc>] do_page_fault+0x294/0x3b4
       [<c05a9384>] do_translation_fault+0xa8/0xb0
       [<c00083f4>] do_DataAbort+0x44/0xa8
       [<c05a751c>] __dabt_svc+0x3c/0x60
       [<c02d17c0>] __clear_user_std+0x34/0x64
 
-> #0 (&mm->mmap_sem){++++++}:
       [<c059fa20>] print_circular_bug+0x78/0x2c8
       [<c008c59c>] __lock_acquire+0x1a38/0x1b04
       [<c008cb70>] lock_acquire+0x9c/0x114
       [<c05a4f78>] down_read+0x40/0x50
       [<c00f1928>] get_user_pages_fast+0x48/0x88
       [<c0151110>] __blockdev_direct_IO+0x1be4/0x3840
       [<c01ae1ac>] ext4_direct_IO+0x2d8/0x450
       [<c00d9db0>] generic_file_direct_write+0xf4/0x20c
       [<c00da23c>] __generic_file_aio_write+0x374/0x454
       [<c01aa49c>] ext4_file_write+0x2ac/0x4d0
       [<c015cf18>] aio_rw_vect_retry+0x78/0x1ac
       [<c015d858>] aio_run_iocb+0x64/0x14c
       [<c015ed10>] do_io_submit+0x574/0x8ec
       [<c015f0a4>] sys_io_submit+0x1c/0x20
       [<c000e3c0>] ret_fast_syscall+0x0/0x3c
 
other info that might help us debug this:
 
 Possible unsafe locking scenario:
 
       CPU0                    CPU1
       ----                    ----
  lock(&ei->i_data_sem);
                               lock(&mm->mmap_sem);
                               lock(&ei->i_data_sem);
  lock(&mm->mmap_sem);
 
 *** DEADLOCK ***
 
1 lock held by aio-stress/8597:
 #0:  (&ei->i_data_sem){++++.+}, at: [<c01ae2a8>] ext4_direct_IO+0x3d4/0x450
 
stack backtrace:
[<c0016d18>] (unwind_backtrace+0x0/0x104) from [<c059e450>] (dump_stack+0x20/0x24)
[<c059e450>] (dump_stack+0x20/0x24) from [<c059fc24>] (print_circular_bug+0x27c/0x2c8)
[<c059fc24>] (print_circular_bug+0x27c/0x2c8) from [<c008c59c>] (__lock_acquire+0x1a38/0x1b04)
[<c008c59c>] (__lock_acquire+0x1a38/0x1b04) from [<c008cb70>] (lock_acquire+0x9c/0x114)
[<c008cb70>] (lock_acquire+0x9c/0x114) from [<c05a4f78>] (down_read+0x40/0x50)
[<c05a4f78>] (down_read+0x40/0x50) from [<c00f1928>] (get_user_pages_fast+0x48/0x88)
[<c00f1928>] (get_user_pages_fast+0x48/0x88) from [<c0151110>] (__blockdev_direct_IO+0x1be4/0x3840)
[<c0151110>] (__blockdev_direct_IO+0x1be4/0x3840) from [<c01ae1ac>] (ext4_direct_IO+0x2d8/0x450)
[<c01ae1ac>] (ext4_direct_IO+0x2d8/0x450) from [<c00d9db0>] (generic_file_direct_write+0xf4/0x20c)
[<c00d9db0>] (generic_file_direct_write+0xf4/0x20c) from [<c00da23c>] (__generic_file_aio_write+0x374/0x454)
[<c00da23c>] (__generic_file_aio_write+0x374/0x454) from [<c01aa49c>] (ext4_file_write+0x2ac/0x4d0)
[<c01aa49c>] (ext4_file_write+0x2ac/0x4d0) from [<c015cf18>] (aio_rw_vect_retry+0x78/0x1ac)
[<c015cf18>] (aio_rw_vect_retry+0x78/0x1ac) from [<c015d858>] (aio_run_iocb+0x64/0x14c)
[<c015d858>] (aio_run_iocb+0x64/0x14c) from [<c015ed10>] (do_io_submit+0x574/0x8ec)
[<c015ed10>] (do_io_submit+0x574/0x8ec) from [<c015f0a4>] (sys_io_submit+0x1c/0x20)
[<c015f0a4>] (sys_io_submit+0x1c/0x20) from [<c000e3c0>] (ret_fast_syscall+0x0/0x3c)
--
To unsubscribe from this list: send the line "unsubscribe linux-ext4" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Powered by blists - more mailing lists