[PATCH 2/2] btrfs-progs: check: enhanced progress indicator

[Stéphane Lesimple]

We reuse the task_position enum and task_ctx struct of the original progress
indicator, adding more values and fields for our needs.

Then add hooks in all steps of the check to properly record progress.

Signed-off-by: Stéphane Lesimple 
---
 check/main.c| 176 ++--
 check/mode-common.h |  20 ++
 check/mode-lowmem.c |   1 +
 convert/main.c  |   2 +-
 qgroup-verify.c |   7 +++
 qgroup-verify.h |   2 +
 task-utils.c|   8 ++-
 task-utils.h|   3 +-
 8 files changed, 154 insertions(+), 65 deletions(-)

diff --git a/check/main.c b/check/main.c
index 3190b5d..bb3ebea 100644
--- a/check/main.c
+++ b/check/main.c
@@ -25,6 +25,7 @@
 #include 
 #include 
 #include 
+#include 
 #include "ctree.h"
 #include "volumes.h"
 #include "repair.h"
@@ -47,20 +48,6 @@
 #include "check/mode-original.h"
 #include "check/mode-lowmem.h"
 
-enum task_position {
-   TASK_EXTENTS,
-   TASK_FREE_SPACE,
-   TASK_FS_ROOTS,
-   TASK_NOTHING, /* have to be the last element */
-};
-
-struct task_ctx {
-   int progress_enabled;
-   enum task_position tp;
-
-   struct task_info *info;
-};
-
 u64 bytes_used = 0;
 u64 total_csum_bytes = 0;
 u64 total_btree_bytes = 0;
@@ -72,6 +59,7 @@ u64 data_bytes_referenced = 0;
 LIST_HEAD(duplicate_extents);
 LIST_HEAD(delete_items);
 int no_holes = 0;
+static int is_free_space_tree = 0;
 int init_extent_tree = 0;
 int check_data_csum = 0;
 struct btrfs_fs_info *global_info;
@@ -173,28 +161,48 @@ static int compare_extent_backref(struct rb_node *node1, 
struct rb_node *node2)
return compare_tree_backref(node1, node2);
 }
 
+static void print_status_check_line(void *p)
+{
+   struct task_ctx *priv = p;
+   char *task_position_string[] = {
+   "[1/7] checking root items ",
+   "[2/7] checking extents",
+   is_free_space_tree ?
+   "[3/7] checking free space tree":
+   "[3/7] checking free space cache   ",
+   "[4/7] checking fs roots   ",
+   check_data_csum ?
+   "[5/7] checking csums against data ":
+   "[5/7] checking csums (without verifying data) ",
+   "[6/7] checking root refs  ",
+   "[7/7] checking quota groups   ",
+   };
+
+   time_t elapsed = time(NULL) - priv->start_time;
+   int hours   = elapsed / 3600;
+   elapsed-= hours   * 3600;
+   int minutes = elapsed / 60;
+   elapsed-= minutes * 60;
+   int seconds = elapsed;
+   printf("%s (%d:%02d:%02d elapsed", task_position_string[priv->tp], 
hours, minutes, seconds);
+   if (priv->item_count > 0)
+   printf(", %llu items checked)\r", priv->item_count);
+   else
+   printf(")\r");
+   fflush(stdout);
+}
 
 static void *print_status_check(void *p)
 {
struct task_ctx *priv = p;
-   const char work_indicator[] = { '.', 'o', 'O', 'o' };
-   uint32_t count = 0;
-   static char *task_position_string[] = {
-   "checking extents",
-   "checking free space cache",
-   "checking fs roots",
-   };
 
-   task_period_start(priv->info, 1000 /* 1s */);
+   task_period_start(priv->info, 50);
 
if (priv->tp == TASK_NOTHING)
return NULL;
 
while (1) {
-   printf("%s [%c]\r", task_position_string[priv->tp],
-   work_indicator[count % 4]);
-   count++;
-   fflush(stdout);
+   print_status_check_line(p);
task_period_wait(priv->info);
}
return NULL;
@@ -202,6 +210,7 @@ static void *print_status_check(void *p)
 
 static int print_status_return(void *p)
 {
+   print_status_check_line(p);
printf("\n");
fflush(stdout);
 
@@ -2942,6 +2951,7 @@ static int check_root_refs(struct btrfs_root *root,
loop = 0;
cache = search_cache_extent(root_cache, 0);
while (1) {
+   ctx.item_count++;
if (!cache)
break;
rec = container_of(cache, struct root_record, cache);
@@ -3263,6 +3273,7 @@ static int check_fs_root(struct btrfs_root *root,
}
 
while (1) {
+   ctx.item_count++;
wret = walk_down_tree(root, , wc, , );
if (wret < 0)
ret = wret;
@@ -3340,11 +3351,6 @@ static int check

[PATCH 1/2] btrfs-progs: fix nanosecs in task_period_start

[Stéphane Lesimple]

This is a single-line fix on the preexisting task_period_start function.

Signed-off-by: Stéphane Lesimple 
---
 task-utils.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/task-utils.c b/task-utils.c
index 12b0002..284cbb3 100644
--- a/task-utils.c
+++ b/task-utils.c
@@ -102,7 +102,7 @@ int task_period_start(struct task_info *info, unsigned int 
period_ms)
info->periodic.wakeups_missed = 0;
 
sec = period_ms / 1000;
-   ns = (period_ms - (sec * 1000)) * 1000;
+   ns = (period_ms - (sec * 1000)) * 1000 * 1000;
itval.it_interval.tv_sec = sec;
itval.it_interval.tv_nsec = ns;
itval.it_value.tv_sec = sec;
-- 
2.7.4

--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

[PATCH 0/2] btrfs-progs: check: enhanced progress indicator

[Stéphane Lesimple]

This patch replaces the current ".oOo."-style progress indicator of
btrfs check (-p), by a more helpful live indication of the check progress.
I've been using it on a custom btrfs-progs version since 2015.

Here's how the output looks like on a 22 Tb 5-disk RAID1 FS:

# btrfs check -p /dev/mapper/luks-ST1VN0004-
Opening filesystem to check...
Checking filesystem on /dev/mapper/luks-ST1VN0004-
UUID: ----
[1/7] checking extents   (0:20:21 elapsed, 950958 items checked)
[2/7] checking root items(0:01:29 elapsed, 15121 items checked)
[3/7] checking free space cache  (0:00:11 elapsed, 4928 items checked)
[4/7] checking fs roots  (0:51:31 elapsed, 600892 items checked)
[5/7] checking csums (0:14:35 elapsed, 754522 items checked)
[6/7] checking root refs (0:00:00 elapsed, 232 items checked)
[7/7] checking quota groups skipped (not enabled on this FS)
found 5286458060800 bytes used, no error found

The code is also viewable at https://github.com/kdave/btrfs-progs/pull/69

Stéphane Lesimple (2):
  btrfs-progs: fix nanosecs in task_period_start
  btrfs-progs: check: enhanced progress indicator

 check/main.c| 176 ++--
 check/mode-common.h |  20 ++
 check/mode-lowmem.c |   1 +
 convert/main.c  |   2 +-
 qgroup-verify.c |   7 +++
 qgroup-verify.h |   2 +
 task-utils.c|  10 ++-
 task-utils.h|   3 +-
 8 files changed, 155 insertions(+), 66 deletions(-)

-- 
2.7.4

--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

btrfs-progs: enhanced btrfsck progress patch proposition

[Stéphane Lesimple]

Hi,

I've been forking btrfs-progs locally to add an enhanced progress 
indicator, based on the work from Silvio Fricke posted here in 
September. I'm using it routinely, it has been of help when I was 
debugging my multi-Tb btrfs system, where I often had to use btrfs 
check. So I thought it might be of interest to others.


The patch replaces the .oOo. progress indicator with a count of the 
walked items (depending on the "thing" being inspected, this way if the 
walks stops or there's an infinite loop somewhere, you'll notice), adds 
an elapsed time indicator, and a step counter (currently 6).


Once you're used to your FS, you'll know roughly how many remaining time 
to expect. Here's how it looks like:


Opening filesystem to check...
Checking filesystem on /dev/mapper/luks-WD30EZRX-WCAWZ3013164
UUID: 428b20da-dcb1-403e-b407-ba984fd07ebd
[1/6] checking extents (0:00:59 elapsed, 199559 chunk items checked)
[2/6] checking free space cache (0:00:30 elapsed, 2547 cache objects 
checked)

[3/6] checking fs roots (0:02:33 elapsed, 19731 tree blocks checked)
[4/6] checking csums (0:01:37 elapsed, 391340 csums checked)
[5/6] checking root refs (0:00:00 elapsed, 7 root refs checked)
[6/6] checking quota groups skipped (not enabled on this FS)
found 2786490501673 bytes used err is 0
total csum bytes: 2717987856
total tree bytes: 3270934528
total fs tree bytes: 324255744
total extent tree bytes: 35897344
btree space waste bytes: 208202162
file data blocks allocated: 2783900614656
 referenced 2783900614656
btrfs-progs v4.2.3-dirty

It's available here https://github.com/speed47/btrfs-progs/tree/progress

Or, alternatively:

$ git clone https://github.com/speed47/btrfs-progs.git
$ cd btrfs-progs
$ git checkout origin/progress

The master branch is the kdave's one.
The patch is kind of hacky (especially for the qgroup step, which I'm 
not proud of), but if it builds interest here, I'll clean it up and post 
it the right way to the mailing-list.


Regards,

--
Stéphane.
--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH] Btrfs: fix regression when running delayed references

[Stéphane Lesimple]

Le 2015-10-23 12:11, Filipe Manana a écrit :
On Fri, Oct 23, 2015 at 12:03 AM, Filipe Manana <fdman...@kernel.org> 
wrote:

On Thu, Oct 22, 2015 at 11:38 PM, Stéphane Lesimple
<stephane_bt...@lesimple.fr> wrote:

[ ... thread cleanup ... ]

Don't hesitate to ask if you need me to debug or even ftrace 
something.



Thanks Stéphane. I haven't seen that crash yet (still running tests
for 2 consecutive days now).
Can you please try the following patch, which works on top of mine,
and enable ftrace before running balance:

Debug patch:  https://friendpaste.com/5s3dItRpcpq3dH1E4KUJor

Enable ftrace:

$ echo > /sys/kernel/debug/tracing/trace
$ echo "nop" > /sys/kernel/debug/tracing/current_tracer
$ echo 10 > /sys/kernel/debug/tracing/buffer_size_kb   # if
you can use larger buffer size, even better
$ echo > /sys/kernel/debug/tracing/set_ftrace_filter
$ echo 1 > /sys/kernel/debug/tracing/tracing_on

$ run balance... wait until it finishes with IO error or the
patch's printk message shows up in dmesg/syslog

$ echo 0 > /sys/kernel/debug/tracing/tracing_on

$ cat /sys/kernel/debug/tracing/trace > some_file.txt

Then send is some_file.txt for debugging, hopefully it will give 
some

useful information. Note that it might produce tons of messages,
depending on how long it takes for you to hit the BUG_ON.

Thanks a lot for this.



I'm compiling it now (using your v2 of the friendpaste diff).

I took the liberty to add a tracing_off() right before the return 
-EIO

so that the trace tail ends exactly at the right place.

Last time I tried to use ftrace to diagnose the bug we're trying to
fix, the system crashes so hard that usually it's complicated to get
the trace contents written somewhere before the system is unusable.
But I'll eventually work around it by using
/sys/kernel/debug/tracing/trace_pipe to send the trace live to 
another

machine over the LAN.

This series of bugs are so easy to trigger on my system that we'll
hopefully get something useful out of the trace. I guess that's a 
good

thing !



So, this time it took a little over an hour to get the crash, but it 
did

reach the -EIO condition eventually.
The ftrace log (2M gzipped) is available here :
http://www.speed47.net/tmp2/btrfs-4.3rc6p7463161-ftrace1.log.gz

The associated kernel log is as follows :

[ 2880.178589] INFO: task btrfs-transacti:7358 blocked for more than 
120

seconds.
[ 2880.178600]   Not tainted 4.3.0-rc6p7463161+ #3
[ 2880.178603] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables

this message.
[ 3088.829429] Out of memory: Kill process 9449 (df-complex2simp) 
score 246

or sacrifice child
[ 3088.829435] Killed process 9449 (df-complex2simp) 
total-vm:964732kB,

anon-rss:943764kB, file-rss:0kB
[ 3600.197642] INFO: task btrfs-transacti:7358 blocked for more than 
120

seconds.
[ 3600.197657]   Not tainted 4.3.0-rc6p7463161+ #3
[ 3600.197660] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables

this message.
[ 3840.204146] INFO: task btrfs-transacti:7358 blocked for more than 
120

seconds.
[ 3840.204180]   Not tainted 4.3.0-rc6p7463161+ #3
[ 3840.204219] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables

this message.
[ 3993.671982] Out of memory: Kill process 11357 (df-complex2simp) 
score 227

or sacrifice child
[ 3993.671989] Killed process 11357 (df-complex2simp) 
total-vm:891608kB,

anon-rss:870704kB, file-rss:60kB
[ 4080.210324] INFO: task btrfs-transacti:7358 blocked for more than 
120

seconds.
[ 4080.210336]   Not tainted 4.3.0-rc6p7463161+ #3
[ 4080.210339] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables

this message.
[ 4320.215635] INFO: task btrfs-transacti:7358 blocked for more than 
120

seconds.
[ 4320.215662]   Not tainted 4.3.0-rc6p7463161+ #3
[ 4320.215667] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables

this message.
[ 4560.221119] INFO: task btrfs-transacti:7358 blocked for more than 
120

seconds.
[ 4560.221146]   Not tainted 4.3.0-rc6p7463161+ #3
[ 4560.221148] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables

this message.
[ 4800.226884] INFO: task btrfs-transacti:7358 blocked for more than 
120

seconds.
[ 4800.226898]   Not tainted 4.3.0-rc6p7463161+ #3
[ 4800.226902] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables

this message.
[ 4890.116131] Out of memory: Kill process 13377 (df-complex2simp) 
score 207

or sacrifice child
[ 4890.116138] Killed process 13377 (df-complex2simp) 
total-vm:834976kB,

anon-rss:793272kB, file-rss:48kB
[ 5785.793580] Out of memory: Kill process 15285 (df-complex2simp) 
score 201

or sacrifice child
[ 5785.793586] Killed process 15285 (df-complex2simp) 
total-vm:802208kB,

anon-rss:772172kB, file-rss:4kB
[ 6480.269728] INFO: task btrfs-transacti:7358 blocked for more than 
120

seconds.
[ 6480.269

Re: [PATCH] Btrfs: fix regression when running delayed references

[Stéphane Lesimple]

Le 2015-10-23 12:59, Stéphane Lesimple a écrit :

Le 2015-10-23 12:11, Filipe Manana a écrit :
On Fri, Oct 23, 2015 at 12:03 AM, Filipe Manana <fdman...@kernel.org> 
wrote:

On Thu, Oct 22, 2015 at 11:38 PM, Stéphane Lesimple
<stephane_bt...@lesimple.fr> wrote:

[ ... thread cleanup ... ]

Don't hesitate to ask if you need me to debug or even ftrace 
something.



Thanks Stéphane. I haven't seen that crash yet (still running 
tests

for 2 consecutive days now).
Can you please try the following patch, which works on top of 
mine,

and enable ftrace before running balance:

Debug patch:  https://friendpaste.com/5s3dItRpcpq3dH1E4KUJor

Enable ftrace:

$ echo > /sys/kernel/debug/tracing/trace
$ echo "nop" > /sys/kernel/debug/tracing/current_tracer
$ echo 10 > /sys/kernel/debug/tracing/buffer_size_kb   # 
if

you can use larger buffer size, even better
$ echo > /sys/kernel/debug/tracing/set_ftrace_filter
$ echo 1 > /sys/kernel/debug/tracing/tracing_on

$ run balance... wait until it finishes with IO error or the
patch's printk message shows up in dmesg/syslog

$ echo 0 > /sys/kernel/debug/tracing/tracing_on

$ cat /sys/kernel/debug/tracing/trace > some_file.txt

Then send is some_file.txt for debugging, hopefully it will give 
some

useful information. Note that it might produce tons of messages,
depending on how long it takes for you to hit the BUG_ON.

Thanks a lot for this.



I'm compiling it now (using your v2 of the friendpaste diff).

I took the liberty to add a tracing_off() right before the return 
-EIO

so that the trace tail ends exactly at the right place.

Last time I tried to use ftrace to diagnose the bug we're trying to
fix, the system crashes so hard that usually it's complicated to 
get

the trace contents written somewhere before the system is unusable.
But I'll eventually work around it by using
/sys/kernel/debug/tracing/trace_pipe to send the trace live to 
another

machine over the LAN.

This series of bugs are so easy to trigger on my system that we'll
hopefully get something useful out of the trace. I guess that's a 
good

thing !



So, this time it took a little over an hour to get the crash, but it 
did

reach the -EIO condition eventually.
The ftrace log (2M gzipped) is available here :
http://www.speed47.net/tmp2/btrfs-4.3rc6p7463161-ftrace1.log.gz

The associated kernel log is as follows :

[ 2880.178589] INFO: task btrfs-transacti:7358 blocked for more than 
120

seconds.
[ 2880.178600]   Not tainted 4.3.0-rc6p7463161+ #3
[ 2880.178603] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables

this message.
[ 3088.829429] Out of memory: Kill process 9449 (df-complex2simp) 
score 246

or sacrifice child
[ 3088.829435] Killed process 9449 (df-complex2simp) 
total-vm:964732kB,

anon-rss:943764kB, file-rss:0kB
[ 3600.197642] INFO: task btrfs-transacti:7358 blocked for more than 
120

seconds.
[ 3600.197657]   Not tainted 4.3.0-rc6p7463161+ #3
[ 3600.197660] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables

this message.
[ 3840.204146] INFO: task btrfs-transacti:7358 blocked for more than 
120

seconds.
[ 3840.204180]   Not tainted 4.3.0-rc6p7463161+ #3
[ 3840.204219] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables

this message.
[ 3993.671982] Out of memory: Kill process 11357 (df-complex2simp) 
score 227

or sacrifice child
[ 3993.671989] Killed process 11357 (df-complex2simp) 
total-vm:891608kB,

anon-rss:870704kB, file-rss:60kB
[ 4080.210324] INFO: task btrfs-transacti:7358 blocked for more than 
120

seconds.
[ 4080.210336]   Not tainted 4.3.0-rc6p7463161+ #3
[ 4080.210339] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables

this message.
[ 4320.215635] INFO: task btrfs-transacti:7358 blocked for more than 
120

seconds.
[ 4320.215662]   Not tainted 4.3.0-rc6p7463161+ #3
[ 4320.215667] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables

this message.
[ 4560.221119] INFO: task btrfs-transacti:7358 blocked for more than 
120

seconds.
[ 4560.221146]   Not tainted 4.3.0-rc6p7463161+ #3
[ 4560.221148] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables

this message.
[ 4800.226884] INFO: task btrfs-transacti:7358 blocked for more than 
120

seconds.
[ 4800.226898]   Not tainted 4.3.0-rc6p7463161+ #3
[ 4800.226902] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables

this message.
[ 4890.116131] Out of memory: Kill process 13377 (df-complex2simp) 
score 207

or sacrifice child
[ 4890.116138] Killed process 13377 (df-complex2simp) 
total-vm:834976kB,

anon-rss:793272kB, file-rss:48kB
[ 5785.793580] Out of memory: Kill process 15285 (df-complex2simp) 
score 201

or sacrifice child
[ 5785.793586] Killed process 15285 (df-complex2simp) 
total-vm:802208kB,

anon-rss:772172kB, file-rss:4kB
[ 6480.269728] INFO: task btrfs-transac

Re: [PATCH] Btrfs: fix regression when running delayed references

[Stéphane Lesimple]

Le 2015-10-22 19:03, Filipe Manana a écrit :

On Thu, Oct 22, 2015 at 3:58 PM, Stéphane Lesimple
<stephane_bt...@lesimple.fr> wrote:

Le 2015-10-22 11:47, Filipe Manana a écrit :


On Thu, Oct 22, 2015 at 10:43 AM, Filipe Manana <fdman...@kernel.org>
wrote:


On Thu, Oct 22, 2015 at 10:32 AM, Qu Wenruo 
<quwen...@cn.fujitsu.com>

wrote:




 wrote on 2015/10/22 09:47 +0100:



From: Filipe Manana <fdman...@suse.com>

In the kernel 4.2 merge window we had a refactoring/rework of the
delayed
references implementation in order to fix certain problems with
qgroups.
However that rework introduced one more regression that leads to 
the

following trace when running delayed references for metadata:

[35908.064664] kernel BUG at fs/btrfs/extent-tree.c:1832!
[35908.065201] invalid opcode:  [#1] PREEMPT SMP 
DEBUG_PAGEALLOC
[35908.065201] Modules linked in: dm_flakey dm_mod btrfs 
crc32c_generic

xor raid6_pq nfsd auth_rpcgss oid_registry nfs_acl nfs lockd grace
fscache
sunrpc loop fuse parport_pc psmouse i2
[35908.065201] CPU: 14 PID: 15014 Comm: kworker/u32:9 Tainted: G
W
4.3.0-rc5-btrfs-next-17+ #1
[35908.065201] Hardware name: QEMU Standard PC (i440FX + PIIX, 
1996),

BIOS
rel-1.8.1-0-g4adadbd-20150316_085822-nilsson.home.kraxel.org 
04/01/2014
[35908.065201] Workqueue: btrfs-extent-refs 
btrfs_extent_refs_helper

[btrfs]
[35908.065201] task: 880114b7d780 ti: 88010c4c8000 
task.ti:

88010c4c8000
[35908.065201] RIP: 0010:[]  
[]

insert_inline_extent_backref+0x52/0xb1 [btrfs]
[35908.065201] RSP: 0018:88010c4cbb08  EFLAGS: 00010293
[35908.065201] RAX:  RBX: 88008a661000 RCX:

[35908.065201] RDX: a04dd58f RSI: 0001 RDI:

[35908.065201] RBP: 88010c4cbb40 R08: 1000 R09:
88010c4cb9f8
[35908.065201] R10:  R11: 002c R12:

[35908.065201] R13: 88020a74c578 R14:  R15:

[35908.065201] FS:  () 
GS:88023edc()

knlGS:
[35908.065201] CS:  0010 DS:  ES:  CR0: 8005003b
[35908.065201] CR2: 015e8708 CR3: 000102185000 CR4:
06e0
[35908.065201] Stack:
[35908.065201]  88010c4cbb18 0f37 88020a74c578
88015a408000
[35908.065201]  880154a44000  0005
88010c4cbbd8
[35908.065201]  a0492b9a 0005 

[35908.065201] Call Trace:
[35908.065201]  [] 
__btrfs_inc_extent_ref+0x8b/0x208

[btrfs]
[35908.065201]  [] ?
__btrfs_run_delayed_refs+0x4d4/0xd33 [btrfs]
[35908.065201]  []
__btrfs_run_delayed_refs+0xafa/0xd33
[btrfs]
[35908.065201]  [] ?
join_transaction.isra.10+0x25/0x41f
[btrfs]
[35908.065201]  [] ?
join_transaction.isra.10+0xa8/0x41f
[btrfs]
[35908.065201]  [] 
btrfs_run_delayed_refs+0x75/0x1dd

[btrfs]
[35908.065201]  [] 
delayed_ref_async_start+0x3c/0x7b

[btrfs]
[35908.065201]  [] 
normal_work_helper+0x14c/0x32a

[btrfs]
[35908.065201]  [] 
btrfs_extent_refs_helper+0x12/0x14

[btrfs]
[35908.065201]  [] process_one_work+0x24a/0x4ac
[35908.065201]  [] worker_thread+0x206/0x2c2
[35908.065201]  [] ? rescuer_thread+0x2cb/0x2cb
[35908.065201]  [] ? rescuer_thread+0x2cb/0x2cb
[35908.065201]  [] kthread+0xef/0xf7
[35908.065201]  [] ? kthread_parkme+0x24/0x24
[35908.065201]  [] ret_from_fork+0x3f/0x70
[35908.065201]  [] ? kthread_parkme+0x24/0x24
[35908.065201] Code: 6a 01 41 56 41 54 ff 75 10 41 51 4d 89 c1 49 
89 c8

48
8d 4d d0 e8 f6 f1 ff ff 48 83 c4 28 85 c0 75 2c 49 81 fc ff 00 00 
00 77

02
<0f> 0b 4c 8b 45 30 8b 4d 28 45 31
[35908.065201] RIP  []
insert_inline_extent_backref+0x52/0xb1 [btrfs]
[35908.065201]  RSP 
[35908.310885] ---[ end trace fe4299baf0666457 ]---

This happens because the new delayed references code no longer 
merges
delayed references that have different sequence values. The 
following

steps are an example sequence leading to this issue:

1) Transaction N starts, fs_info->tree_mod_seq has value 0;

2) Extent buffer (btree node) A is allocated, delayed reference 
Ref1

for
bytenr A is created, with a value of 1 and a seq value of 0;

3) fs_info->tree_mod_seq is incremented to 1;

4) Extent buffer A is deleted through btrfs_del_items(), which 
calls
btrfs_del_leaf(), which in turn calls btrfs_free_tree_block(). 
The
later returns the metadata extent associated to extent buffer 
A to
the free space cache (the range is not pinned), because the 
extent
buffer was created in the current transaction (N) and 
writeback

