Re: [PATCH] Btrfs: fix easily get into ENOSPC in mixed case

[Sergei Trofimovich <slyich@gmail.com>]

[-- Attachment #1.1: Type: text/plain, Size: 3729 bytes --]

On Mon, 11 Apr 2011 14:29:21 +0800
liubo <liubo2009@cn.fujitsu.com> wrote:

> On 04/09/2011 05:55 AM, Sergei Trofimovich wrote:
> > [  100.500011] Call Trace:
> > [  100.500011]  [<ffffffff810ed3a0>] vfs_unlink+0x80/0xf0
> > [  100.500011]  [<ffffffff810ef6f3>] do_unlinkat+0x173/0x1b0
> > [  100.500011]  [<ffffffff8111727b>] ? fsnotify_find_inode_mark+0x3b/0x50
> > [  100.500011]  [<ffffffff810dff91>] ? filp_close+0x61/0x90
> > [  100.500011]  [<ffffffff810f0c0d>] sys_unlinkat+0x1d/0x40
> > [  100.500011]  [<ffffffff81574c3b>] system_call_fastpath+0x16/0x1b
> > [  100.500011] Code: 4c 8b 65 e0 48 8b 5d d8 4c 8b 6d e8 4c 8b 75 f0 4c 8b 7d f8 c9 c3 0f 1f 40 00 4c 89 fe 4c 89 ef e8 05 d0 ff ff 85 c0 74 bb 0f 0b <0f> 0b 89 c3 eb cd 66 0f 1f 84 00 00 00 00 00 55 48 89 e5 41 57 
> > [  100.500011] RIP  [<ffffffffa024a011>] btrfs_unlink+0xd1/0xe0 [btrfs]
> > [  100.500011]  RSP <ffff880070b55e28>
> > [  100.525672] ---[ end trace 7e63b9144b7307fe ]---
> > 
> > Looks like I won't be able to test your patch until this thing will go away first.
> 
> Thanks a lot for testing, though.
> 
> I guess something messed up your btrfs metadata, cause when btrfs_unlink() wanted to remove A,
> it found that A was just missing...

Hello again!

I've decided to explore OOps myself a bit. The result is a debugging patch I've attached.
I've applied it and you patch
    [PATCH] Btrfs: fix easily get into ENOSPC in mixed case
on top of vanilla 2.6.39-rc4

The result you can see in attached 'fault.log'. There you can see -ENOSPC propagation.
No idea why it converted to -ENOENT in the end. The result is very similar with vanilla 2.6.39-rc4.
I can run the debugging patch on it as well if you like.


I think interesting the parts are (they were found by Arne before):
[    0.040000] new update_space_info: 
[    0.040000] space_info has 0 free, is not full
[    0.040000] space_info total=0, used=0, pinned=0, reserved=0, may_use=0, readonly=0
[    0.040000] new update_space_info: 
[    0.040000] space_info has 0 free, is not full
[    0.040000] space_info total=0, used=0, pinned=0, reserved=0, may_use=0, readonly=0
[    0.040000] new update_space_info: 
[    0.040000] space_info has 0 free, is not full
[    0.040000] space_info total=0, used=0, pinned=0, reserved=0, may_use=0, readonly=0

and:
[    0.290000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.300000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.310000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.320000] reserve_metadata_bytes: shrink_delalloc(num_bytes=983040) -> 0
[    0.320000] reserve_metadata_bytes: 
[    0.320000] space_info has 18446744073708568576 free, is not full
[    0.320000] space_info total=0, used=0, pinned=0, reserved=983040, may_use=0, readonly=0

Here I see 2 problems:
1 (major) free space is busted (as the whole space_info).
2 (minor) the original loop of shrink_delalloc busy waited 30 seconds, so I had to trim it;
   and it seemed to know that additional IO won't reclaim any pages ('yet 0 bytes' string AFAIU);
   but it's likely a result of busted space_info: it has reserved=983040 more, than total=0.

If I'll revert c59021f846881a957ac5afe456d0f59d6a517b61 from vanilla 2.6.39-rc4 I'll be able to delete
the files from filesystem.

I perform tests in usermode linux,  and run 'rm -rf' on the same faulty partition snapshot.
I've backed it up, so it's easy to reproduce and debug. I can provide more info if you need.
It's a 'readable' (read-only btrfs mount behaves fine) 5GB image.

-- 

  Sergei

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1.2: 0002-btrfs-my-nice-debug.patch --]
[-- Type: text/x-patch, Size: 8575 bytes --]

