Linux Arch: kernel BUG at fs/btrfs/inode.c:873!

Linux Arch: kernel BUG at fs/btrfs/inode.c:873!

[Anatol Pomozov]

Hi,

I have a home server on Linux Arch (kernel 3.11.2) that uses
multi-device btrfs on root filesystem.

Until recently it worked completely fine. And yesterday I rebooted it
and the machine did not wake up.

I booted from a USB (kernel 3.10) and tried to mount the filesystem.
Here is OOPs I see

[   41.676217] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
8 transid 164237 /dev/sda
[   41.684161] btrfs: disk space caching is enabled
[   67.266742] BTRFS error (device sdd3): block group 1141416919040
has wrong amount of free space
[   67.266796] BTRFS error (device sdd3): failed to load free space
cache for block group 1141416919040
[   68.126102] ------------[ cut here ]------------
[   68.126138] kernel BUG at fs/btrfs/inode.c:873!
[   68.126164] invalid opcode: 0000 [#1] PREEMPT SMP
[   68.126203] Modules linked in: intel_powerclamp coretemp kvm_intel
kvm crc32_pclmul ghash_clmulni_intel cryptd iTCO_wdt
iTCO_vendor_support ppdev microcode snd_hda_codec_hdmi psmouse
snd_hda_codec_realtek serio_raw i2c_i801 snd_hda_intel pcspkr
snd_hda_codec lpc_ich snd_hwdep parport_pc parport snd_pcm mperf
snd_page_alloc snd_timer snd mei_me soundcore evdev mei processor nfs
lockd sunrpc fscache ext4 crc16 mbcache jbd2 dm_snapshot dm_mod
squashfs loop isofs btrfs raid6_pq libcrc32c zlib_deflate xor
hid_generic usbhid hid usb_storage sd_mod i915 intel_agp intel_gtt
ahci libahci crc32c_intel i2c_algo_bit xhci_hcd libata ehci_pci
ehci_hcd scsi_mod atl1c drm_kms_helper usbcore usb_common drm i2c_core
button video
[   68.126754] CPU: 1 PID: 386 Comm: mount Not tainted 3.10.10-1-ARCH #1
[   68.126787] Hardware name: To Be Filled By O.E.M. To Be Filled By
O.E.M./H61M/U3S3, BIOS P2.20 07/30/2012
[   68.126834] task: ffff880118869950 ti: ffff88011377e000 task.ti:
ffff88011377e000
[   68.126871] RIP: 0010:[<ffffffffa0471223>]  [<ffffffffa0471223>]
__cow_file_range+0x3e3/0x460 [btrfs]
[   68.126933] RSP: 0018:ffff88011377f328  EFLAGS: 00010206
[   68.126961] RAX: 00000000000004d2 RBX: 0000000000000000 RCX: 0000000000001000
[   68.126996] RDX: 00000000000004d2 RSI: ffff88001f438608 RDI: ffff880115eb3000
[   68.127032] RBP: ffff88011377f3c8 R08: 0000000000000000 R09: 000000000003ffff
[   68.127068] R10: 0000000000040000 R11: 0000000000000000 R12: 0000000000000000
[   68.127103] R13: ffff880115f88630 R14: ffff88001f438608 R15: 0000000000000000
[   68.127140] FS:  00007fac17768780(0000) GS:ffff88011f300000(0000)
knlGS:0000000000000000
[   68.127180] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   68.127209] CR2: 00007f518d994000 CR3: 0000000117ab4000 CR4: 00000000000407e0
[   68.127246] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[   68.127281] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[   68.127317] Stack:
[   68.127331]  00000109ffe26000 ffff880115f88c60 ffff88001f438428
000000000003ffff
[   68.127381]  ffff88011700c010 ffffea0003231b40 ffff880115eb3000
f600000109ffd870
[   68.127430]  ffffffffa0482f29 ffff880118a31000 ffff880115f88638
ffff88001f438448
[   68.127480] Call Trace:
[   68.127508]  [<ffffffffa0482f29>] ? release_extent_buffer+0xa9/0xd0 [btrfs]
[   68.127553]  [<ffffffffa048862f>] ? free_extent_buffer+0x4f/0xa0 [btrfs]
[   68.127598]  [<ffffffffa04716d6>] run_delalloc_nocow+0x436/0xaf0 [btrfs]
[   68.127641]  [<ffffffffa0472180>] run_delalloc_range+0x320/0x390 [btrfs]
[   68.127685]  [<ffffffffa04854c1>] ?
find_lock_delalloc_range.constprop.44+0x1d1/0x1f0 [btrfs]
[   68.127735]  [<ffffffffa0487044>] __extent_writepage+0x354/0x7b0 [btrfs]
[   68.127772]  [<ffffffff81122645>] ? find_get_pages_tag+0x105/0x180
[   68.127813]  [<ffffffffa0487722>]
extent_write_cache_pages.isra.32.constprop.48+0x282/0x3e0 [btrfs]
[   68.127867]  [<ffffffffa0487b7d>] extent_writepages+0x4d/0x70 [btrfs]
[   68.127909]  [<ffffffffa046e080>] ? can_nocow_odirect+0x2f0/0x2f0 [btrfs]
[   68.127951]  [<ffffffffa046cf28>] btrfs_writepages+0x28/0x30 [btrfs]
[   68.127985]  [<ffffffff8112e28e>] do_writepages+0x1e/0x40
[   68.128014]  [<ffffffff81123669>] __filemap_fdatawrite_range+0x59/0x60
[   68.128048]  [<ffffffff81123733>] filemap_fdatawrite_range+0x13/0x20
[   68.128090]  [<ffffffffa0481c99>] btrfs_wait_ordered_range+0x49/0x110 [btrfs]
[   68.128135]  [<ffffffffa04a64c0>] __btrfs_write_out_cache+0x6d0/0x8f0 [btrfs]
[   68.128180]  [<ffffffffa04a774d>] btrfs_write_out_cache+0x8d/0xe0 [btrfs]
[   68.128224]  [<ffffffffa0459983>]
btrfs_write_dirty_block_groups+0x533/0x620 [btrfs]
[   68.128271]  [<ffffffffa04676e2>] commit_cowonly_roots+0x172/0x260 [btrfs]
[   68.128314]  [<ffffffffa04695ad>]
btrfs_commit_transaction+0x5bd/0xaf0 [btrfs]
[   68.128353]  [<ffffffff8107b460>] ? wake_up_bit+0x30/0x30
[   68.128391]  [<ffffffffa04a4edd>] btrfs_recover_log_trees+0x3bd/0x490 [btrfs]
[   68.128434]  [<ffffffffa04a3270>] ? replay_one_dir_item+0xf0/0xf0 [btrfs]
[   68.128477]  [<ffffffffa0466689>] open_ctree+0x17b9/0x1e80 [btrfs]
[   68.128513]  [<ffffffff813555d3>] ? proc_comm_connector+0x33/0x120
[   68.128551]  [<ffffffffa043f456>] btrfs_mount+0x636/0x830 [btrfs]
[   68.128584]  [<ffffffff81141cd2>] ? pcpu_alloc+0x7d2/0x9e0
[   68.128616]  [<ffffffff8118f5d9>] mount_fs+0x39/0x1b0
[   68.128643]  [<ffffffff81141ef0>] ? __alloc_percpu+0x10/0x20
[   68.128676]  [<ffffffff811a8c27>] vfs_kern_mount+0x67/0x100
[   68.128706]  [<ffffffff811ab24e>] do_mount+0x23e/0xa20
[   68.128737]  [<ffffffff8113d73b>] ? strndup_user+0x4b/0xf0
[   68.128766]  [<ffffffff811abab3>] SyS_mount+0x83/0xc0
[   68.128795]  [<ffffffff814cfe1d>] system_call_fastpath+0x1a/0x1f
[   68.128826] Code: 8b 7d 90 4c 89 f6 e8 ad 9e 00 00 e9 dc fc ff ff
48 85 d2 74 40 80 be 30 fe ff ff 84 48 89 d0 74 34 48 83 f8 01 0f 84
87 fc ff ff <0f> 0b 48 8b 75 a8 48 8b 7d 90 41 89 c0 b9 9b 03 00 00 48
c7 c2
[   68.129145] RIP  [<ffffffffa0471223>] __cow_file_range+0x3e3/0x460 [btrfs]
[   68.129192]  RSP <ffff88011377f328>
[   68.129230] ---[ end trace 7992880786c40076 ]---