never
happened for the extent buffer (flag BTRFS_HEADER_FLAG_WRITTEN 
not

set
in the extent buffer).
This creates the delayed reference Ref2 for bytenr A, with a 
value

of -1 and a seq value of 1;

5) Delayed reference Ref2 is not merged with Ref1 when we create 
it,

because they have different sequence numbers (decided at
add_delayed_ref_tail

Re: [PATCH] Btrfs: fix regression when running delayed references

[Stéphane Lesimple]

[ ... thread cleanup ... ]
Don't hesitate to ask if you need me to debug or even ftrace 
something.


Thanks Stéphane. I haven't seen that crash yet (still running tests
for 2 consecutive days now).
Can you please try the following patch, which works on top of mine,
and enable ftrace before running balance:

Debug patch:  https://friendpaste.com/5s3dItRpcpq3dH1E4KUJor

Enable ftrace:

$ echo > /sys/kernel/debug/tracing/trace
$ echo "nop" > /sys/kernel/debug/tracing/current_tracer
$ echo 10 > /sys/kernel/debug/tracing/buffer_size_kb   # if
you can use larger buffer size, even better
$ echo > /sys/kernel/debug/tracing/set_ftrace_filter
$ echo 1 > /sys/kernel/debug/tracing/tracing_on

$ run balance... wait until it finishes with IO error or the
patch's printk message shows up in dmesg/syslog

$ echo 0 > /sys/kernel/debug/tracing/tracing_on

$ cat /sys/kernel/debug/tracing/trace > some_file.txt

Then send is some_file.txt for debugging, hopefully it will give some
useful information. Note that it might produce tons of messages,
depending on how long it takes for you to hit the BUG_ON.

Thanks a lot for this.


I'm compiling it now (using your v2 of the friendpaste diff).

I took the liberty to add a tracing_off() right before the return -EIO
so that the trace tail ends exactly at the right place.

Last time I tried to use ftrace to diagnose the bug we're trying to
fix, the system crashes so hard that usually it's complicated to get
the trace contents written somewhere before the system is unusable.
But I'll eventually work around it by using
/sys/kernel/debug/tracing/trace_pipe to send the trace live to another
machine over the LAN.

This series of bugs are so easy to trigger on my system that we'll
hopefully get something useful out of the trace. I guess that's a good
thing !


So, this time it took a little over an hour to get the crash, but it did 
reach the -EIO condition eventually.

The ftrace log (2M gzipped) is available here :
http://www.speed47.net/tmp2/btrfs-4.3rc6p7463161-ftrace1.log.gz

The associated kernel log is as follows :

[ 2880.178589] INFO: task btrfs-transacti:7358 blocked for more than 120 
seconds.

[ 2880.178600]   Not tainted 4.3.0-rc6p7463161+ #3
[ 2880.178603] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables this message.
[ 3088.829429] Out of memory: Kill process 9449 (df-complex2simp) score 
246 or sacrifice child
[ 3088.829435] Killed process 9449 (df-complex2simp) total-vm:964732kB, 
anon-rss:943764kB, file-rss:0kB
[ 3600.197642] INFO: task btrfs-transacti:7358 blocked for more than 120 
seconds.

[ 3600.197657]   Not tainted 4.3.0-rc6p7463161+ #3
[ 3600.197660] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables this message.
[ 3840.204146] INFO: task btrfs-transacti:7358 blocked for more than 120 
seconds.

[ 3840.204180]   Not tainted 4.3.0-rc6p7463161+ #3
[ 3840.204219] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables this message.
[ 3993.671982] Out of memory: Kill process 11357 (df-complex2simp) score 
227 or sacrifice child
[ 3993.671989] Killed process 11357 (df-complex2simp) total-vm:891608kB, 
anon-rss:870704kB, file-rss:60kB
[ 4080.210324] INFO: task btrfs-transacti:7358 blocked for more than 120 
seconds.

[ 4080.210336]   Not tainted 4.3.0-rc6p7463161+ #3
[ 4080.210339] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables this message.
[ 4320.215635] INFO: task btrfs-transacti:7358 blocked for more than 120 
seconds.

[ 4320.215662]   Not tainted 4.3.0-rc6p7463161+ #3
[ 4320.215667] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables this message.
[ 4560.221119] INFO: task btrfs-transacti:7358 blocked for more than 120 
seconds.