From 56668c999cae1b5ca00e94c63dc1c38eba68e3e1 Mon Sep 17 00:00:00 2001
From: Sergei Trofimovich <slyfox@gentoo.org>
Date: Wed, 20 Apr 2011 00:11:40 +0300
Subject: [PATCH 2/2] btrfs: my nice debug

Signed-off-by: Sergei Trofimovich <slyfox@gentoo.org>
---
 fs/btrfs/ctree.c       |    7 +++++++
 fs/btrfs/dir-item.c    |    6 ++++++
 fs/btrfs/extent-tree.c |   25 ++++++++++++++++++++++++-
 fs/btrfs/inode.c       |    5 +++++
 4 files changed, 42 insertions(+), 1 deletions(-)

diff --git a/fs/btrfs/ctree.c b/fs/btrfs/ctree.c
index 84d7ca1..41f8581 100644
--- a/fs/btrfs/ctree.c
+++ b/fs/btrfs/ctree.c
@@ -421,7 +421,10 @@ static noinline int __btrfs_cow_block(struct btrfs_trans_handle *trans,
 				     root->root_key.objectid, &disk_key,
 				     level, search_start, empty_size);
 	if (IS_ERR(cow))
+	{
+		printk(KERN_INFO "__btrfs_cow_block: btrfs_alloc_free_block ret=%d\n", (int)PTR_ERR(cow));
 		return PTR_ERR(cow);
+	}
 
 	/* cow is set to blocking by btrfs_init_new_buffer */
 
@@ -1648,6 +1651,7 @@ again:
 					      p->slots[level + 1], &b);
 			if (err) {
 				ret = err;
+				printk(KERN_INFO "1. btrfs_search_slot ret=%d\n", ret);
 				goto done;
 			}
 		}
@@ -1692,6 +1696,7 @@ cow_done:
 				goto again;
 			if (err) {
 				ret = err;
+				printk(KERN_INFO "2. btrfs_search_slot ret=%d\n", ret);
 				goto done;
 			}
 			b = p->nodes[level];
@@ -1711,6 +1716,7 @@ cow_done:
 				goto again;
 			if (err) {
 				ret = err;
+				printk(KERN_INFO "3. btrfs_search_slot ret=%d\n", ret);
 				goto done;
 			}
 
@@ -1736,6 +1742,7 @@ cow_done:
 				BUG_ON(err > 0);
 				if (err) {
 					ret = err;
+					printk(KERN_INFO "4. btrfs_search_slot ret=%d\n", ret);
 					goto done;
 				}
 			}