Hm.... it looks like it crashed when it tries to restore logs. Ok, I
ran 'btrfschk /dev/sda' and here is its output:

[  181.281546] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
8 transid 164237 /dev/sda
[  181.318148] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
3 transid 164237 /dev/sdb
[  181.408490] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
2 transid 164237 /dev/sdc1
[  181.763300] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
9 transid 164237 /dev/sdd3
[  181.782414] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
8 transid 164237 /dev/sda
[  181.784634] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
3 transid 164237 /dev/sdb
[  181.788715] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
2 transid 164237 /dev/sdc1
[  181.803161] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
9 transid 164237 /dev/sdd3
[  337.445525] systemd-journald[160]: Failed to write entry, ignoring:
Argument list too long


Then I tried to mount the filesystem again and it stuck. I see several
processes in UNINTERRUPTIBLE state:

[  828.034908] SysRq : Show Blocked State
[  828.036150]   task                        PC stack   pid father
[  828.037418] btrfs-transacti D ffff880118a311e8     0   407      2 0x00000000
[  828.038709]  ffff880115051dc8 0000000000000046 0000000000014340
ffff880115051fd8
[  828.040030]  ffff880115051fd8 0000000000014340 ffff88011886f620
ffff88011886f620
[  828.041364]  000000000000082f ffff880115051d30 ffffffff8109d141
ffff880118868048
[  828.042724] Call Trace:
[  828.044071]  [<ffffffff8109d141>] ? cpuacct_charge+0x61/0x70
[  828.045445]  [<ffffffff8108dd88>] ? __enqueue_entity+0x78/0x80
[  828.046829]  [<ffffffff810920f6>] ? enqueue_entity+0x286/0xa20
[  828.048227]  [<ffffffff81065bbb>] ? lock_timer_base.isra.35+0x2b/0x50
[  828.049648]  [<ffffffff814c6f09>] schedule+0x29/0x70
[  828.051076]  [<ffffffffa0468695>]
wait_current_trans.isra.14+0xa5/0xf0 [btrfs]
[  828.052515]  [<ffffffff8107b460>] ? wake_up_bit+0x30/0x30
[  828.053970]  [<ffffffffa0469e18>] start_transaction+0x338/0x530 [btrfs]
[  828.055453]  [<ffffffffa046a0c7>] btrfs_attach_transaction+0x17/0x20 [btrfs]
[  828.056943]  [<ffffffffa0460ca1>] transaction_kthread+0x141/0x230 [btrfs]
[  828.058455]  [<ffffffffa0460b60>] ? free_fs_root+0x90/0x90 [btrfs]
[  828.059989]  [<ffffffff8107a670>] kthread+0xc0/0xd0
[  828.061508]  [<ffffffff8107a5b0>] ? kthread_create_on_node+0x120/0x120
[  828.063036]  [<ffffffff814cfd6c>] ret_from_fork+0x7c/0xb0
[  828.064568]  [<ffffffff8107a5b0>] ? kthread_create_on_node+0x120/0x120
[  828.066109] mount           D ffff880118a31878     0   427    343 0x00000000
[  828.067680]  ffff880117bdbc18 0000000000000086 0000000000014340
ffff880117bdbfd8
[  828.069278]  ffff880117bdbfd8 0000000000014340 ffff880118facbf0
ffff8801169cb800
[  828.070869]  ffff88011f214340 ffffffff81085aa9 ffff8801169cb800
ffff88011f214340
[  828.072430] Call Trace:
[  828.073966]  [<ffffffff81085aa9>] ? finish_task_switch+0x49/0xe0
[  828.075524]  [<ffffffff814c6996>] ? __schedule+0x3f6/0x940
[  828.077093]  [<ffffffff81071194>] ? wake_up_worker+0x24/0x30
[  828.078671]  [<ffffffff814c5a34>] ? __mutex_lock_slowpath+0x284/0x3b0
[  828.080275]  [<ffffffff814c6f09>] schedule+0x29/0x70
[  828.081867]  [<ffffffff814c7d95>] rwsem_down_write_failed+0xf5/0x1c3
[  828.083473]  [<ffffffffa043a000>] ? 0xffffffffa0439fff
[  828.085083]  [<ffffffff81279e33>] call_rwsem_down_write_failed+0x13/0x20
[  828.086717]  [<ffffffff814c5ec4>] ? down_write+0x24/0x26
[  828.088366]  [<ffffffff8118dffe>] grab_super+0x2e/0xa0
[  828.090021]  [<ffffffff8118e6f0>] sget+0x320/0x580
[  828.091677]  [<ffffffffa043e130>] ?
btrfs_parse_early_options+0x190/0x190 [btrfs]
[  828.093368]  [<ffffffff814c57ae>] ? mutex_unlock+0xe/0x10
[  828.095068]  [<ffffffffa043f228>] btrfs_mount+0x408/0x830 [btrfs]
[  828.096786]  [<ffffffff81141cd2>] ? pcpu_alloc+0x7d2/0x9e0
[  828.098516]  [<ffffffff8118f5d9>] mount_fs+0x39/0x1b0
[  828.100267]  [<ffffffff81141ef0>] ? __alloc_percpu+0x10/0x20
[  828.102017]  [<ffffffff811a8c27>] vfs_kern_mount+0x67/0x100
[  828.103775]  [<ffffffff811ab24e>] do_mount+0x23e/0xa20
[  828.105547]  [<ffffffff8113d73b>] ? strndup_user+0x4b/0xf0
[  828.107312]  [<ffffffff811abab3>] SyS_mount+0x83/0xc0
[  828.109096]  [<ffffffff814cfe1d>] system_call_fastpath+0x1a/0x1f

The only thing that I did recently is defrag /var/log/journal files
(journalctl is very slow because of btrfs COW). Something like this
http://www.mail-archive.com/linux-btrfs@vger.kernel.org/msg24878.html

How to fix this problem? And restore the data...

Re: Linux Arch: kernel BUG at fs/btrfs/inode.c:873!

[Duncan]

Anatol Pomozov posted on Fri, 04 Oct 2013 21:03:11 -0700 as excerpted:

> Hi,
> 
> I have a home server on Linux Arch (kernel 3.11.2) that uses
> multi-device btrfs on root filesystem.
> 
> Until recently it worked completely fine. And yesterday I rebooted it
> and the machine did not wake up.
> 
> I booted from a USB (kernel 3.10) and tried to mount the filesystem.
> Here is OOPs I see