[ 4560.221146]   Not tainted 4.3.0-rc6p7463161+ #3
[ 4560.221148] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables this message.
[ 4800.226884] INFO: task btrfs-transacti:7358 blocked for more than 120 
seconds.

[ 4800.226898]   Not tainted 4.3.0-rc6p7463161+ #3
[ 4800.226902] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables this message.
[ 4890.116131] Out of memory: Kill process 13377 (df-complex2simp) score 
207 or sacrifice child
[ 4890.116138] Killed process 13377 (df-complex2simp) total-vm:834976kB, 
anon-rss:793272kB, file-rss:48kB
[ 5785.793580] Out of memory: Kill process 15285 (df-complex2simp) score 
201 or sacrifice child
[ 5785.793586] Killed process 15285 (df-complex2simp) total-vm:802208kB, 
anon-rss:772172kB, file-rss:4kB
[ 6480.269728] INFO: task btrfs-transacti:7358 blocked for more than 120 
seconds.

[ 6480.269738]   Not tainted 4.3.0-rc6p7463161+ #3
[ 6480.269740] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables this message.
[ 7081.967354] BTRFS: here, ref_mod != 1, bytenr 12090260504576, ref_mod 
2, seq 0 action 1
[ 7081.967784] BTRFS: error (device dm-3) in 
btrfs_run_delayed_refs:2872: errno=-5 IO failure


The OOM conditions are unrelated, this is an rrdtool 

Re: BTRFS BUG at insert_inline_extent_backref+0xe3/0xf0 while rebalancing

[Stéphane Lesimple]

Le 2015-10-22 10:53, Filipe Manana a écrit :
On Thu, Oct 22, 2015 at 6:32 AM, Erkki Seppala  
wrote:

Hello,

Recently I added daily rebalancing to my cron.d (after finding myself 
in

the no-space-situation), and not long after that, I found my PC had
crashed over night. Having no sign in the logs anywhere (not even over
network even though there should be) I had nothing to go on, but this
night it crashed again after starting the rebalance, and this time 
there

was some information on the kernel log.

Kernel version: 4.2.3 (package linux-image-4.2.0-1-amd64 version 
4.2.3-1

from Debian Unstable)

The dump is available at:

  http://www.modeemi.fi/~flux/btrfs/btrfs-BUG-2015-10-55.txt

The log is available as well (stripped some unrelated USB- and 
firewall

logging, showing that last evening there was some kernel task hung for
120 seconds; but it's in another btrfs filesystem and is another 
story):


  http://www.modeemi.fi/~flux/btrfs/btrfs-2015-10-55.txt

I'm not quite sure which of the btrfs balance commands caused the
issue. But there is my script:

#!/bin/sh
fs="$1"
if [ -z "$fs" ]; then
  echo usage: btrfs-balance / 0 1 5 10 20 50
  exit 1
fi
fs="$1"
shift
for usage in d m; do for a in "$@"; do date; /bin/btrfs balance start
"$fs" -v -${usage}usage=$a; done; done

And it was started at 07:30 with:

  /usr/local/sbin/btrfs-balance / 0 1 2 5 10 20 30 50 70

I should add that the filesystem in question is backed by MD RAID10 
and

that is backed by four SSDs, so it's reasonably fast in IO, if that
affects anything. There should have been no much competing IO at the
time of the occurrence.

Before Duncan asks ;-), I only have a moderate number of subvolumes 
and
snapshots, ie. one subvolume for each of /, /var/log/journal and 
/home,

24 snapshots of / and /home plus <10 snapshots of /.

Before that balance there was another balance on a another BTRFS 
RAID10,

but given the time stamp I think I can easily say it wasn't the cause.

I don't really have other 'solutions' than disabling the rebalancing 
for

the time being, and only use it as-needed as I had earlier done..


Try this (just sent a few minutes ago):
https://patchwork.kernel.org/patch/7463161/



Awesome, I'll also try it right now under 4.3.0-rc6. My system is 
currently hit so hard by this bug that it no longer survives a balance 
for longer than a few minutes.


Will keep you posted on the outcome.

Thanks,

--
Stéphane.


--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH] Btrfs: fix regression when running delayed references

[Stéphane Lesimple]

fb0() 
knlGS:

[  822.462716] CS:  0010 DS:  ES:  CR0: 80050033
[  822.462736] CR2: 7ff7a21ca000 CR3: 01c1 CR4: 
000406e0

[  822.462762] Stack:
[  822.462770]  c037c8be 88011fb169f0 0001 
0001
[  822.462802]  0001 88011a4a1a60 8800b663bd38 
8800b663bd40
[  822.462831]  810aded5 8101fcc9 8800b663bd20 
14d9

[  822.462859] Call Trace:
[  822.462877]  [] ? 
try_merge_free_space.isra.26+0x12e/0x180 [btrfs]

[  822.462902]  [] ? put_prev_entity+0x35/0x660
[  822.462924]  [] ? sched_clock+0x9/0x10
[  822.462949]  [] btrfs_run_delayed_refs+0x7d/0x2b0 
[btrfs]

[  822.462972]  [] ? schedule_timeout+0x16b/0x2a0
[  822.462999]  [] btrfs_commit_transaction+0x43/0xb10 
[btrfs]
[  822.463028]  [] transaction_kthread+0x1a9/0x230 
[btrfs]
[  822.463056]  [] ? 
btrfs_cleanup_transaction+0x550/0x550 [btrfs]

[  822.463080]  [] kthread+0xc9/0xe0
[  822.463096]  [] ? kthread_park+0x60/0x60
[  822.463116]  [] ret_from_fork+0x3f/0x70
[  822.463134]  [] ? kthread_park+0x60/0x60
[  822.463153] Code: c0 48 8b bd 40 ff ff ff 31 c0 e8 31 94 fe ff 0f 0b 
be d3 00 00 00 48 c7 c7 3b c6 3b c0 e8 6e 63 d5 c0 e9 64 f9 ff ff 0f 0b 
0f 0b <0f> 0b be d3 00 00 00 48 c7 c7 3b c6 3b c0 e8 52 63 d5 c0 e9 60
[  822.463300] RIP  [] 
__btrfs_run_delayed_refs.constprop.73+0x108b/0x10d0 [btrfs]

[  822.463335]  RSP 
[  822.472131] ---[ end trace f1e21f38cb0ea144 ]---

A couple other stacktraces follow after some seconds, then the system 
dies completely. sysrqd doesn't even work to reboot it remotely using 
sysrq logic.


fs/btrfs/extent-tree.c:2287 is the line you get from a vanilla 4.3-rc6 + 
your patch. I'll post it as soon as I can get somebody to manually 
reboot this remote machine (my kernel build machine is the same than the 
one hosting the btrfs FS).


Don't hesitate to ask if you need me to debug or even ftrace something.

Thanks,

--
Stéphane.

I was going to do it but not completely sure is there any other user 
of

tree_mod_seq.
And if it's possible to get rid of tree_mod_seq and merge with last
delayed_ref, things should get cleaner without new codes.


Well, the tree mod seq is what allows backref walkers (and possibly
other paths) to get a consistent view of all btrees and delayed refs
state while doing some processing - that's why we have calls to
btrfs_check_delayed_seq() when running delayed references - so that
any backref walker will not see changes that happen after it started,
i.e. it will see a consistent view of all the btrees (like an
in-memory snapshot of all btrees while the transaction is running).

I don't think you can get this level of consistency through any other
existing means.
So just adding back yet more code that was removed despite still being 
needed.


This is affecting way too many people now, I would like to get this
fixed and later, if there's a better (new) solution for this, we can
get it in.

thanks



Thanks,
Qu





