BUG at fs/buffer.c:2933 during umount

BUG at fs/buffer.c:2933 during umount

[Christian Kujau]

[-- Attachment #1: Type: TEXT/PLAIN, Size: 595 bytes --]

Hi,

I could not find this anywhere else reported, so here we go:
creating a new btrfs filesystem (btrfs-progs-unstable from git) and 
mounting it succeeds, unmounting however fails with the kernel messages 
attached to this mail. After that, I can still read and write to the 
btrfs mount, but e.g. /bin/sync never finishes, sysrq-s never reports 
"Sync complete".

I'm using a vanilla kernel, yesterday's git version 
and I *think* I remember having creating btrfs filesystems before (2.6.29, 
IIRC) and being able to umount them without problems. But I don't know for 
sure...yet.

Christian.

[-- Attachment #2: Type: TEXT/PLAIN, Size: 11809 bytes --]

# uptime
 21:03:57 up 0 min,  1 user,  load average: 0.11, 0.03, 0.01
# uname -a
Linux sid 2.6.30-rc4 #1 Tue May 5 11:07:42 CEST 2009 x86_64 GNU/Linux

# ls -l `which mkfs.btrfs`
-rwxr-xr-x 1 root root 540530 May  5 10:42 /opt/btrfs-progs/bin/mkfs.btrfs

# mkfs.btrfs /dev/xvdb

WARNING! - Btrfs Btrfs v0.18 IS EXPERIMENTAL
WARNING! - see http://btrfs.wiki.kernel.org before using

fs created label (null) on /dev/xvdb
	nodesize 4096 leafsize 4096 sectorsize 4096 size 2.00GB
Btrfs Btrfs v0.18


# mount -t btrfs /dev/xvdb /mnt/d1
# df -h /mnt/d1
Filesystem            Size  Used Avail Use% Mounted on
/dev/xvdb             2.0G   28K  2.0G   1% /mnt/d1
# grep xvdb /proc/mounts
/dev/xvdb /mnt/d1 btrfs rw,relatime 0 0
# ls -la /mnt/d1
total 16
dr-xr-xr-x 1 root root    0 Jan  1  1970 .
drwxr-xr-x 7 root root 4096 May  5 10:46 ..
# umount /mnt/d1
Segmentation fault

# dmesg
[    0.000000] Linux version 2.6.30-rc4 (dummy@sid) (gcc version 4.4.0 (Debian 4.4.0-1~exp2) ) #1 Tue May 5 11:07:42 CEST 2009
[    0.000000] Command line: root=/dev/xvda1 console=hvc0 init=/sbin/init
[    0.000000] KERNEL supported cpus:
[    0.000000]   Intel GenuineIntel
[    0.000000]   AMD AuthenticAMD
[    0.000000]   Centaur CentaurHauls
[    0.000000] BIOS-provided physical RAM map:
[    0.000000]  Xen: 0000000000000000 - 00000000000a0000 (usable)
[    0.000000]  Xen: 00000000000a0000 - 0000000000100000 (reserved)
[    0.000000]  Xen: 0000000000100000 - 0000000000580000 (usable)
[    0.000000]  Xen: 0000000000580000 - 0000000000683000 (reserved)
[    0.000000]  Xen: 0000000000683000 - 0000000020000000 (usable)
[    0.000000] DMI not present or invalid.
[    0.000000] last_pfn = 0x20000 max_arch_pfn = 0x100000000
[    0.000000] init_memory_mapping: 0000000000000000-0000000020000000
[    0.000000]  0000000000 - 0020000000 page 4k
[    0.000000] kernel direct mapping tables up to 20000000 @ 68a000-78c000
[    0.000000] (4 early reservations) ==> bootmem [0000000000 - 0020000000]
[    0.000000]   #0 [0000000000 - 0000001000]   BIOS data page ==> [0000000000 - 0000001000]
[    0.000000]   #1 [0000683000 - 000068a000]   XEN PAGETABLES ==> [0000683000 - 000068a000]
[    0.000000]   #2 [0000200000 - 000055f850]    TEXT DATA BSS ==> [0000200000 - 000055f850]
[    0.000000]   #3 [000068a000 - 0000782000]          PGTABLE ==> [000068a000 - 0000782000]
[    0.000000] Zone PFN ranges:
[    0.000000]   DMA      0x00000000 -> 0x00001000
[    0.000000]   DMA32    0x00001000 -> 0x00100000
[    0.000000]   Normal   0x00100000 -> 0x00100000
[    0.000000] Movable zone start PFN for each node
[    0.000000] early_node_map[3] active PFN ranges
[    0.000000]     0: 0x00000000 -> 0x000000a0
[    0.000000]     0: 0x00000100 -> 0x00000580
[    0.000000]     0: 0x00000683 -> 0x00020000
[    0.000000] On node 0 totalpages: 130717
[    0.000000]   DMA zone: 56 pages used for memmap
[    0.000000]   DMA zone: 1119 pages reserved
[    0.000000]   DMA zone: 2566 pages, LIFO batch:0
[    0.000000]   DMA32 zone: 1736 pages used for memmap
[    0.000000]   DMA32 zone: 125240 pages, LIFO batch:31
[    0.000000] trying to map vcpu_info 0 at ffffffff8047fae0, mfn ad3c8, offset 2784
[    0.000000] cpu 0 using vcpu_info at ffffffff8047fae0
[    0.000000] Xen: using vcpu_info placement
[    0.000000] No local APIC present
[    0.000000] nr_irqs_gsi: 16
[    0.000000] Allocating PCI resources starting at 30000000 (gap: 20000000:e0000000)
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 127806
[    0.000000] Kernel command line: root=/dev/xvda1 console=hvc0 init=/sbin/init
[    0.000000] Initializing CPU#0
[    0.000000] NR_IRQS:288
[    0.000000] PID hash table entries: 2048 (order: 11, 16384 bytes)
[    0.000000] Detected 1999.964 MHz processor.
[    0.010000] Console: colour dummy device 80x25
[    0.010000] console [tty0] enabled
[    0.010000] console [hvc0] enabled
[    0.010000] Dentry cache hash table entries: 65536 (order: 7, 524288 bytes)
[    0.010000] Inode-cache hash table entries: 32768 (order: 6, 262144 bytes)
[    0.010000] Checking aperture...
[    0.010000] No AGP bridge found
[    0.010000] Memory: 509684k/524288k available (1933k kernel code, 1420k absent, 12500k reserved, 874k data, 268k init)
[    0.010000] SLUB: Genslabs=13, HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.010000] Xen: using vcpuop timer interface
[    0.010000] installing Xen timer for CPU 0
[    0.010000] Calibrating delay loop (skipped), value calculated using timer frequency.. 3999.92 BogoMIPS (lpj=19999640)
[    0.010000] Mount-cache hash table entries: 256
[    0.010000] CPU: L1 I cache: 32K, L1 D cache: 32K
[    0.010000] CPU: L2 cache: 4096K
[    0.010000] CPU: Intel(R) Core(TM)2 CPU         T7200  @ 2.00GHz stepping 06
[    0.010000] Apic disabled by BIOS
[    0.010000] net_namespace: 544 bytes
[    0.010000] Booting paravirtualized kernel on Xen
[    0.010000] Xen version: 3.2.1-rc1-pre
[    0.010000] Grant table initialized
[    0.010000] NET: Registered protocol family 16
[    0.010000] PCI: Fatal: No config space access function found
[    0.010000] bio: create slab <bio-0> at 0
[    0.010000] xen_balloon: Initialising balloon driver.
[    0.010223] PCI: System does not support PCI
[    0.010235] PCI: System does not support PCI
[    0.010785] NET: Registered protocol family 2
[    0.010816] IP route cache hash table entries: 16384 (order: 5, 131072 bytes)
[    0.010918] TCP established hash table entries: 65536 (order: 8, 1048576 bytes)
[    0.011396] TCP bind hash table entries: 65536 (order: 7, 524288 bytes)
[    0.011662] TCP: Hash tables configured (established 65536 bind 65536)
[    0.011670] TCP reno registered
[    0.011724] NET: Registered protocol family 1
[    0.011967] platform rtc_cmos: registered platform RTC device (no PNP device found)
[    0.014860] VFS: Disk quotas dquot_6.5.2
[    0.014935] Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.015304] msgmni has been set to 1024
[    0.015407] alg: No test for stdrng (krng)
[    0.015426] io scheduler noop registered
[    0.015431] io scheduler anticipatory registered
[    0.015437] io scheduler deadline registered
[    0.015449] io scheduler cfq registered (default)
[    0.020012] Switched to high resolution mode on CPU 0
[    0.020432] rtc: I/O resource 70 is not free.
[    0.020438] Linux agpgart interface v0.103
[    0.162232] Initialising Xen virtual ethernet driver.
[    0.189082] blkfront: xvda: barriers enabled
[    0.189661]  xvda:<3>i8042.c: No controller found.
[    0.191359] mice: PS/2 mouse device common for all mice
[    0.191409] md: raid0 personality registered for level 0
[    0.191425] TCP cubic registered
[    0.191430] NET: Registered protocol family 17
[    0.278763]  xvda1 xvda2
[    0.286091] blkfront: xvdb: barriers enabled
[    0.286855]  xvdb: unknown partition table
[    0.384202] blkfront: xvdc: barriers enabled
[    0.384660]  xvdc: unknown partition table
[    0.490019] XENBUS: Device with no driver: device/console/0
[    0.490091] md: Waiting for all devices to be available before autodetect
[    0.490099] md: If you don't use raid, use raid=noautodetect
[    0.490260] md: Autodetecting RAID arrays.
[    0.490269] md: Scanned 0 and added 0 devices.
[    0.490274] md: autorun ...
[    0.490278] md: ... autorun DONE.
[    0.526103] kjournald starting.  Commit interval 5 seconds
[    0.527595] EXT3 FS on xvda1, internal journal
[    0.527609] EXT3-fs: mounted filesystem with writeback data mode.
[    0.527626] VFS: Mounted root (ext3 filesystem) on device 202:1.
[    0.527683] Freeing unused kernel memory: 268k freed
[    0.552690] Warning: unable to open an initial console.
[    3.063440] Adding 192772k swap on /dev/xvda2.  Priority:1 extents:1 across:192772k SS
[    3.342382] loop: module loaded
[    3.718318] fuse init (API version 7.11)
[    4.449990] RPC: Registered udp transport module.
[    4.450004] RPC: Registered tcp transport module.
[    4.548323] Slow work thread pool: Starting up
[    4.549707] Slow work thread pool: Ready
[    4.549772] FS-Cache: Loaded
[    4.596773] FS-Cache: Netfs 'nfs' registered for caching
[  115.470981] Btrfs loaded
[  115.486763] device fsid a0485aee66bb72a2-b75e6c0749ef9883 devid 1 transid 9 /dev/xvdb
[  152.576795] blkfront: xvdb: write barrier op failed
[  152.576810] blkfront: xvdb: barriers disabled
[  152.576815] end_request: I/O error, dev xvdb, sector 131072
[  152.576822] end_request: I/O error, dev xvdb, sector 131072
[  152.576846] ------------[ cut here ]------------
[  152.576852] kernel BUG at /data/Scratch/scm/linux-2.6-git/fs/buffer.c:2933!
[  152.576858] invalid opcode: 0000 [#1] 
[  152.576866] last sysfs file: /sys/devices/vbd-51728/block/xvdb/removable
[  152.576872] CPU 0 
[  152.576876] Modules linked in: btrfs zlib_deflate zlib_inflate nfs lockd fscache nfs_acl auth_rpcgss sunrpc fuse loop
[  152.576904] Pid: 1015, comm: umount Not tainted 2.6.30-rc4 #1 
[  152.576910] RIP: e030:[<ffffffff802a53a0>]  [<ffffffff802a53a0>] submit_bh+0x110/0x120
[  152.576923] RSP: e02b:ffff88001f8f7c78  EFLAGS: 00010246
[  152.576929] RAX: 0000000000002028 RBX: ffff88001f5d41c0 RCX: ffffffff8047fc28
[  152.576936] RDX: ffff88001f8f7c50 RSI: ffff88001f5d41c0 RDI: 0000000000000005
[  152.576945] RBP: 0000000000000005 R08: ffff88001f8f6000 R09: 0000000000000000
[  152.576952] R10: 0000000000000001 R11: 0000000000000001 R12: ffff88001f3e2c43
[  152.576959] R13: 0000000000000001 R14: ffff88001f5d41c0 R15: 0000000000000003
[  152.576970] FS:  00007fc5dca97740(0000) GS:ffffffff80486000(0000) knlGS:0000000000000000
[  152.576978] CS:  e033 DS: 0000 ES: 0000 CR0: 000000008005003b
[  152.576984] CR2: 00007fc5dc368258 CR3: 000000001e3df000 CR4: 0000000000002620
[  152.576992] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  152.577000] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[  152.577008] Process umount (pid: 1015, threadinfo ffff88001f8f6000, task ffff88001f8bbbd0)
[  152.577015] Stack:
[  152.577019]  ffff88001f2e2600 0000000000000001 ffff88001f3e2c43 ffffffffa00edb50
[  152.577031]  ffff88001f620178 0000001800000000 0000000100000000 ffff88001f3e2c63
[  152.577044]  00000001006e5928 ffff88001f3e2c44 0000000000000000 ffff88001f2e2600
[  152.577060] Call Trace:
[  152.577065]  [<ffffffffa00edb50>] ? write_dev_supers+0x2f0/0x3c0 [btrfs]
[  152.577089]  [<ffffffffa00eddf9>] ? write_all_supers+0x1d9/0x230 [btrfs]
[  152.577109]  [<ffffffffa00f1e37>] ? btrfs_commit_transaction+0x647/0x870 [btrfs]
[  152.577130]  [<ffffffff80240e70>] ? autoremove_wake_function+0x0/0x30
[  152.577141]  [<ffffffffa00d1a32>] ? btrfs_sync_fs+0x52/0x90 [btrfs]
[  152.577158]  [<ffffffff802c0c72>] ? quota_sync_sb+0x52/0x160
[  152.577168]  [<ffffffff802860f8>] ? __fsync_super+0x18/0x80
[  152.577177]  [<ffffffff80286169>] ? fsync_super+0x9/0x20
[  152.577185]  [<ffffffff80286461>] ? generic_shutdown_super+0x21/0x100
[  152.577195]  [<ffffffff80286599>] ? kill_anon_super+0x9/0x20
[  152.577204]  [<ffffffff80286633>] ? deactivate_super+0x63/0xa0
[  152.577212]  [<ffffffff8029b250>] ? sys_umount+0x70/0x3a0
[  152.577221]  [<ffffffff8020fcbf>] ? system_call_fastpath+0x16/0x1b
[  152.577231] Code: 05 00 41 0f b6 44 24 18 4c 89 e7 83 e0 80 3c 01 19 db e8 14 3c 00 00 f7 d3 83 e3 a1 89 d8 5b 5d 41 5c c3 0f 0b eb fe 0f 0b eb fe <0f> 0b eb fe 66 66 66 2e 0f 1f 84 00 00 00 00 00 53 83 fe a1 48 
[  152.577334] RIP  [<ffffffff802a53a0>] submit_bh+0x110/0x120
[  152.577343]  RSP <ffff88001f8f7c78>
[  152.577349] ---[ end trace 89172def5c4aa34d ]---
# logout

