Re: disk space caching generation missmatch

Previous thread: kernel BUG at fs/btrfs/inode.c:806 by Johannes Hirte on Wednesday, December 1, 2010 - 6:11 am. (6 messages)

Next thread: 800 GByte free, but "no space left" by Helmut Hullen on Thursday, December 2, 2010 - 11:23 am. (2 messages)
From: Johannes Hirte
Date: Wednesday, December 1, 2010 - 9:46 am

After enabling disk space caching I've observed several log entries like this:

btrfs: free space inode generation (0) did not match free space cache generation (169594) for block group 15464398848

I'm not sure, but it seems this happens on every reboot. Is this something to
worry about?

regards,
  Johannes
--

From: Josef Bacik
Date: Wednesday, December 1, 2010 - 10:40 am

So that usually means 1 of a couple of things

1) You didn't have space for us to save the free space cache
2) When trying to write out the cache we hit one of those cases where we would
deadlock so we couldn't write the cache out

It's nothing to worry about, it's doing what it is supposed to.  However I'd
like to know why we're not able to write out the cache.  Are you running close
to full?  Thanks,

Josef
--

From: Johannes Hirte
Date: Wednesday, December 1, 2010 - 12:56 pm

I think there should be enough free space:

df -h

Filesystem            Size  Used Avail Use% Mounted on
rootfs                 41G   29G  8.4G  78% /
/dev/root              41G   29G  8.4G  78% /
rc-svcdir             1.0M  112K  912K  11% /lib/rc/init.d
udev                   10M  284K  9.8M   3% /dev
shm                  1008M     0 1008M   0% /dev/shm
/dev/sda3             108G   90G   15G  87% /home

btrfs filesystem df /

Data: total=34.48GB, used=26.13GB
System, DUP: total=8.00MB, used=12.00KB
System: total=4.00MB, used=0.00
Metadata, DUP: total=2.75GB, used=1.26GB
Metadata: total=8.00MB, used=0.00

btrfs filesystem df /home

Data: total=88.01GB, used=84.84GB
System, DUP: total=8.00MB, used=20.00KB
System: total=4.00MB, used=0.00
Metadata, DUP: total=4.00GB, used=2.43GB
Metadata: total=8.00MB, used=0.00
--

From: Josef Bacik
Date: Wednesday, December 1, 2010 - 1:03 pm

Hmm well then we're hitting one of the other corner cases.  Can you run with
this debug thread and reboot.  Hopefully it will tell me why we're not saving
the free space cache. Thanks,

Josef

diff --git a/fs/btrfs/extent-tree.c b/fs/btrfs/extent-tree.c
index 87aae66..4fd5659 100644
--- a/fs/btrfs/extent-tree.c
+++ b/fs/btrfs/extent-tree.c
@@ -2794,13 +2794,17 @@ again:
 	if (i_size_read(inode) > 0) {
 		ret = btrfs_truncate_free_space_cache(root, trans, path,
 						      inode);
-		if (ret)
+		if (ret) {
+			printk(KERN_ERR "truncate free space cache failed for %llu, %d\n",
+			       block_group->key.objectid, ret);
 			goto out_put;
+		}
 	}
 
 	spin_lock(&block_group->lock);
 	if (block_group->cached != BTRFS_CACHE_FINISHED) {
 		spin_unlock(&block_group->lock);
+		printk(KERN_ERR "block group %llu not cached\n", block_group->key.objectid);
 		goto out_put;
 	}
 	spin_unlock(&block_group->lock);
@@ -2820,8 +2824,10 @@ again:
 	num_pages *= PAGE_CACHE_SIZE;
 
 	ret = btrfs_check_data_free_space(inode, num_pages);