Fixes: c6fc24549960 ("btrfs: delayed-ref: Use list to replace the 
ref_root

in ref_head.")
Reported-by: Peter Becker <floyd@gmail.com>
Reported-by: Stéphane Lesimple <stephane_bt...@lesimple.fr>
Reported-by: Malte Schröder <ma...@tnxip.de>
Reported-by: Derek Dongray <de...@valedon.co.uk>
Reported-by: Erkki Seppala <flux-bt...@inside.org>
Cc: sta...@vger.kernel.org  # 4.2+
Signed-off-by: Filipe Manana <fdman...@suse.com>
---
  fs/btrfs/delayed-ref.c | 113
+
  fs/btrfs/extent-tree.c |  14 ++
  2 files changed, 127 insertions(+)

diff --git a/fs/btrfs/delayed-ref.c b/fs/btrfs/delayed-ref.c
index ac3e81d..4832943 100644
--- a/fs/btrfs/delayed-ref.c
+++ b/fs/btrfs/delayed-ref.c
@@ -197,6 +197,119 @@ static inline void drop_delayed_ref(struct
btrfs_trans_handle *trans,
trans->delayed_ref_updates--;
  }

+static bool merge_ref(struct btrfs_trans_handle *trans,
+ struct btrfs_delayed_ref_root *delayed_refs,
+ struct btrfs_delayed_ref_head *head,
+ struct btrfs_delayed_ref_node *ref,
+ u64 seq)
+{
+   struct btrfs_delayed_ref_node *next;
+   bool done = false;
+
+   next = list_first_entry(>ref_list, struct
btrfs_delayed_ref_node,
+   list);
+   while (!done && >list != >ref_list) {
+   int mod;
+   struct btrfs_delayed_ref_node *next2;
+
+   next2 = list_next_entry(next, list);
+
+   if (next == ref)
+   goto next;
+
+   if (seq && next->seq >= seq)
+   goto next;
+
+   if (next->type != ref->type || next->no_quota !=
ref->no_quota)
+   goto next;
+
+   if ((ref->type

Re: kernel BUG at /linux/fs/btrfs/extent-tree.c:1833!

[Stéphane Lesimple]

Hello Peter,

I have the same problem you have, as reported ~1 month ago on this 
mailing-list.


My setup is 2 disks, and I tried balancing after adding a third one, in a 
raid5 configuration.
I also have some "extent buffer leak" in my btrfsck, but it's hard to say 
if it can be the cause. If you look at the source code you'll see that 
those messages are not printed by the main checking routine but by an 
helper subroutine, I'm not even sure it represents a problem on the 
filesystem (maybe somebody can sched some light here).


I tried with the 4.3-rc2 kernel, and the kernel bug is still there, 
unfortunately. I also posted an ftrace of the bug, hopefully somebody with 
enough btrfs knowledge will have a look.
I reproduced this bug dozens of time, and as far as I can tell I never lost 
any single byte because of the crash, probably thanks to the transaction 
system of btrfs, so, at least there's that.


--
Stéphane.


Le 11 octobre 2015 22:50:07 Peter Becker  a écrit :


the output of btrfs check --readonly /dev/sdb

http://pastebin.com/UxkeVd7Y

many entrys with "extent buffer leak"


the output of  btrfs-show-super -i0 /dev/sd[bcd] &&  btrfs-show-super
-i1 /dev/sd[bcd] &&  btrfs-show-super -i2 /dev/sd[bcd]

http://pastebin.com/zs7B8827
http://pastebin.com/Kn1kwgYv
http://pastebin.com/CHC52ef7
--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html



--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

ftrace of kernel BUG at extent-tree.c during balance

[Stéphane Lesimple]

Hello,

This bug has been discussed several times here already, both recently 
and also in 2012 where the bug was deemed fixed in btrfs-next, but 
probably wasn't in the end [1]. It has also been reported at a couple 
other places, such as [2].


I managed to add some trace_printk's at the beggining of each function 
present in the stack trace, and reproduced the problem. Took me a couple 
days to reproduce it and get potentially useful logs.


The stacktrace is :

[60424.709967] kernel BUG at fs/btrfs/extent-tree.c:1841!
[60424.710748] CPU: 0 PID: 1622 Comm: kworker/u2:3 Tainted: GW   
4.3.0-rc1 #1
[60424.710816] Workqueue: btrfs-extent-refs btrfs_extent_refs_helper 
[btrfs]
[60424.710849] task: 880113fd ti: 8800550f task.ti: 
8800550f
[60424.710874] RIP: 0010:[]  [] 
insert_inline_extent_backref+0x195/0x1a0 [btrfs]

[60424.711189] Call Trace:
[60424.711206]  [] __btrfs_inc_extent_ref+0xe1/0x290 
[btrfs]
[60424.711234]  [] 
__btrfs_run_delayed_refs+0xd1e/0x1070 [btrfs]
[60424.711264]  [] ? 
ring_buffer_unlock_commit+0x2c/0x260

[60424.711287]  [] ? __trace_bprintk+0x50/0x60
[60424.711307]  [] btrfs_run_delayed_refs+0x91/0x2c0 
[btrfs]
[60424.711332]  [] ? 
btrfs_start_transaction_lflush+0x20/0x20 [btrfs]
[60424.711358]  [] delayed_ref_async_start+0x37/0x90 
[btrfs]
[60424.711384]  [] normal_work_helper+0xc0/0x270 
[btrfs]

[60424.711404]  [] ftrace_graph_caller+0xa8/0xa8
[60424.711427]  [] btrfs_extent_refs_helper+0x12/0x20 
[btrfs]

[60424.711446]  [] ftrace_graph_caller+0xa8/0xa8
[60424.711464]  [] process_one_work+0x14e/0x3d0
[60424.711481]  [] worker_thread+0x11a/0x470
[60424.711497]  [] ? rescuer_thread+0x310/0x310
[60424.711514]  [] kthread+0xc9/0xe0
[60424.711529]  [] ? kthread_park+0x60/0x60

Corresponding code is (slightly modified on my end for ftrace) :

static noinline_for_stack
int insert_inline_extent_backref(struct btrfs_trans_handle *trans,
 struct btrfs_root *root,
 struct btrfs_path *path,
 u64 bytenr, u64 num_bytes, u64 parent,
 u64 root_objectid, u64 owner,
 u64 offset, int refs_to_add,
 struct btrfs_delayed_extent_op *extent_op)
{
  struct btrfs_extent_inline_ref *iref;
  int ret;
  trace_printk("insert_inline_extent_backref args: trans=%p root=%p 
path=%p bytenr=%llu num_bytes=%llu parent=%llu root_objectid=%llu 
owner=%llu offset=%llu refs_to_add=%d extent_op=%p\n",
trans, root, path, bytenr, num_bytes, parent, root_objectid, owner, 
offset, refs_to_add, extent_op);


  ret = lookup_inline_extent_backref(trans, root, path, ,
 bytenr, num_bytes, parent,
 root_objectid, owner, offset, 1);
  if (ret == 0) {
if (owner < BTRFS_FIRST_FREE_OBJECTID)
{
  trace_printk("info: CONDITIONS MET FOR BUG, STOPPING TRACING\n");
  tracing_off();
  printk("{btrfs} in insert_inline_extent_backref, got owner < 
BTRFS_FIRST_FREE_OBJECTID\n");
  printk("{btrfs} with bytenr=%llu num_bytes=%llu parent=%llu 
root_objectid=%llu owner=%llu offset=%llu refs_to_add=%d 
BTRFS_FIRST_FREE_OBJECTID=%llu\n",
bytenr, num_bytes, parent, root_objectid, owner, offset, 
refs_to_add, BTRFS_FIRST_FREE_OBJECTID);

  BUG(); // <== here
}


The ftrace configuration was :

echo 8 > max_graph_depth
echo function_graph > current_tracer
echo :mod:btrfs > set_ftrace_filter
echo btrfs_{g,s}et_token_{8,16,32,64} btrfs_comp_cpu_keys 
read_extent_buffer map_private_extent_buffer free_extent_buffer 
release_extent_buffer check_buffer_tree_ref find_extent_buffer 
extent_buffer_uptodate verify_parent_transid mark_extent_buffer_accessed 
btrfs_set_path_blocking btrfs_set_lock_blocking_rw btrfs_tree_read_lock 
alloc_extent_buffer btrfs_find_create_tree_block 
read_extent_buffer_pages btree_read_extent_buffer_pages.constprop.56 
read_tree_block btrfs_tree_read_unlock_blocking 
btrfs_clear_path_blocking bin_search > set_ftrace_notrace


The kernel was booted with nosmp to avoid out of order logs.

The ftrace data was collected by netcat and sent over the network to a 
logging machine. The kernel stacktrace was collected with netconsole on 
the same machine.


Over 100G of logs were created during the 3 days I was trying to 
reproduce the bug *and* getting a usable ftrace configuration. I had a 
script to pause/resume the balance from time to time to enable log 
splitting and keep only the one where the bug would happen. This last 
log is a little under 1G (uncompressed, 40M compressed). I suspect the 
last few lines of this log were not sent by the crashing machine (the 
trace_printk above doesn't appear), but the crash condition can be seen 
however (owner == 1).


The first and last 1000 lines of this log are available here :
http://www.speed47.net/tmp2/bug_first_1k.log.gz
http://www.speed47.net/tmp2/bug_last_1k.log.gz

The complete log is available here (40M) :
http://www.speed47.net/tmp2/btrfs_ftrace.2015-09-29.15-11-15.cpu0.gz

You can grep "args:" to get the trace_printk's indicating 

Re: [PATCH 0/2] Btrfs: Fix a insane extent_buffer copy behavior for qgroup

[Stéphane Lesimple]

Le 2015-09-25 04:37, Qu Wenruo a écrit :

Stephane Lesimple reported an qgroup rescan bug:

[92098.841309] general protection fault:  [#1] SMP
[92098.841338] Modules linked in: ...
[92098.841814] CPU: 1 PID: 24655 Comm: kworker/u4:12 Not tainted
4.3.0-rc1 #1
[92098.841868] Workqueue: btrfs-qgroup-rescan 
btrfs_qgroup_rescan_helper

[btrfs]
[92098.842261] Call Trace:
[92098.842277]  [] ? read_extent_buffer+0xb8/0x110
[btrfs]
[92098.842304]  [] ? btrfs_find_all_roots+0x60/0x70
[btrfs]
[92098.842329]  []
btrfs_qgroup_rescan_worker+0x28d/0x5a0 [btrfs]
...

The triggering function btrfs_disk_key_to_cpu(), which should never
fail.
But it turned out that the extent_buffere being called on is memcpied
from an existing one.

Such behavior to copy a structure with page pointers and locks in it is
never a sane thing.

Fix it by do it in memory other than extent_buffer.

Qu Wenruo (2):
  btrfs: Add support to do stack item key operation
  btrfs: qgroup: Don't copy extent buffer to do qgroup rescan

 fs/btrfs/ctree.h  | 20 
 fs/btrfs/qgroup.c | 22 --
 2 files changed, 32 insertions(+), 10 deletions(-)


I applied this patch and ran 100+ rescans on my filesystem for several 
hours. No crash happened, where only a few rescans were enough to 
trigger the bug previously.


I'm confident this patch fixes the GPF, thanks Qu !

--
Stéphane.


--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: kernel BUG at linux-4.2.0/fs/btrfs/extent-tree.c:1833 on rebalance

[Stéphane Lesimple]

Le 2015-09-23 09:03, Qu Wenruo a écrit :

Stéphane Lesimple wrote on 2015/09/22 16:31 +0200:

Le 2015-09-22 10:51, Qu Wenruo a écrit :

[92098.842261] Call Trace:
[92098.842277]  [] ? 
read_extent_buffer+0xb8/0x110

[btrfs]
[92098.842304]  [] ? 
btrfs_find_all_roots+0x60/0x70

[btrfs]
[92098.842329]  []
btrfs_qgroup_rescan_worker+0x28d/0x5a0 [btrfs]


Would you please show the code of it?
This one seems to be another stupid bug I made when rewriting the
framework.
Maybe I forgot to reinit some variants or I'm screwing memory...


(gdb) list *(btrfs_qgroup_rescan_worker+0x28d)
0x97f6d is in btrfs_qgroup_rescan_worker (fs/btrfs/ctree.h:2760).
2755
2756static inline void btrfs_disk_key_to_cpu(struct btrfs_key 
*cpu,
2757 struct 
btrfs_disk_key

*disk)
2758{
2759cpu->offset =e64_to_cpu(disk->offset);
2760cpu->type =isk->type;
2761cpu->objectid =e64_to_cpu(disk->objectid);
2762}
2763
2764static inline void btrfs_cpu_key_to_disk(struct 
btrfs_disk_key

*disk,
(gdb)


Does it makes sense ?

So it seems that the memory of cpu key is being screwed up...

The code is be specific thin inline function, so what about other 
stack?

Like btrfs_qgroup_rescan_helper+0x12?

Thanks,
Qu

Oh, I forgot that you can just change the number of
btrfs_qgroup_rescan_worker+0x28d to smaller value.
Try +0x280 for example, which will revert to 14 bytes asm code back,
which may jump out of the inline function range, and may give you a
good hint.

Or gdb may have a better mode for inline function, but I don't 
know...


Actually, "list -" is our friend here (show 10 lignes before the last
src output)

No, that's not the case.

List - will only show lines around the source code.

What I need is to get the higher caller stack.
If debugging a running program, it's quite easy to just use frame 
command.


But in this situation, we don't have call stack, so I'd like to change
the +0x28d to several bytes backward, until we jump out of the inline
function call, and see the meaningful codes.


Ah, you're right.
I had a hard time finding a value where I wouldn't end up in another 
inline

function or entirely somewhere else in the kernel code, but here it is :

(gdb) list *(btrfs_qgroup_rescan_worker+0x26e)
0x97f4e is in btrfs_qgroup_rescan_worker (fs/btrfs/qgroup.c:2237).
2232memcpy(scratch_leaf, path->nodes[0], 
sizeof(*scratch_leaf));

2233slot = path->slots[0];
2234btrfs_release_path(path);
2235mutex_unlock(_info->qgroup_rescan_lock);
2236
2237for (; slot < btrfs_header_nritems(scratch_leaf); 
++slot) {
2238btrfs_item_key_to_cpu(scratch_leaf, , 
slot); <== here


2239if (found.type != BTRFS_EXTENT_ITEM_KEY &&
2240found.type != BTRFS_METADATA_ITEM_KEY)
2241continue;

the btrfs_item_key_to_cpu() inline func calls 2 other inline funcs:

static inline void btrfs_item_key_to_cpu(struct extent_buffer *eb,
  struct btrfs_key *key, int nr)
{
struct btrfs_disk_key disk_key;
btrfs_item_key(eb, _key, nr);
btrfs_disk_key_to_cpu(key, _key); <== this is 0x28d
}

btrfs_disk_key_to_cpu() is the inline referenced by 0x28d and this is 
where

the GPF happens.



BTW, did you tried the following patch?
https://patchwork.kernel.org/patch/7114321/
btrfs: qgroup: exit the rescan worker during umount

The problem seems a little related to the bug you encountered, so I'd
recommend to give it a try.


Not yet, but I've come across this bug too during my tests: starting a 
rescan
and umounting gets you a crash. I didn't mention it because I was sure 
this

was an already known bug. Nice to see it has been fixed though !
I'll certainly give it a try but I'm not really sure it'll fix the 
specific

bug we're talking about.
However the group of patches posted by Mark should fix the qgroup count
disrepancies as I understand it, right ? It might be of interest to try 
them

all at once for sure.

Thanks,

--
Stéphane.


--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: kernel BUG at linux-4.2.0/fs/btrfs/extent-tree.c:1833 on rebalance

[Stéphane Lesimple]

Le 2015-09-22 03:37, Qu Wenruo a écrit :

Stéphane Lesimple wrote on 2015/09/22 03:30 +0200:

Le 2015-09-20 13:14, Stéphane Lesimple a écrit :

Le 2015-09-20 12:51, Qu Wenruo a écrit :

Would you please use gdb to show the codes of
"btrfs_qgroup_rescan_worker+0x388" ?
(Need kernel debuginfo)

My guess is the following line:(pretty sure, but not 100% sure)
--
/*
 * only update status, since the previous part has alreay
updated the
 * qgroup info.
 */
trans = btrfs_start_transaction(fs_info->quota_root, 1); 
<<<<<

if (IS_ERR(trans)) {
err = PTR_ERR(trans);
btrfs_err(fs_info,
  "fail to start transaction for status
update: %d\n",
  err);
goto done;
}
--


The kernel and modules were already compiled with debuginfo.
However for some reason, I couldn't get gdb disassembly of 
/proc/kcore

properly
aligned with the source I compiled: the asm code doesn't match the 
C

code shown
by gdb. In any case, watching the source of this function, this is 
the

only place
btrfs_start_transaction is called, so we can be 100% sure it's 
where

the
crash
happens indeed.


Yep, that's the only caller.

Here is some useful small hint to locate the code, if you are
interestied in kernel development.

# Not sure about whether ubuntu gzipped modules, at least Arch does
# compress it
$ cp /kernel/fs/btrfs/btrfs.ko.gz /tmp/
$ gunzip /tmp/btrfs.ko.gz
$ gdb /tmp/btrfs.ko
# Make sure gdb read all the needed debuginfo
$ gdb list *(btrfs_qgroup_rescan_worker+0x388)

And gdb will find the code position for you.
Quite easy one, only backtrace info is needed.


Ah, thanks for the tips, I was loading whole vmlinux and using
/proc/kcore
as the core info, then adding the module with "add-symbol-file". But 
as

we're just looking for the code and not the variables, it was indeed
completely overkill.

(gdb) list *(btrfs_qgroup_rescan_worker+0x388)
0x98068 is in btrfs_qgroup_rescan_worker (fs/btrfs/qgroup.c:2328).
2323
2324/*
2325 * only update status, since the previous part has
alreay updated the
2326 * qgroup info.
2327 */
2328trans = btrfs_start_transaction(fs_info->quota_root, 
1);

2329if (IS_ERR(trans)) {
2330err = PTR_ERR(trans);
2331btrfs_err(fs_info,
2332  "fail to start transaction for
status update: %d\n",

So this just confirms what we were already 99% sure of.


Another hint is about how to collect the kernel crash info.
Your netconsole setup would be definitely one good practice.

Another one I use to collect crash info is kdump.
Ubuntu should have a good wiki on it.


I've already come across kdump a few times, but never really look 
into

it.
To debug the other complicated extend backref bug, it could be of 
some

use.


So, as a quick summary of this big thread, it seems I've been
hitting
3 bugs, all reproductible :
- kernel BUG on balance (this original thread)


For this, I can't provide much help, as extent backref bug is 
quite

hard to debug, unless a developer is interested in it and find a
stable way to reproduce it.


Yes, unfortunately as it looks so much like a race condition, I 
know

I can
reproduce it with my worflow, but it can take between 1 minute and 
12

hours,
so I wouldn't call it a "stable way" to reproduce it unfortunately 
:(


Still if any dev is interested in it, I can reproduce it, with a
patched
kernel if needed.


Maybe you are already doing it, you can only compile the btrfs
modules, which will be far more faster than compile the whole 
kernel,

if and only if the compiled module can be loaded.


Yes, I've compiled this 4.3.0-rc1 in a completely modular form, so
I'll try to
load the modified module and see if the running kernel accepts it. I
have to rmmod
the loaded module first, hence umounting any btrfs fs before that.
Should be able
to do it in a couple hours.

I'll delete again all my snapshots and run my script. Should be easy
to trigger
the (hopefully worked-around) bug again.


Well, I didn't trigger this exact bug, but another one, not less 
severe

though, as it also crashed the system:

[92098.841309] general protection fault:  [#1] SMP
[92098.841338] Modules linked in: ...
[92098.841814] CPU: 1 PID: 24655 Comm: kworker/u4:12 Not tainted
4.3.0-rc1 #1
[92098.841834] Hardware name: ASUS All Series/H87I-PLUS, BIOS 1005
01/06/2014
[92098.841868] Workqueue: btrfs-qgroup-rescan 
btrfs_qgroup_rescan_helper

[btrfs]
[92098.841889] task: 8800b6cc4100 ti: 8800a3dc8000 task.ti:
8800a3dc8000
[92098.841910] RIP: 0010:[]  []
memcpy_erms+0x6/0x10
[92098.841935] RSP: 0018:8800a3dcbcc8  EFLAGS: 00010207
[92098.841950] RAX: 8800a3dcbd67 RBX: 0009 RCX:
0009
[92098.841970] RDX: 0009 RSI: 0005

Re: kernel BUG at linux-4.2.0/fs/btrfs/extent-tree.c:1833 on rebalance

[Stéphane Lesimple]

Le 2015-09-20 13:14, Stéphane Lesimple a écrit :

Le 2015-09-20 12:51, Qu Wenruo a écrit :

Would you please use gdb to show the codes of
"btrfs_qgroup_rescan_worker+0x388" ?
(Need kernel debuginfo)

My guess is the following line:(pretty sure, but not 100% sure)
--
/*
 * only update status, since the previous part has alreay
updated the
 * qgroup info.
 */
trans = btrfs_start_transaction(fs_info->quota_root, 1); 
<<<<<

if (IS_ERR(trans)) {
err = PTR_ERR(trans);
btrfs_err(fs_info,
  "fail to start transaction for status
update: %d\n",
  err);
goto done;
}
--


The kernel and modules were already compiled with debuginfo.
However for some reason, I couldn't get gdb disassembly of 
/proc/kcore

properly
aligned with the source I compiled: the asm code doesn't match the C
code shown
by gdb. In any case, watching the source of this function, this is 
the

only place
btrfs_start_transaction is called, so we can be 100% sure it's where 
the

crash
happens indeed.


Yep, that's the only caller.

Here is some useful small hint to locate the code, if you are
interestied in kernel development.

# Not sure about whether ubuntu gzipped modules, at least Arch does
# compress it
$ cp /kernel/fs/btrfs/btrfs.ko.gz /tmp/
$ gunzip /tmp/btrfs.ko.gz
$ gdb /tmp/btrfs.ko
# Make sure gdb read all the needed debuginfo
$ gdb list *(btrfs_qgroup_rescan_worker+0x388)

And gdb will find the code position for you.
Quite easy one, only backtrace info is needed.


Ah, thanks for the tips, I was loading whole vmlinux and using 
/proc/kcore

as the core info, then adding the module with "add-symbol-file". But as
we're just looking for the code and not the variables, it was indeed
completely overkill.

(gdb) list *(btrfs_qgroup_rescan_worker+0x388)
0x98068 is in btrfs_qgroup_rescan_worker (fs/btrfs/qgroup.c:2328).
2323
2324/*
2325 * only update status, since the previous part has
alreay updated the
2326 * qgroup info.
2327 */
2328trans = btrfs_start_transaction(fs_info->quota_root, 
1);

2329if (IS_ERR(trans)) {
2330err = PTR_ERR(trans);
2331btrfs_err(fs_info,
2332  "fail to start transaction for
status update: %d\n",

So this just confirms what we were already 99% sure of.


Another hint is about how to collect the kernel crash info.
Your netconsole setup would be definitely one good practice.

Another one I use to collect crash info is kdump.
Ubuntu should have a good wiki on it.


I've already come across kdump a few times, but never really look into 
it.
To debug the other complicated extend backref bug, it could be of some 
use.


So, as a quick summary of this big thread, it seems I've been 
hitting

3 bugs, all reproductible :
- kernel BUG on balance (this original thread)


For this, I can't provide much help, as extent backref bug is quite
hard to debug, unless a developer is interested in it and find a
stable way to reproduce it.


Yes, unfortunately as it looks so much like a race condition, I know 
I can

reproduce it with my worflow, but it can take between 1 minute and 12
hours,
so I wouldn't call it a "stable way" to reproduce it unfortunately :(

Still if any dev is interested in it, I can reproduce it, with a 
patched

kernel if needed.


Maybe you are already doing it, you can only compile the btrfs
modules, which will be far more faster than compile the whole kernel,
if and only if the compiled module can be loaded.


Yes, I've compiled this 4.3.0-rc1 in a completely modular form, so I'll 
try to

load the modified module and see if the running kernel accepts it. I
have to rmmod
the loaded module first, hence umounting any btrfs fs before that.
Should be able
to do it in a couple hours.

I'll delete again all my snapshots and run my script. Should be easy to 
trigger

the (hopefully worked-around) bug again.


Well, I didn't trigger this exact bug, but another one, not less severe 
though, as it also crashed the system:


[92098.841309] general protection fault:  [#1] SMP
[92098.841338] Modules linked in: ...
[92098.841814] CPU: 1 PID: 24655 Comm: kworker/u4:12 Not tainted 
4.3.0-rc1 #1
[92098.841834] Hardware name: ASUS All Series/H87I-PLUS, BIOS 1005 
01/06/2014
[92098.841868] Workqueue: btrfs-qgroup-rescan btrfs_qgroup_rescan_helper 
[btrfs]
[92098.841889] task: 8800b6cc4100 ti: 8800a3dc8000 task.ti: 
8800a3dc8000
[92098.841910] RIP: 0010:[]  [] 
memcpy_erms+0x6/0x10

[92098.841935] RSP: 0018:8800a3dcbcc8  EFLAGS: 00010207
[92098.841950] RAX: 8800a3dcbd67 RBX: 0009 RCX: 
0009
[92098.841970] RDX: 0009 RSI: 00050800 RDI: 
8800a3dcbd67
[92098.841989] RBP: 8800a3dcbd00 R08: 0

Re: kernel BUG at linux-4.2.0/fs/btrfs/extent-tree.c:1833 on rebalance

[Stéphane Lesimple]

Le 2015-09-20 12:51, Qu Wenruo a écrit :

Would you please use gdb to show the codes of
"btrfs_qgroup_rescan_worker+0x388" ?
(Need kernel debuginfo)

My guess is the following line:(pretty sure, but not 100% sure)
--
/*
 * only update status, since the previous part has alreay
updated the
 * qgroup info.
 */
trans = btrfs_start_transaction(fs_info->quota_root, 1); 
<

if (IS_ERR(trans)) {
err = PTR_ERR(trans);
btrfs_err(fs_info,
  "fail to start transaction for status
update: %d\n",
  err);
goto done;
}
--


The kernel and modules were already compiled with debuginfo.
However for some reason, I couldn't get gdb disassembly of /proc/kcore
properly
aligned with the source I compiled: the asm code doesn't match the C
code shown
by gdb. In any case, watching the source of this function, this is the
only place
btrfs_start_transaction is called, so we can be 100% sure it's where 
the

crash
happens indeed.


Yep, that's the only caller.

Here is some useful small hint to locate the code, if you are
interestied in kernel development.

# Not sure about whether ubuntu gzipped modules, at least Arch does
# compress it
$ cp /kernel/fs/btrfs/btrfs.ko.gz /tmp/
$ gunzip /tmp/btrfs.ko.gz
$ gdb /tmp/btrfs.ko
# Make sure gdb read all the needed debuginfo
$ gdb list *(btrfs_qgroup_rescan_worker+0x388)

And gdb will find the code position for you.
Quite easy one, only backtrace info is needed.


Ah, thanks for the tips, I was loading whole vmlinux and using 
/proc/kcore

as the core info, then adding the module with "add-symbol-file". But as
we're just looking for the code and not the variables, it was indeed
completely overkill.

(gdb) list *(btrfs_qgroup_rescan_worker+0x388)
0x98068 is in btrfs_qgroup_rescan_worker (fs/btrfs/qgroup.c:2328).
2323
2324/*
2325 * only update status, since the previous part has 
alreay updated the

2326 * qgroup info.
2327 */
2328trans = btrfs_start_transaction(fs_info->quota_root, 1);
2329if (IS_ERR(trans)) {
2330err = PTR_ERR(trans);
2331btrfs_err(fs_info,
2332  "fail to start transaction for status 
update: %d\n",


So this just confirms what we were already 99% sure of.


Another hint is about how to collect the kernel crash info.
Your netconsole setup would be definitely one good practice.

Another one I use to collect crash info is kdump.
Ubuntu should have a good wiki on it.


I've already come across kdump a few times, but never really look into 
it.
To debug the other complicated extend backref bug, it could be of some 
use.


So, as a quick summary of this big thread, it seems I've been 
hitting

3 bugs, all reproductible :
- kernel BUG on balance (this original thread)


For this, I can't provide much help, as extent backref bug is quite
hard to debug, unless a developer is interested in it and find a
stable way to reproduce it.


Yes, unfortunately as it looks so much like a race condition, I know I 
can

reproduce it with my worflow, but it can take between 1 minute and 12
hours,
so I wouldn't call it a "stable way" to reproduce it unfortunately :(

Still if any dev is interested in it, I can reproduce it, with a 
patched

kernel if needed.


Maybe you are already doing it, you can only compile the btrfs
modules, which will be far more faster than compile the whole kernel,
if and only if the compiled module can be loaded.


Yes, I've compiled this 4.3.0-rc1 in a completely modular form, so I'll 
try to
load the modified module and see if the running kernel accepts it. I 
have to rmmod
the loaded module first, hence umounting any btrfs fs before that. 
Should be able

to do it in a couple hours.

I'll delete again all my snapshots and run my script. Should be easy to 
trigger

the (hopefully worked-around) bug again.

Regards,

--
Stéphane.

--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: kernel BUG at linux-4.2.0/fs/btrfs/extent-tree.c:1833 on rebalance

[Stéphane Lesimple]

Le 2015-09-20 03:22, Qu Wenruo a écrit :

The mentioned steps are as follows :

0) Rsync data from the next ext4 "snapshot" to the subvolume
1) Do 'sync; btrfs qgroup show -⁠prce -⁠-⁠raw' and save the output 
<==

2) Create the needed readonly snapshot on btrfs
3) Do 'sync; btrfs qgroup show -⁠prce -⁠-⁠raw' and save the output 
<==

4) Avoid doing IO if possible until step 6)
5) Do 'btrfs quota rescan -⁠w' and save it <==
6) Do 'sync; btrfs qgroup show -⁠prce -⁠-⁠raw' and save the output 
<==


The resulting files are available here:
http://speed47.net/tmp2/qgroup.tar.gz
The run2 is the more complete one, during run1 the machine crashed
even faster.
It's interesting to note, however, that it seems to have crashed the
same way and at the same step in the process.


Your data really helps a lot!!

And the good news is, the qgroup accouting part is working as expected.
Although I only checked about 1/3/6 of about 5 snaps, they are all OK.

I can make a script to cross check them, but from the last few result,
I think qgroup works fine.

I'm more confident about the minus number, which should be a result of
deleted subvolume, and the real problem is, such qgroup is not handled
well with qgroup rescan.


I agree with your analysis, this matches what I observed.


I'll try to add a hot fix for such case if needed.
But right now, I don't have a good idea for it until Mark's work of
rescan subtree.

Maybe I can add a new option for btrfs-progs to automatically remove
the qgroup and trigger a rescan?


Until this is properly fixed in the kernel code, and this is good news 
to
know Mark and you are working on it, this would be a good workaround 
yes!



[ 5738.172879] Call Trace:
[ 5738.172887]  [] btrfs_start_transaction+0x1b/0x20
[btrfs]
[ 5738.172896]  []
btrfs_qgroup_rescan_worker+0x388/0x5a0 [btrfs]


Your netconsole backtrace is also of greate value.
This one implies that, my rework also caused some stupid bug.
(Yeah, I always make such bugs) or some existing unexposed rescan bug.

Would you please use gdb to show the codes of
"btrfs_qgroup_rescan_worker+0x388" ?
(Need kernel debuginfo)

My guess is the following line:(pretty sure, but not 100% sure)
--
/*
 * only update status, since the previous part has alreay 
updated the

 * qgroup info.
 */
trans = btrfs_start_transaction(fs_info->quota_root, 1); <
if (IS_ERR(trans)) {
err = PTR_ERR(trans);
btrfs_err(fs_info,
  "fail to start transaction for status update: 
%d\n",

  err);
goto done;
}
--


The kernel and modules were already compiled with debuginfo.
However for some reason, I couldn't get gdb disassembly of /proc/kcore 
properly
aligned with the source I compiled: the asm code doesn't match the C 
code shown
by gdb. In any case, watching the source of this function, this is the 
only place
btrfs_start_transaction is called, so we can be 100% sure it's where the 
crash

happens indeed.


But that means, at rescan time, fs_info->quota_root is still NULL,
which is quite wired.
I can add extra check to avoid such NULL pointer for now, but it's
better to review the existing rescan workflow, as I think there is
some race for it to init quota_root.

You can also try the following hotfix patch to see if it works:
http://pastebin.com/966GQXPk

My concern is, this may cause qgroup rescan to exit without updating
its accounting info...

So still need your help.
Or I can use your reproducer script to test it next Monday.


Compiling with your patch, just amended of a little printk to know if 
the execution

flow enters the added if condition. Will let you know about the results.


But I'm pretty sure I can get that (u64)-1 value again by deleting
snapshots. Shall I ? Or do you have something else for me to run
before that ?


You have already done a great job in helping maturing qgroups.
The minus number and 0 excl is somewhat expected for deleted snapshots.

Good news is, 1) it doesn't affect valid(non-orphan) qgroup.
2) Mark is already working on it.

I'll try to add a btrfs-progs hotfix for you to delete and rescan
qgroups to avoid such problem.


That would be good !


So, as a quick summary of this big thread, it seems I've been hitting
3 bugs, all reproductible :
- kernel BUG on balance (this original thread)


For this, I can't provide much help, as extent backref bug is quite
hard to debug, unless a developer is interested in it and find a
stable way to reproduce it.


Yes, unfortunately as it looks so much like a race condition, I know I 
can
reproduce it with my worflow, but it can take between 1 minute and 12 
hours,

so I wouldn't call it a "stable way" to reproduce it unfortunately :(

Still if any dev is interested in it, I can reproduce it, with a patched
kernel if needed.


The rest two are explained or have hot fix mentioned above.


And thanks for that, will keep you posted.

--
Stéphane.

--

Re: kernel BUG at linux-4.2.0/fs/btrfs/extent-tree.c:1833 on rebalance

[Stéphane Lesimple]

Le 2015-09-18 02:59, Qu Wenruo a écrit :

Stéphane Lesimple wrote on 2015/09/17 20:47 +0200:

Le 2015-09-17 12:41, Qu Wenruo a écrit :
In the meantime, I've reactivated quotas, umounted the filesystem 
and

ran a btrfsck on it : as you would expect, there's no qgroup problem
reported so far.


At least, rescan code is working without problem.


I'll clear all my snapshots, run an quota rescan, then
re-create them one by one by rsyncing from my ext4 system I still 
have.

Maybe I'll run into the issue again.



Would you mind to do the following check for each subvolume rsync?

1) Do 'sync; btrfs qgroup show -prce --raw' and save the output
2) Create the needed snapshot
3) Do 'sync; btrfs qgroup show -prce --raw' and save the output
4) Avoid doing IO if possible until step 6)
5) Do 'btrfs quota rescan -w' and save it
6) Do 'sync; btrfs qgroup show -prce --raw' and save the output
7) Rsync data from ext4 to the newly created snapshot

The point is, as you mentioned, rescan is working fine, we can 
compare

output from 3), 6) and 1) to see which qgroup accounting number
changes.