Re: BUG at fs/buffer.c:2933 during umount

[Chris Mason]

On Tue, 2009-05-05 at 12:23 -0700, Christian Kujau wrote:
> Hi,
> 
> I could not find this anywhere else reported, so here we go:
> creating a new btrfs filesystem (btrfs-progs-unstable from git) and 
> mounting it succeeds, unmounting however fails with the kernel messages 
> attached to this mail. After that, I can still read and write to the 
> btrfs mount, but e.g. /bin/sync never finishes, sysrq-s never reports 
> "Sync complete".
> 
> I'm using a vanilla kernel, yesterday's git version 
> and I *think* I remember having creating btrfs filesystems before (2.6.29, 
> IIRC) and being able to umount them without problems. But I don't know for 
> sure...yet.

Somehow xen is turning a barrier request into an IO error.  That's
really quite strange, but you can mount -o nobarrier.

-chris

Re: BUG at fs/buffer.c:2933 during umount

[Christian Kujau]

On Tue, 5 May 2009, Chris Mason wrote:
> Somehow xen is turning a barrier request into an IO error.  That's
> really quite strange, but you can mount -o nobarrier.

Thanks for the quick reply - yes, that helped. So, is that something I 
should report to the Xen folks? These "other filesystems" I can unmount 
with no BUG :-)