> ------------[ cut here ]------------
> [   68.126138] kernel BUG at fs/btrfs/inode.c:873!
> [   68.126164] invalid opcode: 0000 [#1] PREEMPT SMP

> The only thing that I did recently is defrag /var/log/journal files
> (journalctl is very slow because of btrfs COW). Something like this
> http://www.mail-archive.com/linux-btrfs@vger.kernel.org/msg24878.html
> 
> How to fix this problem? And restore the data...

I'm not a dev just a btrfs user and list regular myself, so the traces 
don't mean much to me.  However, the bit I retained in the quote above 
(especially the 0000 opcode) looks very much like a bug that should be 
fixed in kernel 3.12, with the patch queued for stable as well, but due 
to a mixup it didn't get into stable thru 3.11.4, but the mixup's 
hopefully straightened out now so with luck it'll be in 3.11.5.

So the first thing I'd try is either cherrypicking the btrfs patches from 
3.12 back to 3.11-stable, or wait for 3.11.5 and check for btrfs patches 
there, or try 3.12-rcX (rc3 is out and I guess rc4 should be out shortly 
now as I think it has been nearly a week).

With luck that'll fix it.  If not, then post back with the new kernel you 
tried and hopefully one of the devs can help.

-- 
Duncan - List replies preferred.   No HTML msgs.
"Every nonfree program has a lord, a master --
and if you use the program, he is your master."  Richard Stallman

Re: Linux Arch: kernel BUG at fs/btrfs/inode.c:873!

[Anatol Pomozov]

Hi

On Fri, Oct 4, 2013 at 9:42 PM, Duncan <1i5t5.duncan@cox.net> wrote:
> Anatol Pomozov posted on Fri, 04 Oct 2013 21:03:11 -0700 as excerpted:
>
>> Hi,
>>
>> I have a home server on Linux Arch (kernel 3.11.2) that uses
>> multi-device btrfs on root filesystem.
>>
>> Until recently it worked completely fine. And yesterday I rebooted it
>> and the machine did not wake up.
>>
>> I booted from a USB (kernel 3.10) and tried to mount the filesystem.
>> Here is OOPs I see
>
>> ------------[ cut here ]------------
>> [   68.126138] kernel BUG at fs/btrfs/inode.c:873!
>> [   68.126164] invalid opcode: 0000 [#1] PREEMPT SMP
>
>> The only thing that I did recently is defrag /var/log/journal files
>> (journalctl is very slow because of btrfs COW). Something like this
>> http://www.mail-archive.com/linux-btrfs@vger.kernel.org/msg24878.html
>>
>> How to fix this problem? And restore the data...
>
> I'm not a dev just a btrfs user and list regular myself, so the traces
> don't mean much to me.  However, the bit I retained in the quote above
> (especially the 0000 opcode) looks very much like a bug that should be
> fixed in kernel 3.12, with the patch queued for stable as well, but due
> to a mixup it didn't get into stable thru 3.11.4, but the mixup's
> hopefully straightened out now so with luck it'll be in 3.11.5.
>
> So the first thing I'd try is either cherrypicking the btrfs patches from
> 3.12 back to 3.11-stable, or wait for 3.11.5 and check for btrfs patches
> there, or try 3.12-rcX (rc3 is out and I guess rc4 should be out shortly
> now as I think it has been nearly a week).

Could you please give me the patch SHA1 you are talking about?

>
> With luck that'll fix it.  If not, then post back with the new kernel you
> tried and hopefully one of the devs can help.

Re: Linux Arch: kernel BUG at fs/btrfs/inode.c:873!

[Duncan]

Anatol Pomozov posted on Sat, 05 Oct 2013 04:51:52 -0700 as excerpted:

> Hi
> 
> On Fri, Oct 4, 2013 at 9:42 PM, Duncan <1i5t5.duncan@cox.net> wrote:
>> Anatol Pomozov posted on Fri, 04 Oct 2013 21:03:11 -0700 as excerpted:
>>
>>> Hi,
>>>
>>> I have a home server on Linux Arch (kernel 3.11.2) that uses
>>> multi-device btrfs on root filesystem.
>>>
>>> Until recently it worked completely fine. And yesterday I rebooted it
>>> and the machine did not wake up.
>>>
>>> I booted from a USB (kernel 3.10) and tried to mount the filesystem.
>>> Here is OOPs I see
>>
>>> ------------[ cut here ]------------
>>> [   68.126138] kernel BUG at fs/btrfs/inode.c:873!
>>> [   68.126164] invalid opcode: 0000 [#1] PREEMPT SMP
>>
>>> The only thing that I did recently is defrag /var/log/journal files
>>> (journalctl is very slow because of btrfs COW). Something like this
>>> http://www.mail-archive.com/linux-btrfs@vger.kernel.org/msg24878.html

I forgot I was going to mention this in the previous reply...

You can try setting the NOCOW attribute for that file or directory.  
There's instructions on the wiki (btrfs.wiki.kernel.org).  Virtual 
machine images also often work better with NOCOW.

Meanwhile, thinking about systemd journal files there's also another 
patch that is too new to be in the mainline kernel, I think.  That bug 
was found on systemd journal files specifically, because systemd was 
allocating and then writing into them and btrfs wasn't doing the right 
thing with that.  There's a current thread about it.  Since I don't use 
systemd, however, I've not followed it that closely.

>> I'm not a dev just a btrfs user and list regular myself, so the traces
>> don't mean much to me.  However, the bit I retained in the quote above
>> (especially the 0000 opcode) looks very much like a bug that should be
>> fixed in kernel 3.12

>> So the first thing I'd try is either cherrypicking the btrfs patches
>> from 3.12 back to 3.11-stable, or wait for 3.11.5 and check for btrfs
>> patches there, or try 3.12-rcX (rc3 is out and I guess rc4 should be
>> out shortly now as I think it has been nearly a week).
> 
> Could you please give me the patch SHA1 you are talking about?

Sorry, I've not tracked it /that/ closely, as I'm not a dev so the real 
technical stuff is over my head, and I run rc kernels from about rc2 
anyway, so I have the fixes reasonably fast already.  I simply try to 
keep up with the general gist of things well enough to search the list 
for that thread I remembered if I need to, and you should be able to do 
that as well as I, now that you know the threads and patches are there.

-- 
Duncan - List replies preferred.   No HTML msgs.
"Every nonfree program has a lord, a master --
and if you use the program, he is your master."  Richard Stallman

Re: Linux Arch: kernel BUG at fs/btrfs/inode.c:873!

[Anatol Pomozov]

Hi

On Sat, Oct 5, 2013 at 7:44 AM, Duncan <1i5t5.duncan@cox.net> wrote:
> Anatol Pomozov posted on Sat, 05 Oct 2013 04:51:52 -0700 as excerpted:
>
>> Hi
>>
>> On Fri, Oct 4, 2013 at 9:42 PM, Duncan <1i5t5.duncan@cox.net> wrote:
>>> Anatol Pomozov posted on Fri, 04 Oct 2013 21:03:11 -0700 as excerpted:
>>>
>>>> Hi,
>>>>
>>>> I have a home server on Linux Arch (kernel 3.11.2) that uses
>>>> multi-device btrfs on root filesystem.
>>>>
>>>> Until recently it worked completely fine. And yesterday I rebooted it
>>>> and the machine did not wake up.
>>>>
>>>> I booted from a USB (kernel 3.10) and tried to mount the filesystem.
>>>> Here is OOPs I see
>>>
>>>> ------------[ cut here ]------------
>>>> [   68.126138] kernel BUG at fs/btrfs/inode.c:873!
>>>> [   68.126164] invalid opcode: 0000 [#1] PREEMPT SMP
>>>
>>>> The only thing that I did recently is defrag /var/log/journal files
>>>> (journalctl is very slow because of btrfs COW). Something like this
>>>> http://www.mail-archive.com/linux-btrfs@vger.kernel.org/msg24878.html
>
> I forgot I was going to mention this in the previous reply...
>
> You can try setting the NOCOW attribute for that file or directory.
> There's instructions on the wiki (btrfs.wiki.kernel.org).  Virtual
> machine images also often work better with NOCOW.
>
> Meanwhile, thinking about systemd journal files there's also another
> patch that is too new to be in the mainline kernel, I think.  That bug
> was found on systemd journal files specifically, because systemd was
> allocating and then writing into them and btrfs wasn't doing the right
> thing with that.  There's a current thread about it.  Since I don't use
> systemd, however, I've not followed it that closely.

It is good to know that btrfs developers aware of the journald
performance issue. It is really annoying for those who uses
btrfs+systemd.

>
>>> I'm not a dev just a btrfs user and list regular myself, so the traces
>>> don't mean much to me.  However, the bit I retained in the quote above
>>> (especially the 0000 opcode) looks very much like a bug that should be
>>> fixed in kernel 3.12
>
>>> So the first thing I'd try is either cherrypicking the btrfs patches
>>> from 3.12 back to 3.11-stable, or wait for 3.11.5 and check for btrfs
>>> patches there, or try 3.12-rcX (rc3 is out and I guess rc4 should be
>>> out shortly now as I think it has been nearly a week).
>>
>> Could you please give me the patch SHA1 you are talking about?
>
> Sorry, I've not tracked it /that/ closely, as I'm not a dev so the real
> technical stuff is over my head, and I run rc kernels from about rc2
> anyway, so I have the fixes reasonably fast already.  I simply try to
> keep up with the general gist of things well enough to search the list
> for that thread I remembered if I need to, and you should be able to do
> that as well as I, now that you know the threads and patches are there.

Ok, so I still need a fix/workaround for the crash I have.

I booted from USB and ran btrfs-zero-log then mounted the filesystems
with "-orecovery". The files on the FS look fine. When I try to
unmount the fs it hangs in btrfs-transacti (see stacktrace above).
When I mount the FS as read-only it unmounts fine.

Actually I remembered that I set "chattr +C" on /var/log/journal
recursively (even for non-empty files) about a week ago, it might be
related to the crash. When I mount "-orw" and try to remove
/var/log/journal system hangs in btrfs-transacti thread.

Re: Linux Arch: kernel BUG at fs/btrfs/inode.c:873!

[Duncan]

Anatol Pomozov posted on Sat, 05 Oct 2013 22:14:25 -0700 as excerpted:

> Actually I remembered that I set "chattr +C" on /var/log/journal
> recursively (even for non-empty files) about a week ago, it might be
> related to the crash. When I mount "-orw" and try to remove
> /var/log/journal system hangs in btrfs-transacti thread.

Based on what I've seen in other threads and how nocow works, you really 
need to either set it (on the dir) before the files are created, or touch 
them so they're zero size and set it then.  You did say you set it on the 
dir, recursively, but existing files would then have been COW for awhile, 
and that might be related to your problem now, particularly with the just 
freshly patched systemd-journal-file-triggered-bug I mentioned.

Of course as you likely know but others googling this or otherwise 
reading it may not, btrfs is still labeled experimental, and while it 
does work pretty well for the general case, it's exactly the slightly or 
very oddball cases such as allocate-and-write-into technique that isn't 
quite so common, that can still be buggy.  In addition to a few loose-end 
features still being wrapped up, it's finding and fixing stuff like this 
that's the biggest thing still left before btrfs can be labeled stable 
and fully ready for normal and production use.

-- 
Duncan - List replies preferred.   No HTML msgs.
"Every nonfree program has a lord, a master --
and if you use the program, he is your master."  Richard Stallman

Re: Linux Arch: kernel BUG at fs/btrfs/inode.c:873!

[Anatol Pomozov]

Hi, Btrfs developers


On Fri, Oct 4, 2013 at 9:03 PM, Anatol Pomozov <anatol.pomozov@gmail.com> wrote:
> Hi,
>
> I have a home server on Linux Arch (kernel 3.11.2) that uses
> multi-device btrfs on root filesystem.
>
> Until recently it worked completely fine. And yesterday I rebooted it
> and the machine did not wake up.
>
> I booted from a USB (kernel 3.10) and tried to mount the filesystem.
> Here is OOPs I see
>
> [   41.676217] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
> 8 transid 164237 /dev/sda
> [   41.684161] btrfs: disk space caching is enabled
> [   67.266742] BTRFS error (device sdd3): block group 1141416919040
> has wrong amount of free space
> [   67.266796] BTRFS error (device sdd3): failed to load free space
> cache for block group 1141416919040
> [   68.126102] ------------[ cut here ]------------
> [   68.126138] kernel BUG at fs/btrfs/inode.c:873!
> [   68.126164] invalid opcode: 0000 [#1] PREEMPT SMP
> [   68.126203] Modules linked in: intel_powerclamp coretemp kvm_intel
> kvm crc32_pclmul ghash_clmulni_intel cryptd iTCO_wdt
> iTCO_vendor_support ppdev microcode snd_hda_codec_hdmi psmouse
> snd_hda_codec_realtek serio_raw i2c_i801 snd_hda_intel pcspkr
> snd_hda_codec lpc_ich snd_hwdep parport_pc parport snd_pcm mperf
> snd_page_alloc snd_timer snd mei_me soundcore evdev mei processor nfs
> lockd sunrpc fscache ext4 crc16 mbcache jbd2 dm_snapshot dm_mod
> squashfs loop isofs btrfs raid6_pq libcrc32c zlib_deflate xor
> hid_generic usbhid hid usb_storage sd_mod i915 intel_agp intel_gtt
> ahci libahci crc32c_intel i2c_algo_bit xhci_hcd libata ehci_pci
> ehci_hcd scsi_mod atl1c drm_kms_helper usbcore usb_common drm i2c_core
> button video
> [   68.126754] CPU: 1 PID: 386 Comm: mount Not tainted 3.10.10-1-ARCH #1
> [   68.126787] Hardware name: To Be Filled By O.E.M. To Be Filled By
> O.E.M./H61M/U3S3, BIOS P2.20 07/30/2012
> [   68.126834] task: ffff880118869950 ti: ffff88011377e000 task.ti:
> ffff88011377e000
> [   68.126871] RIP: 0010:[<ffffffffa0471223>]  [<ffffffffa0471223>]
> __cow_file_range+0x3e3/0x460 [btrfs]
> [   68.126933] RSP: 0018:ffff88011377f328  EFLAGS: 00010206
> [   68.126961] RAX: 00000000000004d2 RBX: 0000000000000000 RCX: 0000000000001000
> [   68.126996] RDX: 00000000000004d2 RSI: ffff88001f438608 RDI: ffff880115eb3000
> [   68.127032] RBP: ffff88011377f3c8 R08: 0000000000000000 R09: 000000000003ffff
> [   68.127068] R10: 0000000000040000 R11: 0000000000000000 R12: 0000000000000000
> [   68.127103] R13: ffff880115f88630 R14: ffff88001f438608 R15: 0000000000000000
> [   68.127140] FS:  00007fac17768780(0000) GS:ffff88011f300000(0000)
> knlGS:0000000000000000
> [   68.127180] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [   68.127209] CR2: 00007f518d994000 CR3: 0000000117ab4000 CR4: 00000000000407e0
> [   68.127246] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [   68.127281] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
> [   68.127317] Stack:
> [   68.127331]  00000109ffe26000 ffff880115f88c60 ffff88001f438428
> 000000000003ffff
> [   68.127381]  ffff88011700c010 ffffea0003231b40 ffff880115eb3000
> f600000109ffd870
> [   68.127430]  ffffffffa0482f29 ffff880118a31000 ffff880115f88638
> ffff88001f438448
> [   68.127480] Call Trace:
> [   68.127508]  [<ffffffffa0482f29>] ? release_extent_buffer+0xa9/0xd0 [btrfs]
> [   68.127553]  [<ffffffffa048862f>] ? free_extent_buffer+0x4f/0xa0 [btrfs]
> [   68.127598]  [<ffffffffa04716d6>] run_delalloc_nocow+0x436/0xaf0 [btrfs]
> [   68.127641]  [<ffffffffa0472180>] run_delalloc_range+0x320/0x390 [btrfs]
> [   68.127685]  [<ffffffffa04854c1>] ?
> find_lock_delalloc_range.constprop.44+0x1d1/0x1f0 [btrfs]
> [   68.127735]  [<ffffffffa0487044>] __extent_writepage+0x354/0x7b0 [btrfs]
> [   68.127772]  [<ffffffff81122645>] ? find_get_pages_tag+0x105/0x180
> [   68.127813]  [<ffffffffa0487722>]
> extent_write_cache_pages.isra.32.constprop.48+0x282/0x3e0 [btrfs]
> [   68.127867]  [<ffffffffa0487b7d>] extent_writepages+0x4d/0x70 [btrfs]
> [   68.127909]  [<ffffffffa046e080>] ? can_nocow_odirect+0x2f0/0x2f0 [btrfs]
> [   68.127951]  [<ffffffffa046cf28>] btrfs_writepages+0x28/0x30 [btrfs]
> [   68.127985]  [<ffffffff8112e28e>] do_writepages+0x1e/0x40
> [   68.128014]  [<ffffffff81123669>] __filemap_fdatawrite_range+0x59/0x60
> [   68.128048]  [<ffffffff81123733>] filemap_fdatawrite_range+0x13/0x20
> [   68.128090]  [<ffffffffa0481c99>] btrfs_wait_ordered_range+0x49/0x110 [btrfs]
> [   68.128135]  [<ffffffffa04a64c0>] __btrfs_write_out_cache+0x6d0/0x8f0 [btrfs]
> [   68.128180]  [<ffffffffa04a774d>] btrfs_write_out_cache+0x8d/0xe0 [btrfs]
> [   68.128224]  [<ffffffffa0459983>]
> btrfs_write_dirty_block_groups+0x533/0x620 [btrfs]
> [   68.128271]  [<ffffffffa04676e2>] commit_cowonly_roots+0x172/0x260 [btrfs]
> [   68.128314]  [<ffffffffa04695ad>]
> btrfs_commit_transaction+0x5bd/0xaf0 [btrfs]
> [   68.128353]  [<ffffffff8107b460>] ? wake_up_bit+0x30/0x30
> [   68.128391]  [<ffffffffa04a4edd>] btrfs_recover_log_trees+0x3bd/0x490 [btrfs]
> [   68.128434]  [<ffffffffa04a3270>] ? replay_one_dir_item+0xf0/0xf0 [btrfs]
> [   68.128477]  [<ffffffffa0466689>] open_ctree+0x17b9/0x1e80 [btrfs]
> [   68.128513]  [<ffffffff813555d3>] ? proc_comm_connector+0x33/0x120
> [   68.128551]  [<ffffffffa043f456>] btrfs_mount+0x636/0x830 [btrfs]
> [   68.128584]  [<ffffffff81141cd2>] ? pcpu_alloc+0x7d2/0x9e0
> [   68.128616]  [<ffffffff8118f5d9>] mount_fs+0x39/0x1b0
> [   68.128643]  [<ffffffff81141ef0>] ? __alloc_percpu+0x10/0x20
> [   68.128676]  [<ffffffff811a8c27>] vfs_kern_mount+0x67/0x100
> [   68.128706]  [<ffffffff811ab24e>] do_mount+0x23e/0xa20
> [   68.128737]  [<ffffffff8113d73b>] ? strndup_user+0x4b/0xf0
> [   68.128766]  [<ffffffff811abab3>] SyS_mount+0x83/0xc0
> [   68.128795]  [<ffffffff814cfe1d>] system_call_fastpath+0x1a/0x1f
> [   68.128826] Code: 8b 7d 90 4c 89 f6 e8 ad 9e 00 00 e9 dc fc ff ff
> 48 85 d2 74 40 80 be 30 fe ff ff 84 48 89 d0 74 34 48 83 f8 01 0f 84
> 87 fc ff ff <0f> 0b 48 8b 75 a8 48 8b 7d 90 41 89 c0 b9 9b 03 00 00 48
> c7 c2
> [   68.129145] RIP  [<ffffffffa0471223>] __cow_file_range+0x3e3/0x460 [btrfs]
> [   68.129192]  RSP <ffff88011377f328>
> [   68.129230] ---[ end trace 7992880786c40076 ]---
>
>
>
> Hm.... it looks like it crashed when it tries to restore logs. Ok, I
> ran 'btrfschk /dev/sda' and here is its output:
>
> [  181.281546] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
> 8 transid 164237 /dev/sda
> [  181.318148] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
> 3 transid 164237 /dev/sdb
> [  181.408490] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
> 2 transid 164237 /dev/sdc1
> [  181.763300] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
> 9 transid 164237 /dev/sdd3
> [  181.782414] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
> 8 transid 164237 /dev/sda
> [  181.784634] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
> 3 transid 164237 /dev/sdb
> [  181.788715] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
> 2 transid 164237 /dev/sdc1
> [  181.803161] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
> 9 transid 164237 /dev/sdd3
> [  337.445525] systemd-journald[160]: Failed to write entry, ignoring:
> Argument list too long
>
>
> Then I tried to mount the filesystem again and it stuck. I see several
> processes in UNINTERRUPTIBLE state:
>
> [  828.034908] SysRq : Show Blocked State
> [  828.036150]   task                        PC stack   pid father
> [  828.037418] btrfs-transacti D ffff880118a311e8     0   407      2 0x00000000
> [  828.038709]  ffff880115051dc8 0000000000000046 0000000000014340
> ffff880115051fd8
> [  828.040030]  ffff880115051fd8 0000000000014340 ffff88011886f620
> ffff88011886f620
> [  828.041364]  000000000000082f ffff880115051d30 ffffffff8109d141
> ffff880118868048
> [  828.042724] Call Trace:
> [  828.044071]  [<ffffffff8109d141>] ? cpuacct_charge+0x61/0x70
> [  828.045445]  [<ffffffff8108dd88>] ? __enqueue_entity+0x78/0x80
> [  828.046829]  [<ffffffff810920f6>] ? enqueue_entity+0x286/0xa20
> [  828.048227]  [<ffffffff81065bbb>] ? lock_timer_base.isra.35+0x2b/0x50
> [  828.049648]  [<ffffffff814c6f09>] schedule+0x29/0x70
> [  828.051076]  [<ffffffffa0468695>]
> wait_current_trans.isra.14+0xa5/0xf0 [btrfs]
> [  828.052515]  [<ffffffff8107b460>] ? wake_up_bit+0x30/0x30
> [  828.053970]  [<ffffffffa0469e18>] start_transaction+0x338/0x530 [btrfs]
> [  828.055453]  [<ffffffffa046a0c7>] btrfs_attach_transaction+0x17/0x20 [btrfs]
> [  828.056943]  [<ffffffffa0460ca1>] transaction_kthread+0x141/0x230 [btrfs]
> [  828.058455]  [<ffffffffa0460b60>] ? free_fs_root+0x90/0x90 [btrfs]
> [  828.059989]  [<ffffffff8107a670>] kthread+0xc0/0xd0
> [  828.061508]  [<ffffffff8107a5b0>] ? kthread_create_on_node+0x120/0x120
> [  828.063036]  [<ffffffff814cfd6c>] ret_from_fork+0x7c/0xb0
> [  828.064568]  [<ffffffff8107a5b0>] ? kthread_create_on_node+0x120/0x120
> [  828.066109] mount           D ffff880118a31878     0   427    343 0x00000000
> [  828.067680]  ffff880117bdbc18 0000000000000086 0000000000014340
> ffff880117bdbfd8
> [  828.069278]  ffff880117bdbfd8 0000000000014340 ffff880118facbf0
> ffff8801169cb800
> [  828.070869]  ffff88011f214340 ffffffff81085aa9 ffff8801169cb800
> ffff88011f214340
> [  828.072430] Call Trace:
> [  828.073966]  [<ffffffff81085aa9>] ? finish_task_switch+0x49/0xe0
> [  828.075524]  [<ffffffff814c6996>] ? __schedule+0x3f6/0x940
> [  828.077093]  [<ffffffff81071194>] ? wake_up_worker+0x24/0x30
> [  828.078671]  [<ffffffff814c5a34>] ? __mutex_lock_slowpath+0x284/0x3b0
> [  828.080275]  [<ffffffff814c6f09>] schedule+0x29/0x70
> [  828.081867]  [<ffffffff814c7d95>] rwsem_down_write_failed+0xf5/0x1c3
> [  828.083473]  [<ffffffffa043a000>] ? 0xffffffffa0439fff
> [  828.085083]  [<ffffffff81279e33>] call_rwsem_down_write_failed+0x13/0x20
> [  828.086717]  [<ffffffff814c5ec4>] ? down_write+0x24/0x26
> [  828.088366]  [<ffffffff8118dffe>] grab_super+0x2e/0xa0
> [  828.090021]  [<ffffffff8118e6f0>] sget+0x320/0x580
> [  828.091677]  [<ffffffffa043e130>] ?
> btrfs_parse_early_options+0x190/0x190 [btrfs]
> [  828.093368]  [<ffffffff814c57ae>] ? mutex_unlock+0xe/0x10
> [  828.095068]  [<ffffffffa043f228>] btrfs_mount+0x408/0x830 [btrfs]
> [  828.096786]  [<ffffffff81141cd2>] ? pcpu_alloc+0x7d2/0x9e0
> [  828.098516]  [<ffffffff8118f5d9>] mount_fs+0x39/0x1b0
> [  828.100267]  [<ffffffff81141ef0>] ? __alloc_percpu+0x10/0x20
> [  828.102017]  [<ffffffff811a8c27>] vfs_kern_mount+0x67/0x100
> [  828.103775]  [<ffffffff811ab24e>] do_mount+0x23e/0xa20
> [  828.105547]  [<ffffffff8113d73b>] ? strndup_user+0x4b/0xf0
> [  828.107312]  [<ffffffff811abab3>] SyS_mount+0x83/0xc0
> [  828.109096]  [<ffffffff814cfe1d>] system_call_fastpath+0x1a/0x1f
>
> The only thing that I did recently is defrag /var/log/journal files
> (journalctl is very slow because of btrfs COW). Something like this
> http://www.mail-archive.com/linux-btrfs@vger.kernel.org/msg24878.html
>
> How to fix this problem? And restore the data...


Dear btrfs developers, I still have my server in broken state. Is
there anything I can do to restore it? I tried to mount the filesystem
with different flags (e.g. notreelog) but all of them cause deadlock
like above. Have you see such issue before? Any ideas what the problem
can be?

I do not mind to spend some time on debugging this kernel issue it but
I really need some pointers from people who know this code very well
(I am mostly familiar with block layer).

Re: Linux Arch: kernel BUG at fs/btrfs/inode.c:873!

[Liu Bo]

On Mon, Oct 07, 2013 at 11:36:30PM -0700, Anatol Pomozov wrote:
> Hi, Btrfs developers
> 
> 
> On Fri, Oct 4, 2013 at 9:03 PM, Anatol Pomozov <anatol.pomozov@gmail.com> wrote:
> > Hi,
> >
> > I have a home server on Linux Arch (kernel 3.11.2) that uses
> > multi-device btrfs on root filesystem.
> >
> > Until recently it worked completely fine. And yesterday I rebooted it
> > and the machine did not wake up.
> >
> > I booted from a USB (kernel 3.10) and tried to mount the filesystem.
> > Here is OOPs I see
> >
> > [   41.676217] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
> > 8 transid 164237 /dev/sda
> > [   41.684161] btrfs: disk space caching is enabled
> > [   67.266742] BTRFS error (device sdd3): block group 1141416919040
> > has wrong amount of free space
> > [   67.266796] BTRFS error (device sdd3): failed to load free space
> > cache for block group 1141416919040
> > [   68.126102] ------------[ cut here ]------------
> > [   68.126138] kernel BUG at fs/btrfs/inode.c:873!
> > [   68.126164] invalid opcode: 0000 [#1] PREEMPT SMP
> > [   68.126203] Modules linked in: intel_powerclamp coretemp kvm_intel
> > kvm crc32_pclmul ghash_clmulni_intel cryptd iTCO_wdt
> > iTCO_vendor_support ppdev microcode snd_hda_codec_hdmi psmouse
> > snd_hda_codec_realtek serio_raw i2c_i801 snd_hda_intel pcspkr
> > snd_hda_codec lpc_ich snd_hwdep parport_pc parport snd_pcm mperf
> > snd_page_alloc snd_timer snd mei_me soundcore evdev mei processor nfs
> > lockd sunrpc fscache ext4 crc16 mbcache jbd2 dm_snapshot dm_mod
> > squashfs loop isofs btrfs raid6_pq libcrc32c zlib_deflate xor
> > hid_generic usbhid hid usb_storage sd_mod i915 intel_agp intel_gtt
> > ahci libahci crc32c_intel i2c_algo_bit xhci_hcd libata ehci_pci
> > ehci_hcd scsi_mod atl1c drm_kms_helper usbcore usb_common drm i2c_core
> > button video
> > [   68.126754] CPU: 1 PID: 386 Comm: mount Not tainted 3.10.10-1-ARCH #1
> > [   68.126787] Hardware name: To Be Filled By O.E.M. To Be Filled By
> > O.E.M./H61M/U3S3, BIOS P2.20 07/30/2012
> > [   68.126834] task: ffff880118869950 ti: ffff88011377e000 task.ti:
> > ffff88011377e000
> > [   68.126871] RIP: 0010:[<ffffffffa0471223>]  [<ffffffffa0471223>]
> > __cow_file_range+0x3e3/0x460 [btrfs]
> > [   68.126933] RSP: 0018:ffff88011377f328  EFLAGS: 00010206
> > [   68.126961] RAX: 00000000000004d2 RBX: 0000000000000000 RCX: 0000000000001000
> > [   68.126996] RDX: 00000000000004d2 RSI: ffff88001f438608 RDI: ffff880115eb3000
> > [   68.127032] RBP: ffff88011377f3c8 R08: 0000000000000000 R09: 000000000003ffff
> > [   68.127068] R10: 0000000000040000 R11: 0000000000000000 R12: 0000000000000000
> > [   68.127103] R13: ffff880115f88630 R14: ffff88001f438608 R15: 0000000000000000
> > [   68.127140] FS:  00007fac17768780(0000) GS:ffff88011f300000(0000)
> > knlGS:0000000000000000
> > [   68.127180] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [   68.127209] CR2: 00007f518d994000 CR3: 0000000117ab4000 CR4: 00000000000407e0
> > [   68.127246] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> > [   68.127281] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
> > [   68.127317] Stack:
> > [   68.127331]  00000109ffe26000 ffff880115f88c60 ffff88001f438428
> > 000000000003ffff
> > [   68.127381]  ffff88011700c010 ffffea0003231b40 ffff880115eb3000
> > f600000109ffd870
> > [   68.127430]  ffffffffa0482f29 ffff880118a31000 ffff880115f88638
> > ffff88001f438448
> > [   68.127480] Call Trace:
> > [   68.127508]  [<ffffffffa0482f29>] ? release_extent_buffer+0xa9/0xd0 [btrfs]
> > [   68.127553]  [<ffffffffa048862f>] ? free_extent_buffer+0x4f/0xa0 [btrfs]
> > [   68.127598]  [<ffffffffa04716d6>] run_delalloc_nocow+0x436/0xaf0 [btrfs]
> > [   68.127641]  [<ffffffffa0472180>] run_delalloc_range+0x320/0x390 [btrfs]
> > [   68.127685]  [<ffffffffa04854c1>] ?
> > find_lock_delalloc_range.constprop.44+0x1d1/0x1f0 [btrfs]
> > [   68.127735]  [<ffffffffa0487044>] __extent_writepage+0x354/0x7b0 [btrfs]
> > [   68.127772]  [<ffffffff81122645>] ? find_get_pages_tag+0x105/0x180
> > [   68.127813]  [<ffffffffa0487722>]
> > extent_write_cache_pages.isra.32.constprop.48+0x282/0x3e0 [btrfs]
> > [   68.127867]  [<ffffffffa0487b7d>] extent_writepages+0x4d/0x70 [btrfs]
> > [   68.127909]  [<ffffffffa046e080>] ? can_nocow_odirect+0x2f0/0x2f0 [btrfs]
> > [   68.127951]  [<ffffffffa046cf28>] btrfs_writepages+0x28/0x30 [btrfs]
> > [   68.127985]  [<ffffffff8112e28e>] do_writepages+0x1e/0x40
> > [   68.128014]  [<ffffffff81123669>] __filemap_fdatawrite_range+0x59/0x60
> > [   68.128048]  [<ffffffff81123733>] filemap_fdatawrite_range+0x13/0x20
> > [   68.128090]  [<ffffffffa0481c99>] btrfs_wait_ordered_range+0x49/0x110 [btrfs]
> > [   68.128135]  [<ffffffffa04a64c0>] __btrfs_write_out_cache+0x6d0/0x8f0 [btrfs]
> > [   68.128180]  [<ffffffffa04a774d>] btrfs_write_out_cache+0x8d/0xe0 [btrfs]
> > [   68.128224]  [<ffffffffa0459983>]
> > btrfs_write_dirty_block_groups+0x533/0x620 [btrfs]
> > [   68.128271]  [<ffffffffa04676e2>] commit_cowonly_roots+0x172/0x260 [btrfs]
> > [   68.128314]  [<ffffffffa04695ad>]
> > btrfs_commit_transaction+0x5bd/0xaf0 [btrfs]
> > [   68.128353]  [<ffffffff8107b460>] ? wake_up_bit+0x30/0x30
> > [   68.128391]  [<ffffffffa04a4edd>] btrfs_recover_log_trees+0x3bd/0x490 [btrfs]
> > [   68.128434]  [<ffffffffa04a3270>] ? replay_one_dir_item+0xf0/0xf0 [btrfs]
> > [   68.128477]  [<ffffffffa0466689>] open_ctree+0x17b9/0x1e80 [btrfs]
> > [   68.128513]  [<ffffffff813555d3>] ? proc_comm_connector+0x33/0x120
> > [   68.128551]  [<ffffffffa043f456>] btrfs_mount+0x636/0x830 [btrfs]
> > [   68.128584]  [<ffffffff81141cd2>] ? pcpu_alloc+0x7d2/0x9e0
> > [   68.128616]  [<ffffffff8118f5d9>] mount_fs+0x39/0x1b0
> > [   68.128643]  [<ffffffff81141ef0>] ? __alloc_percpu+0x10/0x20
> > [   68.128676]  [<ffffffff811a8c27>] vfs_kern_mount+0x67/0x100
> > [   68.128706]  [<ffffffff811ab24e>] do_mount+0x23e/0xa20
> > [   68.128737]  [<ffffffff8113d73b>] ? strndup_user+0x4b/0xf0
> > [   68.128766]  [<ffffffff811abab3>] SyS_mount+0x83/0xc0
> > [   68.128795]  [<ffffffff814cfe1d>] system_call_fastpath+0x1a/0x1f
> > [   68.128826] Code: 8b 7d 90 4c 89 f6 e8 ad 9e 00 00 e9 dc fc ff ff
> > 48 85 d2 74 40 80 be 30 fe ff ff 84 48 89 d0 74 34 48 83 f8 01 0f 84
> > 87 fc ff ff <0f> 0b 48 8b 75 a8 48 8b 7d 90 41 89 c0 b9 9b 03 00 00 48
> > c7 c2
> > [   68.129145] RIP  [<ffffffffa0471223>] __cow_file_range+0x3e3/0x460 [btrfs]
> > [   68.129192]  RSP <ffff88011377f328>
> > [   68.129230] ---[ end trace 7992880786c40076 ]---
> >
> >
> >
> > Hm.... it looks like it crashed when it tries to restore logs. Ok, I
> > ran 'btrfschk /dev/sda' and here is its output:
> >
> > [  181.281546] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
> > 8 transid 164237 /dev/sda
> > [  181.318148] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
> > 3 transid 164237 /dev/sdb
> > [  181.408490] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
> > 2 transid 164237 /dev/sdc1
> > [  181.763300] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
> > 9 transid 164237 /dev/sdd3
> > [  181.782414] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
> > 8 transid 164237 /dev/sda
> > [  181.784634] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
> > 3 transid 164237 /dev/sdb
> > [  181.788715] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
> > 2 transid 164237 /dev/sdc1
> > [  181.803161] device fsid 25e6a6fa-fe1f-4be5-a638-eeac948f8c21 devid
> > 9 transid 164237 /dev/sdd3
> > [  337.445525] systemd-journald[160]: Failed to write entry, ignoring:
> > Argument list too long
> >
> >
> > Then I tried to mount the filesystem again and it stuck. I see several
> > processes in UNINTERRUPTIBLE state:
> >
> > [  828.034908] SysRq : Show Blocked State
> > [  828.036150]   task                        PC stack   pid father
> > [  828.037418] btrfs-transacti D ffff880118a311e8     0   407      2 0x00000000
> > [  828.038709]  ffff880115051dc8 0000000000000046 0000000000014340
> > ffff880115051fd8
> > [  828.040030]  ffff880115051fd8 0000000000014340 ffff88011886f620
> > ffff88011886f620
> > [  828.041364]  000000000000082f ffff880115051d30 ffffffff8109d141
> > ffff880118868048
> > [  828.042724] Call Trace:
> > [  828.044071]  [<ffffffff8109d141>] ? cpuacct_charge+0x61/0x70
> > [  828.045445]  [<ffffffff8108dd88>] ? __enqueue_entity+0x78/0x80
> > [  828.046829]  [<ffffffff810920f6>] ? enqueue_entity+0x286/0xa20
> > [  828.048227]  [<ffffffff81065bbb>] ? lock_timer_base.isra.35+0x2b/0x50
> > [  828.049648]  [<ffffffff814c6f09>] schedule+0x29/0x70
> > [  828.051076]  [<ffffffffa0468695>]
> > wait_current_trans.isra.14+0xa5/0xf0 [btrfs]
> > [  828.052515]  [<ffffffff8107b460>] ? wake_up_bit+0x30/0x30
> > [  828.053970]  [<ffffffffa0469e18>] start_transaction+0x338/0x530 [btrfs]
> > [  828.055453]  [<ffffffffa046a0c7>] btrfs_attach_transaction+0x17/0x20 [btrfs]
> > [  828.056943]  [<ffffffffa0460ca1>] transaction_kthread+0x141/0x230 [btrfs]
> > [  828.058455]  [<ffffffffa0460b60>] ? free_fs_root+0x90/0x90 [btrfs]
> > [  828.059989]  [<ffffffff8107a670>] kthread+0xc0/0xd0
> > [  828.061508]  [<ffffffff8107a5b0>] ? kthread_create_on_node+0x120/0x120
> > [  828.063036]  [<ffffffff814cfd6c>] ret_from_fork+0x7c/0xb0
> > [  828.064568]  [<ffffffff8107a5b0>] ? kthread_create_on_node+0x120/0x120
> > [  828.066109] mount           D ffff880118a31878     0   427    343 0x00000000
> > [  828.067680]  ffff880117bdbc18 0000000000000086 0000000000014340
> > ffff880117bdbfd8
> > [  828.069278]  ffff880117bdbfd8 0000000000014340 ffff880118facbf0
> > ffff8801169cb800
> > [  828.070869]  ffff88011f214340 ffffffff81085aa9 ffff8801169cb800
> > ffff88011f214340
> > [  828.072430] Call Trace:
> > [  828.073966]  [<ffffffff81085aa9>] ? finish_task_switch+0x49/0xe0
> > [  828.075524]  [<ffffffff814c6996>] ? __schedule+0x3f6/0x940
> > [  828.077093]  [<ffffffff81071194>] ? wake_up_worker+0x24/0x30
> > [  828.078671]  [<ffffffff814c5a34>] ? __mutex_lock_slowpath+0x284/0x3b0
> > [  828.080275]  [<ffffffff814c6f09>] schedule+0x29/0x70
> > [  828.081867]  [<ffffffff814c7d95>] rwsem_down_write_failed+0xf5/0x1c3
> > [  828.083473]  [<ffffffffa043a000>] ? 0xffffffffa0439fff
> > [  828.085083]  [<ffffffff81279e33>] call_rwsem_down_write_failed+0x13/0x20
> > [  828.086717]  [<ffffffff814c5ec4>] ? down_write+0x24/0x26
> > [  828.088366]  [<ffffffff8118dffe>] grab_super+0x2e/0xa0
> > [  828.090021]  [<ffffffff8118e6f0>] sget+0x320/0x580
> > [  828.091677]  [<ffffffffa043e130>] ?
> > btrfs_parse_early_options+0x190/0x190 [btrfs]
> > [  828.093368]  [<ffffffff814c57ae>] ? mutex_unlock+0xe/0x10
> > [  828.095068]  [<ffffffffa043f228>] btrfs_mount+0x408/0x830 [btrfs]
> > [  828.096786]  [<ffffffff81141cd2>] ? pcpu_alloc+0x7d2/0x9e0
> > [  828.098516]  [<ffffffff8118f5d9>] mount_fs+0x39/0x1b0
> > [  828.100267]  [<ffffffff81141ef0>] ? __alloc_percpu+0x10/0x20
> > [  828.102017]  [<ffffffff811a8c27>] vfs_kern_mount+0x67/0x100
> > [  828.103775]  [<ffffffff811ab24e>] do_mount+0x23e/0xa20
> > [  828.105547]  [<ffffffff8113d73b>] ? strndup_user+0x4b/0xf0
> > [  828.107312]  [<ffffffff811abab3>] SyS_mount+0x83/0xc0
> > [  828.109096]  [<ffffffff814cfe1d>] system_call_fastpath+0x1a/0x1f
> >
> > The only thing that I did recently is defrag /var/log/journal files
> > (journalctl is very slow because of btrfs COW). Something like this
> > http://www.mail-archive.com/linux-btrfs@vger.kernel.org/msg24878.html
> >
> > How to fix this problem? And restore the data...
> 
> 
> Dear btrfs developers, I still have my server in broken state. Is
> there anything I can do to restore it? I tried to mount the filesystem
> with different flags (e.g. notreelog) but all of them cause deadlock
> like above. Have you see such issue before? Any ideas what the problem
> can be?
> 
> I do not mind to spend some time on debugging this kernel issue it but
> I really need some pointers from people who know this code very well
> (I am mostly familiar with block layer).

Getting Stuck while sget() doesn't seem to be a problem caused by zeroing the
log.

Is it possible to boot it with a USB(recent 3.12-rc3) and mount it again?

-liubo

Re: Linux Arch: kernel BUG at fs/btrfs/inode.c:873!

[Anatol Pomozov]

Hi,

Kernel 3.12-rc built from HEAD has the same issue as 3.10 and 3.11

Ok, I was able to "fix" my problem by booting from an old kernel
(3.8.7) and it allowed me to mount the fs. Then I removed
/var/log/journal directory. After that I was able to boot with 3.11.
So I believe 3.9/3.10 has a regression in how it handles COW files. As
I described above, some time ago I defraged journald files and set +C
attribute to /var/log/journal (both to the folders and existing
files).

So 3.11 boots fine and the only boot warning I see is

Oct 11 19:06:55 brest kernel: BTRFS error (device sdd3): block group
1141416919040 has wrong amount of free space
Oct 11 19:06:55 brest kernel: BTRFS error (device sdd3): failed to
load free space cache for block group 1141416919040


I tried 'btrfsck -repair' but it crashes so I cannot even check or
repair my btrfs mount.

Re: Linux Arch: kernel BUG at fs/btrfs/inode.c:873!

[Chris Murphy]

On Oct 11, 2013, at 8:22 PM, Anatol Pomozov <anatol.pomozov@gmail.com> wrote:

> Hi,
> 
> Kernel 3.12-rc built from HEAD has the same issue as 3.10 and 3.11
> 
> Ok, I was able to "fix" my problem by booting from an old kernel
> (3.8.7) and it allowed me to mount the fs.

Interesting.

> Then I removed
> /var/log/journal directory. After that I was able to boot with 3.11.
> So I believe 3.9/3.10 has a regression in how it handles COW files. As
> I described above, some time ago I defraged journald files and set +C
> attribute to /var/log/journal (both to the folders and existing
> files).

In any case you'd have saved yourself some trouble by checking the archives first. The journald issue was reported Sep 23 in this thread:
http://comments.gmane.org/gmane.comp.file-systems.btrfs/28678

And a fix has been sent to stable, although I'm not sure the exact 3.10.x, 3.11.x versions it will end up in.

> 
> So 3.11 boots fine and the only boot warning I see is
> 
> Oct 11 19:06:55 brest kernel: BTRFS error (device sdd3): block group
> 1141416919040 has wrong amount of free space
> Oct 11 19:06:55 brest kernel: BTRFS error (device sdd3): failed to
> load free space cache for block group 1141416919040
> 
> 
> I tried 'btrfsck -repair' but it crashes so I cannot even check or
> repair my btrfs mount.

I'm uncertain this problem is related to the journald issue. I'm also uncertain of the fix. But if you don't get a reply from a developer in the time frame you prefer, I suggest you use btrfs-image -c9 -t4 referred to here:
https://btrfs.wiki.kernel.org/index.php/Btrfs-image

this will write the file system state minus data, in case a developer wants to see it at some point. In the meantime you can then blow away the file system and restore the data to get on with using it.


Chris Murphy

Re: Linux Arch: kernel BUG at fs/btrfs/inode.c:873!

[Chris Murphy]

I wrote:
> On Oct 11, 2013, at 8:22 PM, Anatol Pomozov <anatol.pomozov@gmail.com> wrote:
> 
>> Hi,
>> 
>> Kernel 3.12-rc built from HEAD has the same issue as 3.10 and 3.11
>> 
>> Ok, I was able to "fix" my problem by booting from an old kernel
>> (3.8.7) and it allowed me to mount the fs.
> 
> Interesting.

It could be angels dancing on headpins territory, but I'm curious if successful mount is reproducible with either 3.4.66 or 3.9.11. The 3.5 through 3.8 kernels are neither listed as stable nor longterm.


Chris Murphy