And if differs, which means the qgroup update at write time OR
snapshot creation has something wrong, at least we can locate the
problem to qgroup update routine or snapshot creation.


I was about to do that, but first there's something that sounds 
strange
: I've begun by trashing all my snapshots, then ran a quota rescan, 
and

waited for it to complete, to start on a sane base.
However, this is the output of qgroup show now :


By "trashing", did you mean deleting all the files inside the 
subvolume?

Or "btrfs subv del"?


Sorry for the confusion here, yes, I meant btrfs subvolume del.


qgroupid  rfer excl max_rfer max_excl
parent  child
     
--  -
0/5  1638416384 none none
--- ---
0/1906   16578480291841657848029184 none none
--- ---
0/1909124950921216 124950921216 none none
--- ---
0/1911   10545872936961054587293696 none none
--- ---
0/3270 23727300608  23727300608 none none
--- ---
0/3314 23206055936  23206055936 none none
--- ---
0/3317 184729968640 none none
--- ---
0/3318 22235709440 18446744073708421120 none none
--- ---
0/3319 222403338240 none none
--- ---
0/3320 222896087040 none none
--- ---
0/3321 222896087040 none none
--- ---
0/3322 184611512320 none none
--- ---
0/3323 184239022080 none none
--- ---
0/3324 184239022080 none none
--- ---
0/3325 184635064320 none none
--- ---
0/3326 184635064320 none none
--- ---
0/3327 184635064320 none none
--- ---
0/3328 184635064320 none none
--- ---
0/3329 185854279680 none none
--- ---
0/3330 18621472768 18446744073251348480 none none
--- ---
0/3331 186214727680 none none
--- ---
0/3332 186214727680 none none
--- ---
0/ 187830763520 none none
--- ---
0/3334 187998044160 none none
--- ---
0/3335 187998044160 none none
--- ---
0/3336 188162170880 none none
--- ---
0/3337 188162662400 none none
--- ---
0/3338 188162662400 none none
--- ---
0/3339 188162662400 none none
--- ---
0/3340 188163645440 none none
--- ---
0/3341  7530119168   7530119168 none none
--- ---
0/3342  49192837120 none none
--- ---
0/3343  49217249280 none none
--- ---
0/3344  49217249280 none none
--- ---
0/3345  6503317504 18446744073690902528 none none
--- ---
0/3346  65034526720 none none
--- ---
0/3347  65095147520 none none
--- ---
0/3348  65157939200 none non