I just noted something else, but completely unrelated to that barrier 
stuff:

# ls -ld /mnt/d*
dr-xr-xr-x 1 root root    0 Jan  1  1970 /mnt/d1
drwxr-xr-x 3 root root 4096 May  5 21:45 /mnt/d2
# grep mnt/d /proc/mounts 
/dev/xvdb /mnt/d1 btrfs rw,relatime,nobarrier 0 0
/dev/xvdc /mnt/d2 ext3 rw,relatime,errors=continue,data=writeback 0 0

How comes btrfs thinks it has been created at the beginning of time?

Christian.
-- 
Strong cryptography does not exist for Bruce Schneier. There is only weak and
less weak cryptography.

Re: BUG at fs/buffer.c:2933 during umount

[Chris Mason]

On Tue, 2009-05-05 at 12:51 -0700, Christian Kujau wrote:
> On Tue, 5 May 2009, Chris Mason wrote:
> > Somehow xen is turning a barrier request into an IO error.  That's
> > really quite strange, but you can mount -o nobarrier.
> 
> Thanks for the quick reply - yes, that helped. So, is that something I 
> should report to the Xen folks? These "other filesystems" I can unmount 
> with no BUG :-)

For ext3, mount -o barrier=1 and you should see something exciting.  It
won't BUG because ext3 isn't as serious about telling the users about IO
problems as we are, but you should at least see messages.