diff --git a/fs/btrfs/dir-item.c b/fs/btrfs/dir-item.c
index dec9348..228a706 100644
--- a/fs/btrfs/dir-item.c
+++ b/fs/btrfs/dir-item.c
@@ -228,7 +228,10 @@ struct btrfs_dir_item *btrfs_lookup_dir_item(struct btrfs_trans_handle *trans,
 
 	ret = btrfs_search_slot(trans, root, &key, path, ins_len, cow);
 	if (ret < 0)
+	{
+		printk (KERN_INFO "btrfs_lookup_dir_item: search slot failed: %d\n", ret);
 		return ERR_PTR(ret);
+	}
 	if (ret > 0) {
 		if (path->slots[0] == 0)
 			return NULL;
@@ -243,6 +246,7 @@ struct btrfs_dir_item *btrfs_lookup_dir_item(struct btrfs_trans_handle *trans,
 	    found_key.offset != key.offset)
 		return NULL;
 
+	printk (KERN_INFO "btrfs_lookup_dir_item -> btrfs_match_dir_item_name\n");
 	return btrfs_match_dir_item_name(root, path, name, name_len);
 }
 
@@ -377,6 +381,8 @@ struct btrfs_dir_item *btrfs_match_dir_item_name(struct btrfs_root *root,
 	u32 this_len;
 	struct extent_buffer *leaf;
 
+	printk(KERN_INFO "btrfs_match_dir_item_name (name='%s')\n", name);
+
 	leaf = path->nodes[0];
 	dir_item = btrfs_item_ptr(leaf, path->slots[0], struct btrfs_dir_item);
 	if (verify_dir_item(root, leaf, dir_item))
diff --git a/fs/btrfs/extent-tree.c b/fs/btrfs/extent-tree.c
index 31f33ba..e51adfa 100644
--- a/fs/btrfs/extent-tree.c
+++ b/fs/btrfs/extent-tree.c
@@ -3016,6 +3016,7 @@ static int update_space_info(struct btrfs_fs_info *info, u64 flags,
 		found->full = 0;
 		spin_unlock(&found->lock);
 		*space_info = found;
+		printk (KERN_INFO "found %s: ", __func__); dump_space_info (*space_info, 0, 0);
 		return 0;
 	}
 	found = kzalloc(sizeof(*found), GFP_NOFS);
@@ -3043,6 +3044,7 @@ static int update_space_info(struct btrfs_fs_info *info, u64 flags,
 	*space_info = found;
 	list_add_rcu(&found->list, &info->space_info);
 	atomic_set(&found->caching_threads, 0);
+	printk (KERN_INFO "new %s: ", __func__); dump_space_info (*space_info, 0, 0);
 	return 0;
 }
 
@@ -3418,6 +3420,8 @@ static int shrink_delalloc(struct btrfs_trans_handle *trans,
 	block_rsv = &root->fs_info->delalloc_block_rsv;
 	space_info = block_rsv->space_info;
 
+	printk(KERN_INFO "shrink_delalloc: "); dump_space_info (space_info, 0, 0);
+
 	smp_mb();
 	reserved = space_info->bytes_reserved;
 	progress = space_info->reservation_progress;
@@ -3427,11 +3431,13 @@ static int shrink_delalloc(struct btrfs_trans_handle *trans,
 
 	max_reclaim = min(reserved, to_reclaim);
 
-	while (loops < 1024) {
+	while (loops < 10) {
 		/* have the flusher threads jump in and do some IO */
 		smp_mb();
 		nr_pages = min_t(unsigned long, nr_pages,
 		       root->fs_info->delalloc_bytes >> PAGE_CACHE_SHIFT);
+		printk(KERN_INFO "shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free %d pages (yet %llu bytes to wb).\n"
+		      , nr_pages, (long long unsigned)root->fs_info->delalloc_bytes);
 		writeback_inodes_sb_nr_if_idle(root->fs_info->sb, nr_pages);
 
 		spin_lock(&space_info->lock);
@@ -3446,7 +3452,10 @@ static int shrink_delalloc(struct btrfs_trans_handle *trans,
 			break;
 
 		if (trans && trans->transaction->blocked)
+		{
+		printk(KERN_INFO "shrink_delalloc: ret -EAGAIN\n");
 			return -EAGAIN;
+		}
 
 		time_left = schedule_timeout_interruptible(1);
 
@@ -3499,11 +3508,15 @@ again:
 	if (reserved)
 		num_bytes = 0;
 
+	printk(KERN_INFO "reserve_metadata_bytes: "); dump_space_info (space_info, 0, 0);
+
 	spin_lock(&space_info->lock);
 	unused = space_info->bytes_used + space_info->bytes_reserved +
 		 space_info->bytes_pinned + space_info->bytes_readonly +
 		 space_info->bytes_may_use;
 
+	printk(KERN_INFO "reserve_metadata_bytes: consider unused=%llu\n", (long long unsigned)unused);
+
 	/*
 	 * The idea here is that we've not already over-reserved the block group
 	 * then we can go ahead and save our reservation first and then start
@@ -3558,6 +3571,8 @@ again:
 	 * metadata until after the IO is completed.
 	 */
 	ret = shrink_delalloc(trans, root, num_bytes, 1);
+	printk(KERN_INFO "reserve_metadata_bytes: shrink_delalloc(num_bytes=%llu) -> %d\n"
+	      , (long long unsigned)num_bytes, ret);
 	if (ret > 0)
 		return 0;
 	else if (ret < 0)
@@ -5773,11 +5788,14 @@ use_block_rsv(struct btrfs_trans_handle *trans,
 		 * the global reserve.
 		 */
 		if (ret && block_rsv != global_rsv) {
+			printk(KERN_INFO "use_block_rsv (nonglobal metadata rsv) ret=%d. retry global\n", ret);
 			ret = block_rsv_use_bytes(global_rsv, blocksize);
 			if (!ret)
 				return global_rsv;
+			printk(KERN_INFO "use_block_rsv (retry global metadata rsv) ret=%d\n", ret);
 			return ERR_PTR(ret);
 		} else if (ret) {
+			printk(KERN_INFO "use_block_rsv (global metadata rsv) ret=%d\n", ret);
 			return ERR_PTR(ret);
 		}
 		return block_rsv;
@@ -5802,6 +5820,7 @@ use_block_rsv(struct btrfs_trans_handle *trans,
 		}
 	}
 
+	printk(KERN_INFO "the very end of use_block_rsv. -ENOSPC\n");
 	return ERR_PTR(-ENOSPC);
 }
 
@@ -5833,12 +5852,16 @@ struct extent_buffer *btrfs_alloc_free_block(struct btrfs_trans_handle *trans,
 
 	block_rsv = use_block_rsv(trans, root, blocksize);
 	if (IS_ERR(block_rsv))
+	{
+		printk(KERN_INFO "btrfs_alloc_free_block: use_block_rsv error=%d\n", (int)PTR_ERR(block_rsv));
 		return ERR_CAST(block_rsv);
+	}
 
 	ret = btrfs_reserve_extent(trans, root, blocksize, blocksize,
 				   empty_size, hint, (u64)-1, &ins, 0);
 	if (ret) {
 		unuse_block_rsv(block_rsv, blocksize);
+		printk(KERN_INFO "btrfs_alloc_free_block: reserve_extent=%d\n", ret);
 		return ERR_PTR(ret);
 	}
 
diff --git a/fs/btrfs/inode.c b/fs/btrfs/inode.c
index fcd66b6..037afe2 100644
--- a/fs/btrfs/inode.c
+++ b/fs/btrfs/inode.c
@@ -2699,6 +2699,7 @@ static int __btrfs_unlink_inode(struct btrfs_trans_handle *trans,
 	di = btrfs_lookup_dir_item(trans, root, path, dir->i_ino,
 				    name, name_len, -1);
 	if (IS_ERR(di)) {
+		printk(KERN_INFO "btrfs_lookup_dir_item: IS_ERR(di) = %d\n", (int)PTR_ERR(di));
 		ret = PTR_ERR(di);
 		goto err;
 	}
@@ -2710,7 +2711,9 @@ static int __btrfs_unlink_inode(struct btrfs_trans_handle *trans,
 	btrfs_dir_item_key_to_cpu(leaf, di, &key);
 	ret = btrfs_delete_one_dir_name(trans, root, path, di);
 	if (ret)
+	{
 		goto err;
+	}
 	btrfs_release_path(root, path);
 
 	ret = btrfs_del_inode_ref(trans, root, name, name_len,
@@ -2762,8 +2765,10 @@ int btrfs_unlink_inode(struct btrfs_trans_handle *trans,
 		       const char *name, int name_len)
 {
 	int ret;
+	printk (KERN_INFO"__unlinking '%s'\n", name);
 	ret = __btrfs_unlink_inode(trans, root, dir, inode, name, name_len);
 	if (!ret) {
+		printk (KERN_INFO"unlinking '%s'\n", name);
 		btrfs_drop_nlink(inode);
 		ret = btrfs_update_inode(trans, root, inode);
 	}
-- 
1.7.3.4


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1.3: fault.log --]
[-- Type: text/x-log, Size: 18359 bytes --]

Checking that ptrace can change system call numbers...Core dump limits :
	soft - 0
	hard - NONE
OK
Checking syscall emulation patch for ptrace...Core dump limits :
	soft - 0
	hard - NONE
OK
Checking advanced syscall emulation patch for ptrace...Core dump limits :
	soft - 0
	hard - NONE
OK
Core dump limits :
	soft - 0
	hard - NONE
Checking for tmpfs mount on /dev/shm...OK
Checking PROT_EXEC mmap in /dev/shm/...OK
Checking for the skas3 patch in the host:
  - /proc/mm...not found: No such file or directory
  - PTRACE_FAULTINFO...not found
OK
  - PTRACE_LDT...not found
OK
OK
UML running in SKAS0 mode
Adding 18935808 bytes to physical memory to account for exec-shield gap
[    0.000000] Linux version 2.6.39-rc4+ (st@st) (gcc version 4.5.2 (Gentoo Hardened 4.5.2 p1.0, pie-0.4.5) ) #68 Wed Apr 20 00:24:54 EEST 2011
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 133574
[    0.000000] Kernel command line: ubd0=/home/st/linux-2.6-um-fs/chewed-portage.img root=/dev/root rootflags=/home/st/linux-2.6-um-fs/root rw rootfstype=hostfs mem=512M init=/init
[    0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes)
[    0.000000] Dentry cache hash table entries: 131072 (order: 8, 1048576 bytes)
[    0.000000] Inode-cache hash table entries: 65536 (order: 7, 524288 bytes)
[    0.000000] Memory: 502504k available
[    0.000000] SLUB: Genslabs=15, HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] NR_IRQS:15
[    0.000000] ODEBUG: selftest passed
[    0.000000] Calibrating delay loop... 1036.28 BogoMIPS (lpj=5181440)
[    0.040000] pid_max: default: 32768 minimum: 301
[    0.040000] Mount-cache hash table entries: 256
[    0.040000] Checking that host ptys support output SIGIO...Yes
[    0.040000] Checking that host ptys support SIGIO on close...No, enabling workaround
[    0.040000] Using 2.6 host AIO
[    0.040000] atomic64 test passed
[    0.040000] NET: Registered protocol family 16
[    0.040000] bio: create slab <bio-0> at 0
[    0.040000] Switching to clocksource itimer
[    0.040000] NET: Registered protocol family 2
[    0.040000] IP route cache hash table entries: 8192 (order: 4, 65536 bytes)
[    0.040000] IPv4 FIB: Using LC-trie version 0.409
[    0.040000] TCP established hash table entries: 32768 (order: 7, 524288 bytes)
[    0.040000] TCP bind hash table entries: 32768 (order: 6, 262144 bytes)
[    0.040000] TCP: Hash tables configured (established 32768 bind 32768)
[    0.040000] TCP reno registered
[    0.040000] UDP hash table entries: 512 (order: 2, 16384 bytes)
[    0.040000] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[    0.040000] NET: Registered protocol family 1
[    0.040000] mconsole (version 2) initialized on /home/st/.uml/FBNd0K/mconsole
[    0.040000] Checking host MADV_REMOVE support...OK
[    0.040000] ubd: Synchronous mode
[    0.040000] Btrfs loaded
[    0.040000] msgmni has been set to 981
[    0.040000] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 254)
[    0.040000] io scheduler noop registered (default)
[    0.040000] loop: module loaded
[    0.040000] TCP cubic registered
[    0.040000] NET: Registered protocol family 17
[    0.040000] Initialized stdio console driver
[    0.040000] Using a channel type which is configured out of UML
[    0.040000] parse_chan_pair failed for device 1 : Configuration failed
[    0.040000] Using a channel type which is configured out of UML
[    0.040000] parse_chan_pair failed for device 2 : Configuration failed
[    0.040000] Using a channel type which is configured out of UML
[    0.040000] parse_chan_pair failed for device 3 : Configuration failed
[    0.040000] Using a channel type which is configured out of UML
[    0.040000] parse_chan_pair failed for device 4 : Configuration failed
[    0.040000] Using a channel type which is configured out of UML
[    0.040000] parse_chan_pair failed for device 5 : Configuration failed
[    0.040000] Using a channel type which is configured out of UML
[    0.040000] parse_chan_pair failed for device 6 : Configuration failed
[    0.040000] Using a channel type which is configured out of UML
[    0.040000] parse_chan_pair failed for device 7 : Configuration failed
[    0.040000] Using a channel type which is configured out of UML
[    0.040000] parse_chan_pair failed for device 8 : Configuration failed
[    0.040000] Using a channel type which is configured out of UML
[    0.040000] parse_chan_pair failed for device 9 : Configuration failed
[    0.040000] Using a channel type which is configured out of UML
[    0.040000] parse_chan_pair failed for device 10 : Configuration failed
[    0.040000] Using a channel type which is configured out of UML
[    0.040000] parse_chan_pair failed for device 11 : Configuration failed
[    0.040000] Using a channel type which is configured out of UML
[    0.040000] parse_chan_pair failed for device 12 : Configuration failed
[    0.040000] Using a channel type which is configured out of UML
[    0.040000] parse_chan_pair failed for device 13 : Configuration failed
[    0.040000] Using a channel type which is configured out of UML
[    0.040000] parse_chan_pair failed for device 14 : Configuration failed
[    0.040000] Using a channel type which is configured out of UML
[    0.040000] parse_chan_pair failed for device 15 : Configuration failed
[    0.040000] Console initialized on /dev/tty0
[    0.040000] console [tty0] enabled
[    0.040000] console [mc-1] enabled
[    0.040000]  ubda: unknown partition table
[    0.040000] VFS: Mounted root (hostfs filesystem) on device 0:11.
mount /mnt/btr/; rm -rf /mnt/btr/var_tmp/paludis/dev-lang-jhc-9999/
[    0.040000] device label PORTAGE devid 1 transid 17409 /dev/ubda
[    0.040000] btrfs: use lzo compression
[    0.040000] new update_space_info: 
[    0.040000] space_info has 0 free, is not full
[    0.040000] space_info total=0, used=0, pinned=0, reserved=0, may_use=0, readonly=0
[    0.040000] new update_space_info: 
[    0.040000] space_info has 0 free, is not full
[    0.040000] space_info total=0, used=0, pinned=0, reserved=0, may_use=0, readonly=0
[    0.040000] new update_space_info: 
[    0.040000] space_info has 0 free, is not full
[    0.040000] space_info total=0, used=0, pinned=0, reserved=0, may_use=0, readonly=0
[    0.040000] found update_space_info: 
[    0.040000] space_info has 4190208 free, is not full
[    0.040000] space_info total=4194304, used=4096, pinned=0, reserved=0, may_use=0, readonly=0
[    0.040000] found update_space_info: 
[    0.040000] space_info has 2662400 free, is not full
[    0.040000] space_info total=8388608, used=5726208, pinned=0, reserved=0, may_use=0, readonly=0
[    0.040000] found update_space_info: 
[    0.040000] space_info has 4165632 free, is not full
[    0.040000] space_info total=16777216, used=12611584, pinned=0, reserved=0, may_use=0, readonly=0
[    0.040000] found update_space_info: 
[    0.040000] space_info has 230006784 free, is not full
[    0.040000] space_info total=516816896, used=286810112, pinned=0, reserved=0, may_use=0, readonly=0
[    0.040000] found update_space_info: 
[    0.040000] space_info has 274923520 free, is not full
[    0.040000] space_info total=1016856576, used=741867520, pinned=0, reserved=0, may_use=0, readonly=65536
[    0.040000] found update_space_info: 
[    0.040000] space_info has 509603840 free, is not full
[    0.040000] space_info total=1516896256, used=1007226880, pinned=0, reserved=0, may_use=0, readonly=65536
[    0.040000] found update_space_info: 
[    0.040000] space_info has 960970752 free, is not full
[    0.040000] space_info total=2016935936, used=1055899648, pinned=0, reserved=0, may_use=0, readonly=65536
[    0.040000] found update_space_info: 
[    0.040000] space_info has 1266278400 free, is not full
[    0.040000] space_info total=2516975616, used=1250631680, pinned=0, reserved=0, may_use=0, readonly=65536
[    0.040000] found update_space_info: 
[    0.040000] space_info has 1431748608 free, is not full
[    0.040000] space_info total=3017015296, used=1585201152, pinned=0, reserved=0, may_use=0, readonly=65536
[    0.040000] found update_space_info: 
[    0.040000] space_info has 1931784192 free, is not full
[    0.040000] space_info total=3517054976, used=1585205248, pinned=0, reserved=0, may_use=0, readonly=65536
[    0.040000] found update_space_info: 
[    0.040000] space_info has 2431819776 free, is not full
[    0.040000] space_info total=4017094656, used=1585209344, pinned=0, reserved=0, may_use=0, readonly=65536
[    0.040000] found update_space_info: 
[    0.040000] space_info has 2884710400 free, is not full
[    0.040000] space_info total=4517134336, used=1632358400, pinned=0, reserved=0, may_use=0, readonly=65536
[    0.040000] found update_space_info: 
[    0.040000] space_info has 3364249600 free, is not full
[    0.040000] space_info total=4996726784, used=1632411648, pinned=0, reserved=0, may_use=0, readonly=65536
[    0.040000] btrfs_lookup_dir_item -> btrfs_match_dir_item_name
[    0.040000] btrfs_match_dir_item_name (name='default')
[    0.040000] btrfs_lookup_dir_item -> btrfs_match_dir_item_name
[    0.040000] btrfs_match_dir_item_name (name='var_tmp')
[    0.040000] btrfs_lookup_dir_item -> btrfs_match_dir_item_name
[    0.040000] btrfs_match_dir_item_name (name='paludis')
[    0.040000] btrfs_lookup_dir_item -> btrfs_match_dir_item_name
[    0.040000] btrfs_match_dir_item_name (name='dev-lang-jhc-9999')
[    0.040000] btrfs_lookup_dir_item -> btrfs_match_dir_item_name
[    0.040000] btrfs_match_dir_item_name (name='work')
[    0.040000] btrfs_lookup_dir_item -> btrfs_match_dir_item_name
[    0.040000] btrfs_match_dir_item_name (name='jhc-9999')
[    0.040000] btrfs_lookup_dir_item -> btrfs_match_dir_item_name
[    0.040000] btrfs_match_dir_item_name (name='ac-macros')
[    0.040000] btrfs_lookup_dir_item -> btrfs_match_dir_item_name
[    0.040000] btrfs_match_dir_item_name (name='ac_define_dir.m4')
[    0.040000] reserve_metadata_bytes: 
[    0.040000] space_info has 0 free, is not full
[    0.040000] space_info total=0, used=0, pinned=0, reserved=0, may_use=0, readonly=0
[    0.040000] reserve_metadata_bytes: consider unused=0
[    0.040000] shrink_delalloc: 
[    0.040000] space_info has 18446744073708568576 free, is not full
[    0.040000] space_info total=0, used=0, pinned=0, reserved=983040, may_use=0, readonly=0
[    0.040000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.050000] Switched to NOHz mode on CPU #0
[    0.050000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.240000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.250000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.260000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.270000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.280000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.290000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.300000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.310000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.320000] reserve_metadata_bytes: shrink_delalloc(num_bytes=983040) -> 0
[    0.320000] reserve_metadata_bytes: 
[    0.320000] space_info has 18446744073708568576 free, is not full
[    0.320000] space_info total=0, used=0, pinned=0, reserved=983040, may_use=0, readonly=0
[    0.320000] reserve_metadata_bytes: consider unused=983040
[    0.320000] shrink_delalloc: 
[    0.320000] space_info has 18446744073708568576 free, is not full
[    0.320000] space_info total=0, used=0, pinned=0, reserved=983040, may_use=0, readonly=0
[    0.320000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.330000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.340000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.350000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.360000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.370000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.380000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.390000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.400000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.410000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.420000] reserve_metadata_bytes: shrink_delalloc(num_bytes=2949120) -> 0
[    0.420000] reserve_metadata_bytes: 
[    0.420000] space_info has 18446744073708568576 free, is not full
[    0.420000] space_info total=0, used=0, pinned=0, reserved=983040, may_use=0, readonly=0
[    0.420000] reserve_metadata_bytes: consider unused=983040
[    0.420000] shrink_delalloc: 
[    0.420000] space_info has 18446744073708568576 free, is not full
[    0.420000] space_info total=0, used=0, pinned=0, reserved=983040, may_use=0, readonly=0
[    0.420000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.430000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.440000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.450000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.460000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.470000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.480000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.490000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.500000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.510000] shrink_delalloc: kick writeback_inodes_sb_nr_if_idle to free 0 pages (yet 0 bytes to wb).
[    0.520000] reserve_metadata_bytes: shrink_delalloc(num_bytes=3932160) -> 0
[    0.520000] btrfs_lookup_dir_item -> btrfs_match_dir_item_name
[    0.520000] btrfs_match_dir_item_name (name='ac_define_dir.m4')
[    0.520000] btrfs_match_dir_item_name (name='ac_define_dir.m4')
[    0.520000] __unlinking 'ac_define_dir.m4'
[    0.520000] reserve_metadata_bytes: 
[    0.520000] space_info has 0 free, is not full
[    0.520000] space_info total=0, used=0, pinned=0, reserved=0, may_use=0, readonly=0
[    0.520000] reserve_metadata_bytes: consider unused=0
[    0.520000] use_block_rsv (global metadata rsv) ret=-28
[    0.520000] btrfs_alloc_free_block: use_block_rsv error=-28
[    0.520000] __btrfs_cow_block: btrfs_alloc_free_block ret=-28
[    0.520000] 1. btrfs_search_slot ret=-28
[    0.520000] btrfs_lookup_dir_item: search slot failed: -28
[    0.520000] btrfs_lookup_dir_item: IS_ERR(di) = -28
[    0.520000] BUG: failure at /mnt/archive/src/linux-2.6/fs/btrfs/inode.c:2982/btrfs_unlink()!
[    0.520000] Kernel panic - not syncing: BUG!
[    0.520000] Call Trace: 
[    0.520000] 80fb7c78:  [<601ae895>] panic+0xea/0x1dc
[    0.520000] 80fb7c98:  [<601aea27>] printk+0xa0/0xa9
[    0.520000] 80fb7cf8:  [<600b91de>] btrfs_free_path+0x2a/0x2f
[    0.520000] 80fb7d38:  [<600dc01a>] btrfs_unlink_inode+0x4b/0x7c
[    0.520000] 80fb7d78:  [<600dc10f>] btrfs_unlink+0xc4/0xee
[    0.520000] 80fb7db8:  [<6007fccb>] vfs_unlink+0x55/0x8e
[    0.520000] 80fb7de8:  [<6007fdcc>] do_unlinkat+0xc8/0x156
[    0.520000] 80fb7e48:  [<6007818e>] sys_newlstat+0x29/0x34
[    0.520000] 80fb7ec8:  [<6007fe91>] sys_unlink+0x11/0x13
[    0.520000] 80fb7ed8:  [<600171f0>] handle_syscall+0x50/0x70
[    0.520000] 80fb7ef8:  [<60021af5>] userspace+0x30f/0x3c9
[    0.520000] 80fb7fc8:  [<600148c9>] fork_handler+0x62/0x69
[    0.520000] 
[    0.520000] 
[    0.520000] Pid: 160, comm: kill Not tainted 2.6.39-rc4+
[    0.520000] RIP: 0033:[<00000000005443a7>]
[    0.520000] RSP: 0000007fbf931cf8  EFLAGS: 00000246
[    0.520000] RAX: ffffffffffffffda RBX: 000000000086a010 RCX: ffffffffffffffff
[    0.520000] RDX: 0000007fbf931d00 RSI: 0000007fbf931d00 RDI: 000000000086a010
[    0.520000] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
[    0.520000] R10: 7263616d2d63612f R11: 0000000000000246 R12: 0000000000000000
[    0.520000] R13: 0000000040001010 R14: 000000000086a010 R15: 00000000ffffffff
[    0.520000] Call Trace: 
[    0.520000] 80fb7bf8:  [<60016cf1>] panic_exit+0x2f/0x45
[    0.520000] 80fb7c18:  [<60043621>] notifier_call_chain+0x5f/0x96
[    0.520000] 80fb7c68:  [<600436f7>] atomic_notifier_call_chain+0xf/0x11
[    0.520000] 80fb7c78:  [<601ae8b0>] panic+0x105/0x1dc
[    0.520000] 80fb7c98:  [<601aea27>] printk+0xa0/0xa9
[    0.520000] 80fb7cf8:  [<600b91de>] btrfs_free_path+0x2a/0x2f
[    0.520000] 80fb7d38:  [<600dc01a>] btrfs_unlink_inode+0x4b/0x7c
[    0.520000] 80fb7d78:  [<600dc10f>] btrfs_unlink+0xc4/0xee
[    0.520000] 80fb7db8:  [<6007fccb>] vfs_unlink+0x55/0x8e
[    0.520000] 80fb7de8:  [<6007fdcc>] do_unlinkat+0xc8/0x156
[    0.520000] 80fb7e48:  [<6007818e>] sys_newlstat+0x29/0x34
[    0.520000] 80fb7ec8:  [<6007fe91>] sys_unlink+0x11/0x13
[    0.520000] 80fb7ed8:  [<600171f0>] handle_syscall+0x50/0x70
[    0.520000] 80fb7ef8:  [<60021af5>] userspace+0x30f/0x3c9
[    0.520000] 80fb7fc8:  [<600148c9>] fork_handler+0x62/0x69
[    0.520000] 

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 198 bytes --]