Re: kernel BUG at linux-4.2.0/fs/btrfs/extent-tree.c:1833 on rebalance

[Stéphane Lesimple]

Le 2015-09-18 09:36, Stéphane Lesimple a écrit :

Sure, I did a quota disable / quota enable before running the snapshot
debug procedure, so the qgroups were clean again when I started :

qgroupid  rfer  excl max_rfer max_excl parent  
child
       --  
-
0/5  16384 16384 none none --- 
---
0/1906   1657848029184 1657848029184 none none --- 
---
0/1909124950921216  124950921216 none none --- 
---
0/1911   1054587293696 1054587293696 none none --- 
---
0/3270 23727300608   23727300608 none none --- 
---
0/3314 23221784576   23221784576 none none --- 
---
0/3341  74792755207479275520 none none --- 
---
0/3367 24185790464   24185790464 none none --- 
---


The test is running, I expect to post the results within an hour or 
two.


Well, my system crashed twice while running the procedure...
By "crashed" I mean : the machine no longer pings, and nothing is logged 
in kern.log unfortunately :


[ 7096.735731] BTRFS info (device dm-3): qgroup scan completed 
(inconsistency flag cleared)
[ 7172.614851] BTRFS info (device dm-3): qgroup scan completed 
(inconsistency flag cleared)
[ 7242.870259] BTRFS info (device dm-3): qgroup scan completed 
(inconsistency flag cleared)
[ 7321.466931] BTRFS info (device dm-3): qgroup scan completed 
(inconsistency flag cleared)

[0.00] Initializing cgroup subsys cpuset

The even stranger part is that the last 2 stdout dump files exist but 
are empty :


-rw-r--r-- 1 root root   21 Sep 18 10:29 snap32.step5
-rw-r--r-- 1 root root 3.2K Sep 18 10:29 snap32.step6
-rw-r--r-- 1 root root 3.2K Sep 18 10:29 snap33.step1
-rw-r--r-- 1 root root 3.3K Sep 18 10:29 snap33.step3
-rw-r--r-- 1 root root   21 Sep 18 10:30 snap33.step5
-rw-r--r-- 1 root root 3.3K Sep 18 10:30 snap33.step6
-rw-r--r-- 1 root root 3.3K Sep 18 10:30 snap34.step1
-rw-r--r-- 1 root root0 Sep 18 10:30 snap34.step3 <==
-rw-r--r-- 1 root root0 Sep 18 10:30 snap34.step5 <==

The mentioned steps are as follows :

0) Rsync data from the next ext4 "snapshot" to the subvolume
1) Do 'sync; btrfs qgroup show -⁠prce -⁠-⁠raw' and save the output <==
2) Create the needed readonly snapshot on btrfs
3) Do 'sync; btrfs qgroup show -⁠prce -⁠-⁠raw' and save the output <==
4) Avoid doing IO if possible until step 6)
5) Do 'btrfs quota rescan -⁠w' and save it <==
6) Do 'sync; btrfs qgroup show -⁠prce -⁠-⁠raw' and save the output <==

The resulting files are available here: 
http://speed47.net/tmp2/qgroup.tar.gz
The run2 is the more complete one, during run1 the machine crashed even 
faster.
It's interesting to note, however, that it seems to have crashed the 
same way and at the same step in the process.


As the machine is now, qgroups seems OK :

~# btrfs qgroup show -pcre --raw /tank/
qgroupid  rfer  excl max_rfer max_excl parent  
child
       --  
-
0/5  32768 32768 none none --- 
---
0/1906   3315696058368 3315696058368 none none --- 
---
0/1909249901842432  249901842432 none none --- 
---
0/1911   2109174587392 2109174587392 none none --- 
---
0/3270 47454601216   47454601216 none none --- 
---
0/3314 46408499200 32768 none none --- 
---
0/3341 14991097856 32768 none none --- 
---
0/3367 48371580928   48371580928 none none --- 
---
0/5335 56523751424 280592384 none none --- 
---
0/5336 601752535042599960576 none none --- 
---
0/5337 45751746560 250888192 none none --- 
---
0/5338 45804650496 186531840 none none --- 
---
0/5339 45875167232 190521344 none none --- 
---
0/5340 45933486080327680 none none --- 
---
0/5341 45933502464344064 none none --- 
---
0/5342 46442815488  35454976 none none --- 
---
0/5343 46442520576  30638080 none none --- 
---
0/5344 46448312320  36495360 none none --- 
---
0/5345 46425235456  86204416 none none --- 
---
0/5346 46081941504 119398400 none none --- 
---
0/5347 46402715648  55615488 none none --- 
---
0/5348 46403534848  50528256 none none --- 
---
0/5349 45486301184  91463680 none none --- 
---
0/5351 46414635008393216

Re: kernel BUG at linux-4.2.0/fs/btrfs/extent-tree.c:1833 on rebalance

[Stéphane Lesimple]

Le 2015-09-18 12:15, Stéphane Lesimple a écrit :

Le 2015-09-18 09:36, Stéphane Lesimple a écrit :

Sure, I did a quota disable / quota enable before running the snapshot
debug procedure, so the qgroups were clean again when I started :

qgroupid  rfer  excl max_rfer max_excl parent  
child
       --  
-
0/5  16384 16384 none none --- 
---
0/1906   1657848029184 1657848029184 none none --- 
---
0/1909124950921216  124950921216 none none --- 
---
0/1911   1054587293696 1054587293696 none none --- 
---
0/3270 23727300608   23727300608 none none --- 
---
0/3314 23221784576   23221784576 none none --- 
---
0/3341  74792755207479275520 none none --- 
---
0/3367 24185790464   24185790464 none none --- 
---


The test is running, I expect to post the results within an hour or 
two.


Well, my system crashed twice while running the procedure...
By "crashed" I mean : the machine no longer pings, and nothing is
logged in kern.log unfortunately :

[ 7096.735731] BTRFS info (device dm-3): qgroup scan completed
(inconsistency flag cleared)
[ 7172.614851] BTRFS info (device dm-3): qgroup scan completed
(inconsistency flag cleared)
[ 7242.870259] BTRFS info (device dm-3): qgroup scan completed
(inconsistency flag cleared)
[ 7321.466931] BTRFS info (device dm-3): qgroup scan completed
(inconsistency flag cleared)
[0.00] Initializing cgroup subsys cpuset

The even stranger part is that the last 2 stdout dump files exist but
are empty :

-rw-r--r-- 1 root root   21 Sep 18 10:29 snap32.step5
-rw-r--r-- 1 root root 3.2K Sep 18 10:29 snap32.step6
-rw-r--r-- 1 root root 3.2K Sep 18 10:29 snap33.step1
-rw-r--r-- 1 root root 3.3K Sep 18 10:29 snap33.step3
-rw-r--r-- 1 root root   21 Sep 18 10:30 snap33.step5
-rw-r--r-- 1 root root 3.3K Sep 18 10:30 snap33.step6
-rw-r--r-- 1 root root 3.3K Sep 18 10:30 snap34.step1
-rw-r--r-- 1 root root0 Sep 18 10:30 snap34.step3 <==
-rw-r--r-- 1 root root0 Sep 18 10:30 snap34.step5 <==

The mentioned steps are as follows :

0) Rsync data from the next ext4 "snapshot" to the subvolume
1) Do 'sync; btrfs qgroup show -⁠prce -⁠-⁠raw' and save the output <==
2) Create the needed readonly snapshot on btrfs
3) Do 'sync; btrfs qgroup show -⁠prce -⁠-⁠raw' and save the output <==
4) Avoid doing IO if possible until step 6)
5) Do 'btrfs quota rescan -⁠w' and save it <==
6) Do 'sync; btrfs qgroup show -⁠prce -⁠-⁠raw' and save the output <==

The resulting files are available here: 
http://speed47.net/tmp2/qgroup.tar.gz
The run2 is the more complete one, during run1 the machine crashed even 
faster.

It's interesting to note, however, that it seems to have crashed the
same way and at the same step in the process.


Actually about that, I forgot I did set up netconsole before starting 
the second run after the first "muted" crash, and it did work : even if 
I have no logs in kern.log, netconsole managed to send them to my other 
machine before going down, so here it is :


---
[ 5738.172692] BUG: unable to handle kernel NULL pointer dereference at 
01f0
[ 5738.172702] IP: [] start_transaction+0x1b/0x580 
[btrfs]

[ 5738.172719] PGD c0aa7067 PUD c0aa6067 PMD 0
[ 5738.172723] Oops:  [#1] SMP
[ 5738.172726] Modules linked in: netconsole configfs xts gf128mul drbg 
ansi_cprng xt_multiport xt_comment xt_conntrack xt_nat xt_tcpudp 
nfnetlink_queue nfnetlink_log nfnetlink nf_conntrack_ftp 
nf_conntrack_sane iptable_security iptable_filter iptable_mangle 
iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat 
nf_conntrack iptable_raw ip_tables x_tables nfsd auth_rpcgss nfs_acl nfs 
cmac dm_crypt rfcomm bnep lockd grace sunrpc fscache binfmt_misc 
intel_rapl snd_hda_codec_realtek iosf_mbi x86_pkg_temp_thermal 
intel_powerclamp kvm_intel snd_hda_codec_generic snd_hda_intel 
snd_hda_codec kvm eeepc_wmi asus_wmi snd_hda_core btusb sparse_keymap 
btrtl snd_hwdep btbcm snd_pcm btintel 8021q bluetooth snd_seq_midi 
dm_multipath snd_seq_midi_event garp snd_rawmidi mrp snd_seq stp llc 
snd_seq_device snd_timer crct10dif_pclmul crc32_pclmul snd 
ghash_clmulni_intel cryptd serio_raw soundcore mei_me mei lpc_ich shpchp 
mac_hid parport_pc ppdev nct6775 hwmon_vid coretemp lp parport btrfs 
raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor 
async_tx xor raid6_pq raid0 multipath linear nbd raid1 i915 e1000e 
i2c_algo_bit drm_kms_helper syscopyarea ptp sysfillrect sysimgblt 
fb_sys_fops psmouse ahci drm libahci pps_core wmi video [last unloaded: 
netconsole]
[ 5738.172831] CPU: 1 PID: 10932 Comm: kworker/u4:14 Not tainted 
4.3.0-rc1 #1
[ 5738.172833] Hardware name: ASUS All Series/H87I-PLUS, BIOS 1005 
01/06/2014
[ 5738.172843] Workqueue

Re: kernel BUG at linux-4.2.0/fs/btrfs/extent-tree.c:1833 on rebalance

[Stéphane Lesimple]

Le 2015-09-17 05:03, Qu Wenruo a écrit :

Stéphane Lesimple wrote on 2015/09/16 22:41 +0200:

Le 2015-09-16 22:18, Duncan a écrit :
Stéphane Lesimple posted on Wed, 16 Sep 2015 15:04:20 +0200 as 
excerpted:




Well actually it's the (d) option ;)
I activate the quota feature for only one reason : being able to track
down how much space my snapshots are taking.


Yeah, that's completely one of the ideal use case of btrfs qgroup.

But I'm quite curious about the btrfsck error report on qgroup.

If btrfsck report such error, it means either I'm too confident about
the recent qgroup accounting rework, or btrfsck has some bug which I
didn't take much consideration during the kernel rework.

Would you please provide the full result of previous btrfsck with 
qgroup error?


Sure, I've saved the log somewhere just in case, here your are :

Counts for qgroup id: 3359 are different
our:referenced 7530119168 referenced compressed 7530119168
disk:   referenced 7530086400 referenced compressed 7530086400
diff:   referenced 32768 referenced compressed 32768
our:exclusive 49152 exclusive compressed 49152
disk:   exclusive 32768 exclusive compressed 32768
diff:   exclusive 16384 exclusive compressed 16384
Counts for qgroup id: 3361 are different
our:referenced 7530119168 referenced compressed 7530119168
disk:   referenced 7530086400 referenced compressed 7530086400
diff:   referenced 32768 referenced compressed 32768
our:exclusive 49152 exclusive compressed 49152
disk:   exclusive 32768 exclusive compressed 32768
diff:   exclusive 16384 exclusive compressed 16384
Counts for qgroup id: 3362 are different
our:referenced 7530119168 referenced compressed 7530119168
disk:   referenced 7530086400 referenced compressed 7530086400
diff:   referenced 32768 referenced compressed 32768
our:exclusive 49152 exclusive compressed 49152
disk:   exclusive 32768 exclusive compressed 32768
diff:   exclusive 16384 exclusive compressed 16384
Counts for qgroup id: 3363 are different
our:referenced 7530119168 referenced compressed 7530119168
disk:   referenced 7530086400 referenced compressed 7530086400
diff:   referenced 32768 referenced compressed 32768
our:exclusive 49152 exclusive compressed 49152
disk:   exclusive 32768 exclusive compressed 32768
diff:   exclusive 16384 exclusive compressed 16384
Counts for qgroup id: 3361 are different
our:referenced 7530119168 referenced compressed 7530119168
disk:   referenced 7530086400 referenced compressed 7530086400
diff:   referenced 32768 referenced compressed 32768
our:exclusive 49152 exclusive compressed 49152
disk:   exclusive 32768 exclusive compressed 32768
diff:   exclusive 16384 exclusive compressed 16384
Counts for qgroup id: 3362 are different
our:referenced 7530119168 referenced compressed 7530119168
disk:   referenced 7530086400 referenced compressed 7530086400
diff:   referenced 32768 referenced compressed 32768
our:exclusive 49152 exclusive compressed 49152
disk:   exclusive 32768 exclusive compressed 32768
diff:   exclusive 16384 exclusive compressed 16384
Counts for qgroup id: 3363 are different
our:referenced 7530119168 referenced compressed 7530119168
disk:   referenced 7530086400 referenced compressed 7530086400
diff:   referenced 32768 referenced compressed 32768
our:exclusive 49152 exclusive compressed 49152
disk:   exclusive 32768 exclusive compressed 32768
diff:   exclusive 16384 exclusive compressed 16384
Counts for qgroup id: 3364 are different
our:referenced 7530119168 referenced compressed 7530119168
disk:   referenced 7530086400 referenced compressed 7530086400
diff:   referenced 32768 referenced compressed 32768
our:exclusive 49152 exclusive compressed 49152
disk:   exclusive 32768 exclusive compressed 32768
diff:   exclusive 16384 exclusive compressed 16384
Counts for qgroup id: 3365 are different
our:referenced 7530119168 referenced compressed 7530119168
disk:   referenced 7530086400 referenced compressed 7530086400
diff:   referenced 32768 referenced compressed 32768
our:exclusive 49152 exclusive compressed 49152
disk:   exclusive 32768 exclusive compressed 32768
diff:   exclusive 16384 exclusive compressed 16384
Counts for qgroup id: 3366 are different
our:referenced 7530119168 referenced compressed 7530119168
disk:   referenced 7530086400 referenced compressed 7530086400
diff:   referenced 32768 referenced compressed 32768
our:exclusive 16384 exclusive compressed 16384
disk:   exclusive 16384 exclusive compressed 16384

Re: kernel BUG at linux-4.2.0/fs/btrfs/extent-tree.c:1833 on rebalance

[Stéphane Lesimple]

Le 2015-09-16 15:04, Stéphane Lesimple a écrit :

I also disabled quota because it has almost for sure nothing
to do with the bug


As it turns out, it seems that this assertion was completely wrong.

I've got balance running for more than 16 hours now, without a crash. 
This is almost 50% of the work done without any issue. Before, a crash 
would happen within minutes, sometimes 1 hour, but not much more. The 
problem is, I didn't change anything to the filesystem, well, appart 
from the benign quota disable. So Qu's question about the qgroups errors 
in fsck made me wonder : if I activate quota again, it'll still continue 
to balance flawlessly, right ?


Well, it doesn't. I just ran btrfs quota enable on my filesystem, it 
completed successfully after some minutes (rescan -s said that no rescan 
was pending). Then less than 5 minutes later, the kernel crashed, at the 
same BUG_ON() than usually :


[60156.062082] BTRFS info (device dm-3): relocating block group 
972839452672 flags 129

[60185.203626] BTRFS info (device dm-3): found 1463 extents
[60414.452890] {btrfs} in insert_inline_extent_backref, got owner < 
BTRFS_FIRST_FREE_OBJECTID
[60414.452894] {btrfs} with bytenr=5197436141568 num_bytes=16384 
parent=5336636473344 root_objectid=3358 owner=1 offset=0 refs_to_add=1 
BTRFS_FIRST_FREE_OBJECTID=256

[60414.452924] [ cut here ]
[60414.452928] kernel BUG at fs/btrfs/extent-tree.c:1837!

owner is=1 again at this point in the code (this is still kernel 
4.3.0-rc1 with my added printks).


So I'll disable quota, again, and resume the balance. If I'm right, it 
should proceed without issue for 18 more hours !


Qu, my filesystem is at your disposal :)