-	if (ret)
+	if (ret) {
+		printk(KERN_ERR "not enough free space for cache %llu\n", block_group->key.objectid);
 		goto out_put;
+	}
 
 	ret = btrfs_prealloc_file_range_trans(inode, trans, 0, 0, num_pages,
 					      num_pages, num_pages,
diff --git a/fs/btrfs/free-space-cache.c b/fs/btrfs/free-space-cache.c
index 22ee0dc..0078172 100644
--- a/fs/btrfs/free-space-cache.c
+++ b/fs/btrfs/free-space-cache.c
@@ -511,6 +511,8 @@ int btrfs_write_out_cache(struct btrfs_root *root,
 	spin_lock(&block_group->lock);
 	if (block_group->disk_cache_state < BTRFS_DC_SETUP) {
 		spin_unlock(&block_group->lock);
+		printk(KERN_ERR "block group %llu, wrong dcs %d\n", block_group->key.objectid,
+		       block_group->disk_cache_state);
 		return 0;
 	}
 	spin_unlock(&block_group->lock);
@@ -520,6 +522,7 @@ int btrfs_write_out_cache(struct btrfs_root *root,
 		return 0;
 
 	if (!i_size_read(inode)) {
+		printk(KERN_ERR "no allocated space for block group ...
From: Johannes Hirte
Date: Wednesday, December 1, 2010 - 2:22 pm

This is from dmesg shortly after reboot with the debug patch:

btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache generation (177986) for block group 5398069248
btrfs: free space inode generation (0) did not match free space cache generation (177986) for block group 5398069248
block group 5398069248 not cached
block group 19893583872 not cached
no allocated space for block group 5398069248
no allocated space for block group 19893583872
btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode ...
From: Johannes Hirte
Date: Wednesday, December 1, 2010 - 2:40 pm

Ok, now there are some "problem writing out block group cache" too. Here is all
btrfs related dmesg output again (after 23min uptime):

btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache generation (177986) for block group 5398069248
btrfs: free space inode generation (0) did not match free space cache generation (177986) for block group 5398069248
block group 5398069248 not cached
block group 19893583872 not cached
no allocated space for block group 5398069248
no allocated space for block group 19893583872
btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache generation (116974) for block group 14256439296
btrfs: free space inode generation (0) did not match free space cache ...
From: Josef Bacik
Date: Thursday, December 2, 2010 - 1:34 pm

Ok it doesn't look like theres an actual problem, we're just being sub-optimal.
Take out the other patch and apply this one, boot into that kernel and then
reboot and then give me the dmesg.  The thing is we are marking non-cached block
groups as being setup, but they really aren't, so we error out when we try to
write out the block group.  This isn't wrong, it's just crappy since we know we
wont be able to write the things out anyway.  So just mark the thing as written
so we dont even try.  The other cases appear to be where the block group is
empty, so we dont need to write anything out, but because of where I have the
check it makes it seem like an error, so I just moved the check up to make it
simpler.  I also thing the "free space inode generation did not match" messages
should only happen once, but are getting kicked out everytime something gets
removed, which is because the block group is not marked as cleared, so we just
need to go to free_cache so it gets marked to be cleared so we don't get the
same message over and over again.  Let me know how this works out for you,
thanks,

Josef


diff --git a/fs/btrfs/extent-tree.c b/fs/btrfs/extent-tree.c
index 87aae66..5ee883b 100644
--- a/fs/btrfs/extent-tree.c
+++ b/fs/btrfs/extent-tree.c
@@ -2794,13 +2794,19 @@ again:
 	if (i_size_read(inode) > 0) {
 		ret = btrfs_truncate_free_space_cache(root, trans, path,
 						      inode);
-		if (ret)
+		if (ret) {
+			printk(KERN_ERR "truncate free space cache failed for %llu, %d\n",
+			       block_group->key.objectid, ret);
 			goto out_put;
+		}
 	}
 
 	spin_lock(&block_group->lock);
 	if (block_group->cached != BTRFS_CACHE_FINISHED) {
+		/* Not cached, don't bother trying to write something out */
+		block_group->disk_cache_state = BTRFS_DC_WRITTEN;
 		spin_unlock(&block_group->lock);
+		printk(KERN_ERR "block group %llu not cached\n", block_group->key.objectid);
 		goto out_put;
 	}
 	spin_unlock(&block_group->lock);
@@ -2820,13 +2826,20 @@ again:
 	num_pages *= ...
From: C Anthony Risinger
Date: Thursday, December 2, 2010 - 2:45 pm

misspelling:

block_gruop - > block_group

just noticed this glancing thru...

C Anthony
--

From: Johannes Hirte
Date: Thursday, December 2, 2010 - 5:07 pm

Here it comes:

Initializing cgroup subsys cpuset
Linux version 2.6.37-rc4-space-cache-dbg-00022-g620731b-dirty (root@netbook) (gcc version 4.5.1 (Gentoo 4.5.1-r1 p1.3, pie-0.4.5) ) #126 SMP PREEMPT Fri Dec 3 00:40:04 CET 2010
Atom PSE erratum detected, BIOS microcode update recommended
BIOS-provided physical RAM map:
 BIOS-e820: 0000000000000000 - 000000000009f800 (usable)
 BIOS-e820: 000000000009f800 - 00000000000a0000 (reserved)
 BIOS-e820: 00000000000dc000 - 00000000000e4000 (reserved)
 BIOS-e820: 00000000000e8000 - 0000000000100000 (reserved)
 BIOS-e820: 0000000000100000 - 000000007f6d0000 (usable)
 BIOS-e820: 000000007f6d0000 - 000000007f6e2000 (ACPI data)
 BIOS-e820: 000000007f6e2000 - 000000007f6e3000 (ACPI NVS)
 BIOS-e820: 000000007f6e3000 - 0000000080000000 (reserved)
 BIOS-e820: 00000000e0000000 - 00000000f0000000 (reserved)
 BIOS-e820: 00000000fec00000 - 00000000fec10000 (reserved)
 BIOS-e820: 00000000fed00000 - 00000000fed00400 (reserved)
 BIOS-e820: 00000000fed14000 - 00000000fed1a000 (reserved)
 BIOS-e820: 00000000fed1c000 - 00000000fed90000 (reserved)
 BIOS-e820: 00000000fee00000 - 00000000fee01000 (reserved)
 BIOS-e820: 00000000ff000000 - 0000000100000000 (reserved)
NX (Execute Disable) protection: active
DMI present.
DMI: M912/M912, BIOS R02 05/04/2009
e820 update range: 0000000000000000 - 0000000000010000 (usable) ==> (reserved)
e820 remove range: 00000000000a0000 - 0000000000100000 (usable)
last_pfn = 0x7f6d0 max_arch_pfn = 0x1000000
MTRR default type: uncachable
MTRR fixed ranges enabled:
  00000-9FFFF write-back
  A0000-BFFFF uncachable
  C0000-CFFFF write-protect
  D0000-DFFFF uncachable
  E0000-FFFFF write-protect
MTRR variable ranges enabled:
  0 base 000000000 mask 080000000 write-back
  1 base 07F700000 mask 0FFF00000 uncachable
  2 base 07F800000 mask 0FF800000 uncachable
  3 disabled
  4 disabled
  5 disabled
  6 disabled
  7 disabled
x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106
Scanning 0 areas for low memory ...
From: C Anthony Risinger
Date: Thursday, December 2, 2010 - 5:44 pm

Did you fix that typo I posted?

C Anthony [mobile]

On Dec 2, 2010, at 6:05 PM, Johannes Hirte <johannes.hirte@fem.tu-ilmenau.de
--

From: Johannes Hirte
Date: Thursday, December 2, 2010 - 5:57 pm

Yes, without fix it wouldn't compile.

regards,
  Johannes
--

From: Josef Bacik
Date: Friday, December 3, 2010 - 11:14 am

Perfect, thats much better.  Thanks for bringing this up.

Josef
--

Previous thread: kernel BUG at fs/btrfs/inode.c:806 by Johannes Hirte on Wednesday, December 1, 2010 - 6:11 am. (6 messages)

Next thread: 800 GByte free, but "no space left" by Helmut Hullen on Thursday, December 2, 2010 - 11:23 am. (2 messages)