> 
> 
> I just noted something else, but completely unrelated to that barrier 
> stuff:
> 
> # ls -ld /mnt/d*
> dr-xr-xr-x 1 root root    0 Jan  1  1970 /mnt/d1
> drwxr-xr-x 3 root root 4096 May  5 21:45 /mnt/d2
> # grep mnt/d /proc/mounts 
> /dev/xvdb /mnt/d1 btrfs rw,relatime,nobarrier 0 0
> /dev/xvdc /mnt/d2 ext3 rw,relatime,errors=continue,data=writeback 0 0
> 
> How comes btrfs thinks it has been created at the beginning of time?

The mkfs.btrfs command needs to properly set the date on the root
directory.  Sorry, I never noticed that one.

-chris

Re: BUG at fs/buffer.c:2933 during umount

[Christian Kujau]

On Tue, 5 May 2009, Chris Mason wrote:
> For ext3, mount -o barrier=1 and you should see something exciting.  It
> won't BUG because ext3 isn't as serious about telling the users about IO
> problems as we are, but you should at least see messages.

With that option, ext3 gives a waring, yes:

[ 1743.370971] JBD: barrier-based sync failed on xvdc - disabling barriers

Ext4 seems to enable barriers right away and when I actually write to the 
filesystem, it emits a warning indeed:

# umount /mnt/d2
[...]
[ 1409.043735] JBD: barrier-based sync failed on xvdc:8 - disabling barriers
[ 1413.700390] EXT4-fs: mballoc: 1531 blocks 46 reqs (24 success)
[ 1413.700406] EXT4-fs: mballoc: 23 extents scanned, 1 goal hits, 23 2^N hits, 0 breaks, 0 lost
[ 1413.700415] EXT4-fs: mballoc: 2 generated and it took 4884
[ 1413.700421] EXT4-fs: mballoc: 1212 preallocated, 690 discarded

I still find the BUG somehow...misleading. An error message seems to be 
more appropriate.

Christian.
-- 
The universe was created to serve as Bruce Schneier's crib text.