--
Stéphane.


--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: kernel BUG at linux-4.2.0/fs/btrfs/extent-tree.c:1833 on rebalance

[Stéphane Lesimple]

Le 2015-09-17 08:29, Stéphane Lesimple a écrit :

Le 2015-09-16 15:04, Stéphane Lesimple a écrit :

I also disabled quota because it has almost for sure nothing
to do with the bug


As it turns out, it seems that this assertion was completely wrong.

I've got balance running for more than 16 hours now, without a crash.
This is almost 50% of the work done without any issue. Before, a crash
would happen within minutes, sometimes 1 hour, but not much more. The
problem is, I didn't change anything to the filesystem, well, appart
from the benign quota disable. So Qu's question about the qgroups
errors in fsck made me wonder : if I activate quota again, it'll still
continue to balance flawlessly, right ?

Well, it doesn't. I just ran btrfs quota enable on my filesystem, it
completed successfully after some minutes (rescan -s said that no
rescan was pending). Then less than 5 minutes later, the kernel
crashed, at the same BUG_ON() than usually :

[60156.062082] BTRFS info (device dm-3): relocating block group
972839452672 flags 129
[60185.203626] BTRFS info (device dm-3): found 1463 extents
[60414.452890] {btrfs} in insert_inline_extent_backref, got owner <
BTRFS_FIRST_FREE_OBJECTID
[60414.452894] {btrfs} with bytenr=5197436141568 num_bytes=16384
parent=5336636473344 root_objectid=3358 owner=1 offset=0 refs_to_add=1
BTRFS_FIRST_FREE_OBJECTID=256
[60414.452924] [ cut here ]
[60414.452928] kernel BUG at fs/btrfs/extent-tree.c:1837!

owner is=1 again at this point in the code (this is still kernel
4.3.0-rc1 with my added printks).

So I'll disable quota, again, and resume the balance. If I'm right, it
should proceed without issue for 18 more hours !


Damn, wrong again. It just re-crashed without quota enabled :(
The fact that it went perfectly well for 17+ hours and crashed minutes 
after I reactivated quota might be by complete chance then ...


[ 5487.706499] {btrfs} in insert_inline_extent_backref, got owner < 
BTRFS_FIRST_FREE_OBJECTID
[ 5487.706504] {btrfs} with bytenr=6906661109760 num_bytes=16384 
parent=6905020874752 root_objectid=18446744073709551608 owner=1 offset=0 
refs_to_add=1 BTRFS_FIRST_FREE_OBJECTID=256

[ 5487.706536] [ cut here ]
[ 5487.706539] kernel BUG at fs/btrfs/extent-tree.c:1837!

For reference, the crash I had earlier this morning was as follows :

[60414.452894] {btrfs} with bytenr=5197436141568 num_bytes=16384 
parent=5336636473344 root_objectid=3358 owner=1 offset=0 refs_to_add=1 
BTRFS_FIRST_FREE_OBJECTID=256


So, this is a completely different part of the filesystem.
The bug is always the same though, owner=1 where it shouldn't be < 256.

Balance cancelled.

To me, it sounds like some sort of race condition. But I'm out of ideas 
on what to test now.


--
Stéphane.

--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: kernel BUG at linux-4.2.0/fs/btrfs/extent-tree.c:1833 on rebalance

[Stéphane Lesimple]

Le 2015-09-17 08:42, Qu Wenruo a écrit :

Stéphane Lesimple wrote on 2015/09/17 08:11 +0200:

Le 2015-09-17 05:03, Qu Wenruo a écrit :

Stéphane Lesimple wrote on 2015/09/16 22:41 +0200:

Le 2015-09-16 22:18, Duncan a écrit :

Stéphane Lesimple posted on Wed, 16 Sep 2015 15:04:20 +0200 as
excerpted:



Well actually it's the (d) option ;)
I activate the quota feature for only one reason : being able to 
track

down how much space my snapshots are taking.


Yeah, that's completely one of the ideal use case of btrfs qgroup.

But I'm quite curious about the btrfsck error report on qgroup.

If btrfsck report such error, it means either I'm too confident about
the recent qgroup accounting rework, or btrfsck has some bug which I
didn't take much consideration during the kernel rework.

Would you please provide the full result of previous btrfsck with
qgroup error?


Sure, I've saved the log somewhere just in case, here your are :

[...]

Thanks for your log, pretty interesting result.

BTW, did you enabled qgroup from old kernel earlier than 4.2-rc1?
If so, I would be much relaxed as they can be the problem of old 
kernels.


The mkfs.btrfs was done under 3.19, but I'm almost sure I enabled quota 
under 4.2.0 precisely. My kern.log tends to confirm that (looking for 
'qgroup scan completed').



If it's OK for you, would you please enable quota after reproducing
the bug and use for sometime and recheck it?


Sure, I've just reproduced the bug twice as I wanted, and posted the 
info, so now I've cancelled the balance and I can reenable quota. Will 
do it under 4.3.0-rc1. I'll keep you posted if btrfsck complains about 
it in the following days.


Regards,

--
Stéphane.

--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: kernel BUG at linux-4.2.0/fs/btrfs/extent-tree.c:1833 on rebalance

[Stéphane Lesimple]

Le 2015-09-17 10:11, Qu Wenruo a écrit :

Stéphane Lesimple wrote on 2015/09/17 10:02 +0200:

Le 2015-09-17 08:42, Qu Wenruo a écrit :

Stéphane Lesimple wrote on 2015/09/17 08:11 +0200:

Le 2015-09-17 05:03, Qu Wenruo a écrit :

Stéphane Lesimple wrote on 2015/09/16 22:41 +0200:

Le 2015-09-16 22:18, Duncan a écrit :

Stéphane Lesimple posted on Wed, 16 Sep 2015 15:04:20 +0200 as
excerpted:



Well actually it's the (d) option ;)
I activate the quota feature for only one reason : being able to 
track

down how much space my snapshots are taking.


Yeah, that's completely one of the ideal use case of btrfs qgroup.

But I'm quite curious about the btrfsck error report on qgroup.

If btrfsck report such error, it means either I'm too confident 
about
the recent qgroup accounting rework, or btrfsck has some bug which 
I

didn't take much consideration during the kernel rework.

Would you please provide the full result of previous btrfsck with
qgroup error?


Sure, I've saved the log somewhere just in case, here your are :

[...]

Thanks for your log, pretty interesting result.

BTW, did you enabled qgroup from old kernel earlier than 4.2-rc1?
If so, I would be much relaxed as they can be the problem of old 
kernels.


The mkfs.btrfs was done under 3.19, but I'm almost sure I enabled 
quota

under 4.2.0 precisely. My kern.log tends to confirm that (looking for
'qgroup scan completed').


Emmm, seems I need to pay more attention on this case now.
Any info about the workload for this btrfs fs?




If it's OK for you, would you please enable quota after reproducing
the bug and use for sometime and recheck it?


Sure, I've just reproduced the bug twice as I wanted, and posted the
info, so now I've cancelled the balance and I can reenable quota. Will
do it under 4.3.0-rc1. I'll keep you posted if btrfsck complains about
it in the following days.

Regards,


Thanks for your patience and detailed report.


You're very welcome.


But I still have another question, did you do any snapshot deletion
after quota enabled?
(I'll assume you did it, as there are a lot of backup snapshot, old
ones should be already deleted)


Actually no : this btrfs system is quite new (less than a week old) as 
I'm migrating from mdadm(raid1)+ext4 to btrfs. So those snapshots were 
actually rsynced one by one from my hardlinks-based "snapshots" under 
ext4 (those pseudo-snapshots are created using a program named 
"rsnapshot", if you know it. This is basically a wrapper to cp -la). I 
didn't activate yet an automatic snapshot/delete on my btrfs system, due 
to the bugs I'm tripping on. So no snapshot was deleted.



That's one of the known bug and Mark is working on it actively.
If you delete non-empty snapshot a lot, then I'd better add a hot fix
to mark qgroup inconsistent after snapshot delete, and trigger a
rescan if possible.


I've made a btrfs-image of the filesystem just before disabling quotas 
(which I did to get a clean btrfsck and eliminate quotas from the 
equation trying to reproduce the bug I have). Would it be of any use if 
I drop it somewhere for you to pick it up ? (2.9G in size).


In the meantime, I've reactivated quotas, umounted the filesystem and 
ran a btrfsck on it : as you would expect, there's no qgroup problem 
reported so far. I'll clear all my snapshots, run an quota rescan, then 
re-create them one by one by rsyncing from my ext4 system I still have. 
Maybe I'll run into the issue again.


--
Stéphane.

--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: kernel BUG at linux-4.2.0/fs/btrfs/extent-tree.c:1833 on rebalance

[Stéphane Lesimple]

Le 2015-09-17 12:41, Qu Wenruo a écrit :

In the meantime, I've reactivated quotas, umounted the filesystem and
ran a btrfsck on it : as you would expect, there's no qgroup problem
reported so far.


At least, rescan code is working without problem.


I'll clear all my snapshots, run an quota rescan, then
re-create them one by one by rsyncing from my ext4 system I still 
have.

Maybe I'll run into the issue again.



Would you mind to do the following check for each subvolume rsync?

1) Do 'sync; btrfs qgroup show -prce --raw' and save the output
2) Create the needed snapshot
3) Do 'sync; btrfs qgroup show -prce --raw' and save the output
4) Avoid doing IO if possible until step 6)
5) Do 'btrfs quota rescan -w' and save it
6) Do 'sync; btrfs qgroup show -prce --raw' and save the output
7) Rsync data from ext4 to the newly created snapshot

The point is, as you mentioned, rescan is working fine, we can compare
output from 3), 6) and 1) to see which qgroup accounting number
changes.

And if differs, which means the qgroup update at write time OR
snapshot creation has something wrong, at least we can locate the
problem to qgroup update routine or snapshot creation.


I was about to do that, but first there's something that sounds strange 
: I've begun by trashing all my snapshots, then ran a quota rescan, and 
waited for it to complete, to start on a sane base.

However, this is the output of qgroup show now :

qgroupid  rfer excl max_rfer max_excl 
parent  child
      
--  -
0/5  1638416384 none none 
--- ---
0/1906   16578480291841657848029184 none none 
--- ---
0/1909124950921216 124950921216 none none 
--- ---
0/1911   10545872936961054587293696 none none 
--- ---
0/3270 23727300608  23727300608 none none 
--- ---
0/3314 23206055936  23206055936 none none 
--- ---
0/3317 184729968640 none none 
--- ---
0/3318 22235709440 18446744073708421120 none none 
--- ---
0/3319 222403338240 none none 
--- ---
0/3320 222896087040 none none 
--- ---
0/3321 222896087040 none none 
--- ---
0/3322 184611512320 none none 
--- ---
0/3323 184239022080 none none 
--- ---
0/3324 184239022080 none none 
--- ---
0/3325 184635064320 none none 
--- ---
0/3326 184635064320 none none 
--- ---
0/3327 184635064320 none none 
--- ---
0/3328 184635064320 none none 
--- ---
0/3329 185854279680 none none 
--- ---
0/3330 18621472768 18446744073251348480 none none 
--- ---
0/3331 186214727680 none none 
--- ---
0/3332 186214727680 none none 
--- ---
0/ 187830763520 none none 
--- ---
0/3334 187998044160 none none 
--- ---
0/3335 187998044160 none none 
--- ---
0/3336 188162170880 none none 
--- ---
0/3337 188162662400 none none 
--- ---
0/3338 188162662400 none none 
--- ---
0/3339 188162662400 none none 
--- ---
0/3340 188163645440 none none 
--- ---
0/3341  7530119168   7530119168 none none 
--- ---
0/3342  49192837120 none none 
--- ---
0/3343  49217249280 none none 
--- ---
0/3344  49217249280 none none 
--- ---
0/3345  6503317504 18446744073690902528 none none 
--- ---
0/3346  65034526720 none none 
--- ---
0/3347  65095147520 none none 
--- ---
0/3348  65157939200 none none 
--- ---
0/3349  65157939200 none none 
--- ---
0/3350  65186856960 none none 
--- ---
0/3351  65215119360 none none 
---  

Re: kernel BUG at linux-4.2.0/fs/btrfs/extent-tree.c:1833 on rebalance

[Stéphane Lesimple]

Le 2015-09-16 07:02, Duncan a écrit :
Stéphane Lesimple posted on Tue, 15 Sep 2015 23:47:01 +0200 as 
excerpted:



Le 2015-09-15 16:56, Josef Bacik a écrit :

On 09/15/2015 10:47 AM, Stéphane Lesimple wrote:
I've been experiencing repetitive "kernel BUG" occurences in the 
past

