kernel BUG at fs/btrfs/ctree.c:2950

2012-11-01 Thread Darrick J. Wong
Hi,

I have a torture test[1] that I run to test stable page writeback.  When I run
it against a btrfs (3.7.0-rc3) I observe the kernel bug messsage[2] that I've
attached at the end of this message.  The test program spawns a bunch of
threads, which try to rewrite file blocks either through mmap or through
regular pwrite calls.

I'll take a look at it tomorrow, but I was wondering if this caught anybody's
eye...

# gcc -o wac wac.c
# mount /dev/path/to/a/btrfs /mnt
# ./wac -l 65536 -n 32 -m 32 -f -r /mnt/victimfile
wait a few seconds
kaboom

--D

[1] http://djwong.org/docs/wac.c
[2] Double stack-trace:
[ 9713.768350] [ cut here ]
[ 9713.773188] WARNING: at 
/storage/home/djwong/cdev/work/linux-spw/fs/btrfs/tree-log.c:3716 
btrfs_log_inode_parent+0x427/0x480 [btrfs]()
[ 9713.778876] Hardware name: Bochs
[ 9713.780877] Modules linked in: btrfs sd_mod scsi_debug ext4 mbcache jbd2 
scsi_mod sch_fq_codel nfsv4 eeprom nfsd auth_rpcgss exportfs af_packet raid1 
raid0 md_mod zlib_deflate libcrc32c [last unloaded: sd_mod]
[ 9713.786778] Pid: 1992, comm: wac Not tainted 3.7.0-rc3-spw #42
[ 9713.789183] Call Trace:
[ 9713.791102]  [8105210f] warn_slowpath_common+0x7f/0xc0
[ 9713.793428]  [8105216a] warn_slowpath_null+0x1a/0x20
[ 9713.795826]  [a030ad57] btrfs_log_inode_parent+0x427/0x480 [btrfs]
[ 9713.798310]  [8117c97c] ? dget_parent+0x1c/0xe0
[ 9713.800653]  [a030adf6] btrfs_log_dentry_safe+0x46/0x70 [btrfs]
[ 9713.803149]  [a02e21c6] btrfs_sync_file+0x1a6/0x240 [btrfs]
[ 9713.805626]  [81550f49] ? sysret_check+0x22/0x5d
[ 9713.807861]  [8119705d] do_fsync+0x5d/0x90
[ 9713.810077]  [812595ae] ? trace_hardirqs_on_thunk+0x3a/0x3f
[ 9713.812642]  [81197460] sys_fsync+0x10/0x20
[ 9713.814793]  [81550f1d] system_call_fastpath+0x1a/0x1f
[ 9713.817178] ---[ end trace 47f6b9aede5fa6f5 ]---
[ 9715.884354] [ cut here ]
[ 9715.888197] kernel BUG at 
/storage/home/djwong/cdev/work/linux-spw/fs/btrfs/ctree.c:2950!
[ 9715.888197] invalid opcode:  [#1] PREEMPT SMP 
[ 9715.888197] Modules linked in: btrfs sd_mod scsi_debug ext4 mbcache jbd2 
scsi_mod sch_fq_codel nfsv4 eeprom nfsd auth_rpcgss exportfs af_packet raid1 
raid0 md_mod zlib_deflate libcrc32c [last unloaded: sd_mod]
[ 9715.888197] CPU 0 
[ 9715.888197] Pid: 1990, comm: wac Tainted: GW3.7.0-rc3-spw #42 
Bochs Bochs
[ 9715.888197] RIP: 0010:[a02af5b9]  [a02af5b9] 
btrfs_set_item_key_safe+0x149/0x150 [btrfs]
[ 9715.888197] RSP: 0018:880028735ae8  EFLAGS: 00010246
[ 9715.888197] RAX:  RBX: 000f RCX: e000
[ 9715.888197] RDX:  RSI: 880028735c16 RDI: 880028735ac7
[ 9715.888197] RBP: 880028735b48 R08: 0c9e R09: 880028735b08
[ 9715.888197] R10:  R11:  R12: 880016b62bf0
[ 9715.888197] R13: 880028735c16 R14: 880028735b07 R15: 8800293edbd0
[ 9715.888197] FS:  7f3ffa3b3700() GS:88003fc0() 
knlGS:
[ 9715.888197] CS:  0010 DS:  ES:  CR0: 8005003b
[ 9715.888197] CR2: 7f3ffa3b0fba CR3: 2872d000 CR4: 07f0
[ 9715.888197] DR0:  DR1:  DR2: 
[ 9715.888197] DR3:  DR6: 0ff0 DR7: 0400
[ 9715.888197] Process wac (pid: 1990, threadinfo 880028734000, task 
88002870de50)
[ 9715.888197] Stack:
[ 9715.888197]  880028735b48 88002f678000 8800131c2000 
0100
[ 9715.888197]  6c01 e000 880028735b48 
8800293edbd0
[ 9715.888197]  880016b62bf0 d000 0001 

[ 9715.888197] Call Trace:
[ 9715.888197]  [a02e46e7] __btrfs_drop_extents+0x557/0xb00 [btrfs]
[ 9715.888197]  [a0306fdd] btrfs_log_changed_extents+0x5bd/0x610 
[btrfs]
[ 9715.888197]  [a02efff7] ? free_extent_buffer+0x37/0x90 [btrfs]
[ 9715.888197]  [a0308efb] btrfs_log_inode+0x50b/0x5b0 [btrfs]
[ 9715.888197]  [8117c9b8] ? dget_parent+0x58/0xe0
[ 9715.888197]  [a030aac2] btrfs_log_inode_parent+0x192/0x480 [btrfs]
[ 9715.888197]  [8117c97c] ? dget_parent+0x1c/0xe0
[ 9715.888197]  [a030adf6] btrfs_log_dentry_safe+0x46/0x70 [btrfs]
[ 9715.888197]  [a02e21c6] btrfs_sync_file+0x1a6/0x240 [btrfs]
[ 9715.888197]  [81550f49] ? sysret_check+0x22/0x5d
[ 9715.888197]  [8119705d] do_fsync+0x5d/0x90
[ 9715.888197]  [812595ae] ? trace_hardirqs_on_thunk+0x3a/0x3f
[ 9715.888197]  [81197460] sys_fsync+0x10/0x20
[ 9715.888197]  [81550f1d] system_call_fastpath+0x1a/0x1f
[ 9715.888197] Code: 00 00 4c 89 f6 4c 89 e7 48 98 48 8d 04 80 48 8d 54 80 65 
e8 aa 1b 04 00 4c 89 ee 4c 89 f7 e8 2f f2 ff ff 85 c0 0f 8f 57 ff ff ff 0f 0b 
0f 0b 0f 1f 00 66 66 66 66 90 55 48 b8 00 00 00 00 00 16 
[ 9715.888197] 

Re: kernel BUG at fs/btrfs/ctree.c:2950

2012-11-01 Thread Miao Xie
On thu, 1 Nov 2012 00:04:13 -0700, Darrick J. Wong wrote:
 Hi,
 
 I have a torture test[1] that I run to test stable page writeback.  When I run
 it against a btrfs (3.7.0-rc3) I observe the kernel bug messsage[2] that I've
 attached at the end of this message.  The test program spawns a bunch of
 threads, which try to rewrite file blocks either through mmap or through
 regular pwrite calls.
 
 I'll take a look at it tomorrow, but I was wondering if this caught anybody's
 eye...

I'm looking into the following problem now, it seems that the file extent 
metadata
is modified when we do logging.

Thanks
Miao

 
 # gcc -o wac wac.c
 # mount /dev/path/to/a/btrfs /mnt
 # ./wac -l 65536 -n 32 -m 32 -f -r /mnt/victimfile
 wait a few seconds
 kaboom
 
 --D
 
 [1] http://djwong.org/docs/wac.c
 [2] Double stack-trace:
 [ 9713.768350] [ cut here ]
 [ 9713.773188] WARNING: at 
 /storage/home/djwong/cdev/work/linux-spw/fs/btrfs/tree-log.c:3716 
 btrfs_log_inode_parent+0x427/0x480 [btrfs]()
 [ 9713.778876] Hardware name: Bochs
 [ 9713.780877] Modules linked in: btrfs sd_mod scsi_debug ext4 mbcache jbd2 
 scsi_mod sch_fq_codel nfsv4 eeprom nfsd auth_rpcgss exportfs af_packet raid1 
 raid0 md_mod zlib_deflate libcrc32c [last unloaded: sd_mod]
 [ 9713.786778] Pid: 1992, comm: wac Not tainted 3.7.0-rc3-spw #42
 [ 9713.789183] Call Trace:
 [ 9713.791102]  [8105210f] warn_slowpath_common+0x7f/0xc0
 [ 9713.793428]  [8105216a] warn_slowpath_null+0x1a/0x20
 [ 9713.795826]  [a030ad57] btrfs_log_inode_parent+0x427/0x480 
 [btrfs]
 [ 9713.798310]  [8117c97c] ? dget_parent+0x1c/0xe0
 [ 9713.800653]  [a030adf6] btrfs_log_dentry_safe+0x46/0x70 [btrfs]
 [ 9713.803149]  [a02e21c6] btrfs_sync_file+0x1a6/0x240 [btrfs]
 [ 9713.805626]  [81550f49] ? sysret_check+0x22/0x5d
 [ 9713.807861]  [8119705d] do_fsync+0x5d/0x90
 [ 9713.810077]  [812595ae] ? trace_hardirqs_on_thunk+0x3a/0x3f
 [ 9713.812642]  [81197460] sys_fsync+0x10/0x20
 [ 9713.814793]  [81550f1d] system_call_fastpath+0x1a/0x1f
 [ 9713.817178] ---[ end trace 47f6b9aede5fa6f5 ]---
 [ 9715.884354] [ cut here ]
 [ 9715.888197] kernel BUG at 
 /storage/home/djwong/cdev/work/linux-spw/fs/btrfs/ctree.c:2950!
 [ 9715.888197] invalid opcode:  [#1] PREEMPT SMP 
 [ 9715.888197] Modules linked in: btrfs sd_mod scsi_debug ext4 mbcache jbd2 
 scsi_mod sch_fq_codel nfsv4 eeprom nfsd auth_rpcgss exportfs af_packet raid1 
 raid0 md_mod zlib_deflate libcrc32c [last unloaded: sd_mod]
 [ 9715.888197] CPU 0 
 [ 9715.888197] Pid: 1990, comm: wac Tainted: GW3.7.0-rc3-spw #42 
 Bochs Bochs
 [ 9715.888197] RIP: 0010:[a02af5b9]  [a02af5b9] 
 btrfs_set_item_key_safe+0x149/0x150 [btrfs]
 [ 9715.888197] RSP: 0018:880028735ae8  EFLAGS: 00010246
 [ 9715.888197] RAX:  RBX: 000f RCX: 
 e000
 [ 9715.888197] RDX:  RSI: 880028735c16 RDI: 
 880028735ac7
 [ 9715.888197] RBP: 880028735b48 R08: 0c9e R09: 
 880028735b08
 [ 9715.888197] R10:  R11:  R12: 
 880016b62bf0
 [ 9715.888197] R13: 880028735c16 R14: 880028735b07 R15: 
 8800293edbd0
 [ 9715.888197] FS:  7f3ffa3b3700() GS:88003fc0() 
 knlGS:
 [ 9715.888197] CS:  0010 DS:  ES:  CR0: 8005003b
 [ 9715.888197] CR2: 7f3ffa3b0fba CR3: 2872d000 CR4: 
 07f0
 [ 9715.888197] DR0:  DR1:  DR2: 
 
 [ 9715.888197] DR3:  DR6: 0ff0 DR7: 
 0400
 [ 9715.888197] Process wac (pid: 1990, threadinfo 880028734000, task 
 88002870de50)
 [ 9715.888197] Stack:
 [ 9715.888197]  880028735b48 88002f678000 8800131c2000 
 0100
 [ 9715.888197]  6c01 e000 880028735b48 
 8800293edbd0
 [ 9715.888197]  880016b62bf0 d000 0001 
 
 [ 9715.888197] Call Trace:
 [ 9715.888197]  [a02e46e7] __btrfs_drop_extents+0x557/0xb00 [btrfs]
 [ 9715.888197]  [a0306fdd] btrfs_log_changed_extents+0x5bd/0x610 
 [btrfs]
 [ 9715.888197]  [a02efff7] ? free_extent_buffer+0x37/0x90 [btrfs]
 [ 9715.888197]  [a0308efb] btrfs_log_inode+0x50b/0x5b0 [btrfs]
 [ 9715.888197]  [8117c9b8] ? dget_parent+0x58/0xe0
 [ 9715.888197]  [a030aac2] btrfs_log_inode_parent+0x192/0x480 
 [btrfs]
 [ 9715.888197]  [8117c97c] ? dget_parent+0x1c/0xe0
 [ 9715.888197]  [a030adf6] btrfs_log_dentry_safe+0x46/0x70 [btrfs]
 [ 9715.888197]  [a02e21c6] btrfs_sync_file+0x1a6/0x240 [btrfs]
 [ 9715.888197]  [81550f49] ? sysret_check+0x22/0x5d
 [ 9715.888197]  [8119705d] do_fsync+0x5d/0x90
 [ 9715.888197]  [812595ae] ? trace_hardirqs_on_thunk+0x3a/0x3f
 [ 9715.888197]  [81197460]