few days trying to balance a raid5 filesystem after adding a new
drive.
It occurs on both 4.2.0 and 4.1.7, using 4.2 userspace tools.


I've ran a scrub on this filesystem after the crash happened twice,
and if found no errors.

The BUG_ON() condition that my filesystem triggers is the following 
:


BUG_ON(owner < BTRFS_FIRST_FREE_OBJECTID);
// in insert_inline_extent_backref() of extent-tree.c.


Does btrfsck complain at all?


Just to elucidate a bit...
[...]
Which is where btrfs check comes in and why JB asked you to run it, 
since

unlike scrub, check is designed to catch filesystem logic errors.


Thanks for your clarification Duncan, that perfectly makes sense.


You're right, even if btrfs scrub didn't complain, btrfsck does :

checking extents
bad metadata [4179166806016, 4179166822400) crossing stripe boundary
bad metadata [4179166871552, 4179166887936) crossing stripe boundary
bad metadata [4179166937088, 4179166953472) crossing stripe boundary


This is an actively in-focus bug ATM, and while I'm not a dev and can't
tell you for sure that it's behind the specific balance-related crash 
and

traces you posted (tho I believe it so), it certainly has the potential
to be that serious, yes.

The most common cause is a buggy btrfs-convert that was creating 
invalid
btrfs when converting from ext* at one point.  AFAIK they've hotfixed 
the
immediate convert issue, but are still actively working on a longer 
term
proper fix.  Meanwhile, while btrfs check does now detect the issue 
(and

even that is quite new code, added in 4.2 I believe), there's still no
real fix for what was after all a defective btrfs from the moment the
convert was done.
[...]
If, however, you created the filesystem using mkfs.btrfs, then the
problem must have occurred some other way.  Whether there's some other
cause beyond the known cause, a buggy btrfs-convert, has in fact been 
in

question, so in this case the devs are likely to be quite interested
indeed in your case and perhaps the filesystem history that brought you
to this point.  The ultimate fix is likely to be the same (unless the
devs have you test new fix code for btrfs check --repair), but I'd
strongly urge you to delay blowing away the filesystem, if possible,
until the devs have a chance to ask you to run other diagnostics and
perhaps even get a btrfs-image for them, since you may well have
accidentally found a corner-case they'll have trouble reproducing,
without your information.


Nice to know that this bug was already somewhat known, but I can confirm 
that it actually doesn't come from an ext4 conversion on my case.


Here is the filesystem history, which is actually quite short :
- FS created from scratch, no convert, on 2x4T devices using mkfs.btrfs 
with raid1 metadata, raid5 data. This is using the 4.2 tools and kernel 
3.19, so a couple incompat features were turned on by default (such as 
skinny metadata).
- Approx. 4T worth of files copied to it, a bit less, I had around 30G 
free after the copy.

- Upgraded to kernel 4.2.0
- Added a third 4T device to the filesystem
- Ran a balance to get an even repartition of data/metadata among the 3 
drives
- Kernel BUG after a couple hours. The btrfs balance userspace tool 
segfaulted at the same time. Due to apport default configuration (damn 
you, Ubuntu !), core file was discarded, but I don't think the segfault 
is really interesting. The kernel trace is.


This was all done within ~1 week.

I've just created an image of the metadata, using btrfs-image -s. The 
image is 2.9G large, I can drop it somewhere in case a dev would like to 
have a look at it.


For what it's worth, I've been hitting another kernel BUG, almost 
certainly related, while trying to dev del the 3rd device, after 8 hours 
of work (kernel 4.1.7) :


kernel BUG at /home/kernel/COD/linux/fs/btrfs/extent-tree.c:2248!
in __btrfs_run_delayed_refs+0x11a1/0x1230 [btrfs]

Trace:
[] ? __percpu_counter_add+0x55/0x70
[] btrfs_run_delayed_refs.part.66+0x73/0x270 [btrfs]
[] btrfs_run_delayed_refs+0x17/0x20 [btrfs]
[] btrfs_should_end_transaction+0x49/0x60 [btrfs]
[] btrfs_drop_snapshot+0x472/0x880 [btrfs]
[] ? should_ignore_root.part.15+0x50/0x50 [btrfs]
[] merge_reloc_roots+0xd9/0x240 [btrfs]
[] relocate_block_group+0x269/0x670 [btrfs]
[] btrfs_relocate_block_group+0x1d6/0x2e0 [btrfs]
[] btrfs_relocate_chunk.isra.38+0x3e/0xc0 [btrfs]
[] btrfs_shrink_device+0x1d4/0x450 [btrfs]
[] btrfs_rm_device+0x323/0x810 [btrfs]
[] btrfs_ioctl+0x1e86/0x2b30 [btrfs]
[] ? filemap_map_pages+0x1d4/0x230
[] ? handle_mm_fault+0xd95/0x17e0
[] ? from_kgid_munged+0x12/0x20
[] ? cp_new_stat+0x140/0x160
[] do_vfs_ioctl+0x2f8/0x510
[] ? __do_page_fault+0x1b6/0x450
[] ? SYSC_news

Re: kernel BUG at linux-4.2.0/fs/btrfs/extent-tree.c:1833 on rebalance

[Stéphane Lesimple]

Le 2015-09-16 12:46, Holger Hoffstätte a écrit :

On 09/16/15 12:28, Stéphane Lesimple wrote:

Nice to know that this bug was already somewhat known, but I can
confirm that it actually doesn't come from an ext4 conversion on my
case.


In that case the "crossing stripe boundary" messages are false 
positives
in btrfs-progs-4.2: 
http://www.spinics.net/lists/linux-btrfs/msg47059.html


This should be fixed in the next release.


Out of curiosity I compiled the btrfs-progs-4.2 release patched with the 
diff you're referencing to fix the off-by-one error, and ran a btrfsck 
again.
Indeed those errors disappear and my filesystem seems clean in this 
regard. I also disabled quota because it has almost for sure nothing to 
do with the bug, and now btrsfck is 100% happy:


-
checking extents
checking free space cache
checking fs roots
checking csums
checking root refs
Checking filesystem on 
/dev/mapper/luks-WDC_WD30EZRX-00MMMB0_WD-WCAWZ3013164

UUID: 6bec1608-d9c0-453e-87eb-8b8663c9010d
found 2922178546042 bytes used err is 0
total csum bytes: 2849102736
total tree bytes: 4697341952
total fs tree bytes: 1276395520
total extent tree bytes: 90963968
btree space waste bytes: 640514848
file data blocks allocated: 2959998808064
 referenced 2959997575168
btrfs-progs v4.2-dirty
-

So this is even more interesting, my filesystem is reported by scrub and 
fsck as being in perfect shape, but still crashes the kernel from time 
to time on balance.


Next step: reboot under 4.3.0-rc1 with my printk's, run a balance, log 
the crash, reboot, balance again, crash again, and compare. If the same 
filesystem spot triggers the crash twice then it would be an undetected 
metadata/filesystem internal integrity corruption, if it crashes at 2 
different spots, then maybe it's some kind of race condition that, for 
some reason, my system hits way more often than others.


--
Stéphane.

--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: kernel BUG at linux-4.2.0/fs/btrfs/extent-tree.c:1833 on rebalance

[Stéphane Lesimple]

Le 2015-09-16 22:18, Duncan a écrit :
Stéphane Lesimple posted on Wed, 16 Sep 2015 15:04:20 +0200 as 
excerpted:



Le 2015-09-16 12:46, Holger Hoffstätte a écrit :



I also disabled quota because it has almost for sure nothing to
do with the bug, and now btrsfck is 100% happy:


Yes.  Quotas have been a continuing issue on btrfs.  AFAIK, they're on
the third rewrite now, and still have some bugs to work out.  So what
I've been recommending is unless you're (a) directly and specifically
working with the devs to find and fix the quota issues (in which case
please keep at it! =:^), either you (b) really depend on quotas working
and btrfs isn't appropriate for you at this time, since they're known 
to
be buggy, so use a more mature filesystem where they're known to work, 
or
(c) you don't actually need quotas at all, so disable them and remove 
the
quota tracking metadata, thus avoiding the bugs in the feature 
entirely.

=:^)


Well actually it's the (d) option ;)
I activate the quota feature for only one reason : being able to track 
down how much space my snapshots are taking.
I've been using ZFS in the past, and I was really missing the "zfs list" 
command that is able to tell you how much space a given snapshot is 
actually taking under btrfs.
With quota enabled, I was able to somehow mimic zfs list with a perl 
script I wrote, btrfs-list :


PATHID TYPE REFER  USED
'tank'  -1   df - 2.66T 
(13.26G free)

   /tank 5  vol48.00K48.00K
   media  1906   subvol 1.04T 1.04T
   photos 1909   subvol   116.37G   116.37G
   main   1911   subvol   973.23G   973.23G
   bkp-slash  3270   subvol15.86G15.86G
   bkp-quasar 3314   subvol18.26G16.00K
  .snaps/bkp-quasar@2015-01-173317   rosnap17.77G40.76M
  .snaps/bkp-quasar@2015-03-063318   rosnap17.89G88.88M
  .snaps/bkp-quasar@2015-04-053319   rosnap17.92G90.97M
  .snaps/bkp-quasar@2015-05-313320   rosnap17.95G 1.02M
  .snaps/bkp-quasar@2015-06-133321   rosnap17.95G   760.00K
  .snaps/bkp-quasar@2015-07-263322   rosnap18.19G17.88M
  .snaps/bkp-quasar@2015-07-313323   rosnap18.19G14.58M
  .snaps/bkp-quasar@2015-08-033324   rosnap18.19G17.43M
   bkp-liznodisk  3341   subvol 7.01G16.00K
  .snaps/bkp-liznodisk@2015-03-01 3342   rosnap 6.96G75.37M
  .snaps/bkp-liznodisk@2015-03-28 3343   rosnap 6.98G84.93M
  .snaps/bkp-liznodisk@2015-04-26 3344   rosnap 6.96G67.14M
  .snaps/bkp-liznodisk@2015-05-24 3345   rosnap 6.95G47.67M
  .snaps/bkp-liznodisk@2015-06-27 3346   rosnap 6.96G67.97M
  .snaps/bkp-liznodisk@2015-07-25 3347   rosnap 6.98G60.30M
  .snaps/bkp-liznodisk@2015-08-16 3348   rosnap 7.10G   159.44M
   bkp-skyline3367   subvol22.52G22.52G

I just pushed it to https://github.com/speed47/btrfs-list, if anybody is 
interested.


Anyway, balance is running again for 7+ hours, trying to reproduce the 
bug twice, but no crash yet ... should happen soon now !


--
Stéphane.

--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: kernel BUG at linux-4.2.0/fs/btrfs/extent-tree.c:1833 on rebalance

[Stéphane Lesimple]

Le 2015-09-15 16:56, Josef Bacik a écrit :

On 09/15/2015 10:47 AM, Stéphane Lesimple wrote:

I've been experiencing repetitive "kernel BUG" occurences in the past
few days trying to balance a raid5 filesystem after adding a new 
drive.

It occurs on both 4.2.0 and 4.1.7, using 4.2 userspace tools.


I've ran a scrub on this filesystem after the crash happened twice, 
and

if found no errors.

The BUG_ON() condition that my filesystem triggers is the following :

BUG_ON(owner < BTRFS_FIRST_FREE_OBJECTID);
// in insert_inline_extent_backref() of extent-tree.c.

I've compiled a fresh 4.3.0-rc1 with a couple added printk's just 
before

the BUG_ON(), to dump the parameters passed to
insert_inline_extent_backref() when the problem occurs.
Here is an excerpt of the resulting dmesg :

{btrfs} in insert_inline_extent_backref, got owner <
BTRFS_FIRST_FREE_OBJECTID
{btrfs} with bytenr=4557830635520 num_bytes=16384 parent=4558111506432
root_objectid=3339 owner=1 offset=0 refs_to_add=1
BTRFS_FIRST_FREE_OBJECTID=256
[ cut here ]
kernel BUG at fs/btrfs/extent-tree.c:1837!

I'll retry with the exact same kernel once I get the machine back up,
and see if the the bug happens again at the same filesystem spot or a
different one.
The variable amount of time after a balance start elapsed before I get
the bug suggests that this would be a different one.



Does btrfsck complain at all?


Thanks for your suggestion.
You're right, even if btrfs scrub didn't complain, btrfsck does :

checking extents
bad metadata [4179166806016, 4179166822400) crossing stripe boundary
bad metadata [4179166871552, 4179166887936) crossing stripe boundary
bad metadata [4179166937088, 4179166953472) crossing stripe boundary
[... some more ...]
extent buffer leak: start 4561066901504 len 16384
extent buffer leak: start 4561078812672 len 16384
extent buffer leak: start 4561078861824 len 16384
[... some more ...]
then some complains about mismatched counts for qgroups.

I can see from tbe btrfsck source code that the --repair will not work 
here, so I didn't try.


I'm not sure if those errors would be a cause or a consequence of the 
bug. As the filesystem was only a few days old and as there was always a 
balance running during the crashes, I would be tempted to think it might 
actually be a consequence, but I can't be sure.

In your experience, could these inconsistencies cause the crash ?

If you think so, then I'll btrfs dev del the 3rd device, then remount 
the array degraded with just 1 disk and create a new btrfs system from 
scratch on the second, then copy the data in single redundancy, then 
re-add the 2 disks and balance convert in raid5.


If you think not, then this array could still help you debug a corner 
case, and I can keep it that way for a couple days if more testing/debug 
is needed.


Thanks,

--
Stéphane
--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: kernel BUG at linux-4.2.0/fs/btrfs/extent-tree.c:1833 on rebalance

[Stéphane Lesimple]

I've been experiencing repetitive "kernel BUG" occurences in the past
few days trying to balance a raid5 filesystem after adding a new drive.
It occurs on both 4.2.0 and 4.1.7, using 4.2 userspace tools.


I've ran a scrub on this filesystem after the crash happened twice, and 
if found no errors.


The BUG_ON() condition that my filesystem triggers is the following :

BUG_ON(owner < BTRFS_FIRST_FREE_OBJECTID);
// in insert_inline_extent_backref() of extent-tree.c.

I've compiled a fresh 4.3.0-rc1 with a couple added printk's just before 
the BUG_ON(), to dump the parameters passed to 
insert_inline_extent_backref() when the problem occurs.

Here is an excerpt of the resulting dmesg :

{btrfs} in insert_inline_extent_backref, got owner < 
BTRFS_FIRST_FREE_OBJECTID
{btrfs} with bytenr=4557830635520 num_bytes=16384 parent=4558111506432 
root_objectid=3339 owner=1 offset=0 refs_to_add=1 
BTRFS_FIRST_FREE_OBJECTID=256

[ cut here ]
kernel BUG at fs/btrfs/extent-tree.c:1837!

I'll retry with the exact same kernel once I get the machine back up, 
and see if the the bug happens again at the same filesystem spot or a 
different one.
The variable amount of time after a balance start elapsed before I get 
the bug suggests that this would be a different one.


--
Stéphane.
--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html