How to debug very very slow file delete?

I had a tree with some amount of thousand files (less than 1 million) on top of md raid5.

It took 18H to rm it in 3 tries:

gargamel:/mnt/dshelf2/backup/polgara# time rm -rf current.todel/
real    1087m26.491s
user    0m2.448s
sys     4m42.012s

gargamel:/mnt/dshelf2/backup/polgara# btrfs fi show /mnt/btrfs_pool2
Label: btrfs_pool2  uuid: cb9df6d3-a528-4afc-9a45-4fed5ec358d6
        Total devices 1 FS bytes used 2.76TiB
        devid    1 size 7.28TiB used 3.43TiB path /dev/mapper/dshelf2

gargamel:/mnt/dshelf2/backup/polgara# btrfs fi df /mnt/btrfs_pool2
Data, single: total=3.28TiB, used=2.70TiB
System, DUP: total=8.00MiB, used=384.00KiB
System, single: total=4.00MiB, used=0.00
Metadata, DUP: total=73.50GiB, used=62.46GiB
Metadata, single: total=8.00MiB, used=0.00

This is running from
md8 : active raid5 sdf1[6] sdb1[5] sda1[3] sde1[2] sdd1[1]

      7814045696 blocks super 1.2 level 5, 512k chunk, algorithm 2 [5/5] [UUUUU]
      bitmap: 0/15 pages [0KB], 65536KB chunk

The filesystem is pretty new, it shouldn't be fragmented much.

dmesg shows a bit of this:

INFO: task rm:31885 blocked for more than 120 seconds.
      Not tainted 3.14.0-rc5-amd64-i915-preempt-20140216c #1

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message
rm D ffff880117e5a940 0 31885 31280 0x20020080
ffff8800169f3d10 0000000000000086 ffff8800169f3fd8 ffff880117e5a410 00000000000141c0 ffff880117e5a410 ffff88011d4f9e90 ffff88020c0109e8 0000000000000000 ffff88020c010800 ffff8801b6df55a0 ffff8800169f3d20

Call Trace:
 [<ffffffff8160c331>] schedule+0x73/0x75
 [<ffffffff8122a5f9>] wait_current_trans.isra.15+0x98/0xf4
 [<ffffffff810850c9>] ? finish_wait+0x65/0x65
 [<ffffffff8122ba9e>] start_transaction+0x48e/0x4f2
 [<ffffffff8122bb1d>] btrfs_start_transaction+0x1b/0x1d
 [<ffffffff8122cab4>] __unlink_start_trans+0x24/0xaf
 [<ffffffff812327ab>] btrfs_unlink+0x28/0xa0
 [<ffffffff8116176d>] vfs_unlink+0x90/0xdb
 [<ffffffff811618c0>] do_unlinkat+0x108/0x1da
 [<ffffffff810734c8>] ? mmdrop+0x11/0x20
 [<ffffffff8115d2db>] ? path_put+0x1e/0x21
 [<ffffffff811625c7>] SyS_unlinkat+0x22/0x2e
 [<ffffffff816171ac>] sysenter_dispatch+0x7/0x21

That said, it didn't happen much:

[38077.054841] INFO: task btrfs-cleaner:3536 blocked for more than 120 seconds.
[38077.521463] INFO: task rm:31885 blocked for more than 120 seconds.
[38077.926399] INFO: task cp:26645 blocked for more than 120 seconds.
[38078.346885] INFO: task btrfs:7430 blocked for more than 120 seconds.
[38198.921768] INFO: task btrfs-cleaner:3536 blocked for more than 120 seconds.
[38199.357367] INFO: task rm:31885 blocked for more than 120 seconds.
[38199.753897] INFO: task cp:26645 blocked for more than 120 seconds.
[38200.172729] INFO: task btrfs:7430 blocked for more than 120 seconds.
[56696.271850] INFO: task btrfs-transacti:3537 blocked for more than 120 seconds.
[56937.063142] INFO: task btrfs-cleaner:3536 blocked for more than 120 seconds.

Of course, all of those are bad, but I'm unfortunately used to seeing them It wasn't hanging forever every few minutes, so it looks like it was just working very slowly.

The problem does not seem to be just rm though, du is taking way way too long too. I started one, it's been running for 30mn now. Interestingly, sending ^C to that du takes 15 seconds to respond, so it seems that each system call is just slow.

I checked that btrfs scrub is not running.
What else can I check from here?

Thanks,
Marc

"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/  

"noatime" set?

What's your cpu hardware wait time?

And is not *the 512kByte raid chunk* going to give you horrendous write amplification?! For example, rm updates a few bytes in one 4kByte metadata block and the system has to then do a read-modify-write on 512kBytes...

Also, the 64MByte chunk bit-intent map will add a lot of head seeks to anything you do on that raid. (The map would be better on a separate SSD or other separate drive.)

So... That sort of setup is fine for archived data that is effectively read-only. You'll see poor performance for small writes/changes.

Hope that helps,
Martin

My question would be naive, but would it be possible to have a syscall or something to do a fast "rm -rf" or du ?

I think ceph might have the later actually.

Xavier Nicollet

I ran another test after typing the original Email:

gargamel:/mnt/dshelf2/backup/polgara# time du -sh 20140312-feisty/; time find 20140 312-feisty/ | wc -l
17G     20140312-feisty/
real    245m19.491s
user    0m2.108s
sys     1m0.508s

728507 <- number of files

real    11m41.853s <- 11mn to restat them when they should all be in cache ideally
user    0m1.040s
sys     0m4.360s

4 hours to stat 700K files. That's bad...
Even 11mn to restat them just to count them looks bad too.

I have relatime

gargamel:/mnt/dshelf2/backup/polgara# df .
Filesystem           1K-blocks       Used  Available Use% Mounted on
/dev/mapper/dshelf2 7814041600 3026472436 4760588292  39% /mnt/dshelf2/backup

gargamel:/mnt/dshelf2/backup/polgara# grep /mnt/dshelf2/backup /proc/mounts
/dev/mapper/dshelf2 /mnt/dshelf2/backup btrfs rw,relatime,compress=lzo,space_cache 0 0

Sorry, not sure how to get that.

That's probably not great, but
1) rm -rf should bunch a lot of writes together before they start hitting the block layer for writes, so I'm not sure that is too much a problem with the caching layer in between

2) this does not explain 4H to just run du with relatime, which shouldn't generate any writing, correct?
iostat seems to confirm:

gargamel:~# iostat /dev/md8 1 20
Linux 3.14.0-rc5-amd64-i915-preempt-20140216c (gargamel.svh.merlins.org)        03/25/2014      _x86_64_        (4 CPU)
avg-cpu:  %user   %nice %system %iowait  %steal   %idle  
          75.19    0.00   10.13    8.61    0.00    6.08
Device:            tps    kB_read/s    kB_wrtn/s    kB_read    kB_wrtn
md8              98.00       392.00         0.00        392          0
md8              96.00       384.00         0.00        384          0
md8              83.00       332.00         0.00        332          0
md8             153.00       612.00         0.00        612          0
md8              82.00       328.00         0.00        328          0
md8              55.00       220.00         0.00        220          0
md8              69.00       276.00         0.00        276          0

That's true for writing, but not reading, right?

So I agree with you that the write case can be improved, especially since I also have a layer of dmcrypt in the middle

gargamel:/mnt/dshelf2/backup/polgara# cryptsetup luksDump /dev/md8
LUKS header information for /dev/md8
Cipher name:    aes
Cipher mode:    xts-plain64
Hash spec:      sha1
Payload offset: 8192

(I used cryptsetup luksFormat --align-payload=8192 -s 256 -c aes-xts-plain64)

I'm still not convinced that a lot of file IO don't get all collated in memory before hitting disk in bigger blocks, but maybe not.

If I were to recreate this array entirely, what would you use for the raid creation and cryptsetup?

More generally, before I go through all that trouble (it will likely take 1 week of data copying back and forth), I'd like to debug why my reads are so slow first.

Thanks,
Marc

Well, that wouldn't hurt either, even if it wouldn't address my underlying problem.

Marc

"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/                         | PGP 1024R/763BE901

So, since then I found out in the thread
Subject: Re: btrfs on 3.14rc5 stuck on "btrfs_tree_read_lock sync"
that my btrfs filesystem has a clear problem, which Josef and Chris are still looking into.

Basically, I've had btrfs near deadlocks on this filesystem:

INFO: task btrfs-transacti:3633 blocked for more than 120 seconds.
Not tainted 3.14.0-rc5-amd64-i915-preempt-20140216c #1
INFO: task btrfs-cleaner:3571 blocked for more than 120 seconds.

Not tainted 3.14.0-amd64-i915-preempt-20140216 #2

They are thinking it's due to a balancing issue that 3.15 might fix.

One interesting piece of information I found out since yesterday is that now that I mounted the filesystem with -o ro,recovery , its speed as improved very noticeably.
I'm currently copying my data off it about 10x faster.

What follows is for people interested in optimization.

I have swraid5 with dmcrypt on top, and then btrfs.
http://superuser.com/questions/305716/bad-performance-with-linux-software-raid5-and-luks-encryption
says:
"LUKS has a botleneck, that is it just spawns one thread per block device.

Are you placing the encryption on top of the RAID 5? Then from the point of view of your OS you just have one device, then it is using just one thread for all those disks, meaning disks are working in a serial way rather than parallel."
but it was disputed in a reply.
Does someone know if this is still valid/correct in 3.14?

Since I'm going to recreate the filesystem considering the troubles I've had with it, I might as well do it better this time :)
(but doing the copy back will take days, so I'd rather get it right the first time)

How would you recommend I create the array when I rebuild it?

This filesystem contains may backup with many files, most small, and ideally identical stuff is hardlinked together (many files, many hardlinks)

gargamel:~# btrfs fi df /mnt/btrfs_pool2
Data, single: total=3.28TiB, used=2.29TiB
System, DUP: total=8.00MiB, used=384.00KiB
System, single: total=4.00MiB, used=0.00
Metadata, DUP: total=74.50GiB, used=70.11GiB  <<< muchos metadata
Metadata, single: total=8.00MiB, used=0.00

This is my current array:

gargamel:~# mdadm --detail /dev/md8
/dev/md8:
        Version : 1.2
  Creation Time : Thu Mar 25 20:15:00 2010
     Raid Level : raid5
     Array Size : 7814045696 (7452.05 GiB 8001.58 GB)
  Used Dev Size : 1953511424 (1863.01 GiB 2000.40 GB)
    Persistence : Superblock is persistent
  Intent Bitmap : Internal
         Layout : left-symmetric
     Chunk Size : 512K

#1 move the intent bitmap to another device. I have /boot on swraid1 with
ext4, so I'll likely use this.
#2 change chunk size to something smaller? 128K better?
#3 anything else?

Then, I used this for dmcrypt:
cryptsetup luksFormat --align-payload=8192 -s 256 -c aes-xts-plain64

The align-payload was good for my SSD, but probably not for a hard drive.
http://wiki.drewhess.com/wiki/Creating_an_encrypted_filesystem_on_a_partition
says
"To calculate this value, multiply your RAID chunk size in bytes by the number of data disks in the array (N/2 for RAID 1, N-1 for RAID 5 and N-2 for RAID 6), and divide by 512 bytes per sector."

So 512K * 4 / 512 = 4K
In other words, I can do align-payload=4096 for a small reduction of write amplification, or =1024 if I change my raid chunk size to 128K

Correct?

But from what I can see, those will only be small improvements compared to the btrfs performance I've seen which hopefully 3.15 will address in some way.

Other bits I found that can maybe help others:
http://superuser.com/questions/305716/bad-performance-with-linux-software-raid5-and-luks-encryption

This seems to help work around the write amplification a bit:
for i in /sys/block/md*/md/stripe_cache_size; do echo 16384 > $i; done

This looks like an easy thing, done.

If you have other suggestions/comments, please share :)

Thanks,
Marc

"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/  

One way to get an idea of where that's happening is to run the command with "strace -c" to build up a table of times spent in each system call, usecs per call (average) and number of calls.

Best of luck!
Chris

 Chris Samuel  :  http://www.csamuel.org/  :  Melbourne, VIC

If the devs can use this, I can provide this.

For now, the FS got even worse than that, it just hangs btrfs cleaner processes without me doing anything, so I think they got enough data on what is going wrong with it, although I'm not sure if it's fixed in 3.15 or not.

I'm waiting just a bit longer before destroying and rebuilding this filesystem, hence my other questions on how to it better for next time on the block level side.

Is anyone else using btrfs on top of dmcrypt and software raid 5?

Marc

"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/  

Marc MERLIN posted on Fri, 11 Apr 2014 10:23:46 -0700 as excerpted:

There may be others, but I haven't seen them active on-list. For active list users, I think you're leading the pack in that area. =:^/

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

I use Btrfs accessed via NBD over a LAN, physically stored on mdadm RAID5, a setup which is similar to yours in that the block device used for Btrfs has a somewhat limited throughput. But there were no problems with this whatsoever for the past couple of years (other than caused by unrelated h/w issues).

You could check if this slowness is caused by excessive fsync'ing, try running "time eatmydata rm -rf ....." next time. ( https://launchpad.net/libeatmydata )

With respect,
Roman

Maybe 'sysrq+w' can give an answer? We need to find what blocks new transaction.

-liubo

Just misread this thread, sorry...I'm reading the following story of the thread.

-liubo

I was debugging my why backup failed to run, and eventually found it was stuck on sync:
14080 18:18 btrfs_tree_read_lock sync

This was hung for hours on this lock.

Strangely, it looks like taking my sysrq-w hung the machine pretty hard for close to 30sec, but this seems to have unhung sync and in the end btrfs send completed after that.

Sysqrq-w is here:
http://marc.merlins.org/tmp/sysrq-btrfs-sync-hang.txt

Marc

"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/  

Try Chris's integration branch in a few hours and see if that fixes it.
Thanks,

Josef

Mmmh, so I rebooted that server with 3.14.0 (no rc), and it was deadlocked a long time during boot (about 10mn) before it unlocked itself and finished booting.

This is a bit vexing, I don't yet know which of my 3 btrfs filesystems is causing this, and how to fix it.
After boot, it seems ok enough.

You're recommending that I try btrfs-next on a 3.15 pre kernel, correct? If so would it be likely to fix my filesystem and let me go back to a stable 3.14? (I'm a bit warry about running some unstable 3.15 on it :).

Is there a chance balance or some file system cleaning will fix this?

For now, during boot, I get:

INFO: task btrfs-transacti:3633 blocked for more than 120 seconds.
      Not tainted 3.14.0-rc5-amd64-i915-preempt-20140216c #1

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
btrfs-transacti D ffff88020d762680 0 3633 2 0x00000000
ffff88020c6c7dc0 0000000000000046 ffff88020c6c7fd8 ffff88020d762150 00000000000141c0 ffff88020d762150 ffff88020e11be90 ffff8802106271e8 0000000000000000 ffff880210627000 ffff8800c5c82740 ffff88020c6c7dd0

Call Trace:
 [<ffffffff8160c331>] schedule+0x73/0x75
 [<ffffffff8122a5f9>] wait_current_trans.isra.15+0x98/0xf4
 [<ffffffff810850c9>] ? finish_wait+0x65/0x65
 [<ffffffff8122b812>] start_transaction+0x202/0x4f2
 [<ffffffff8122bb9e>] btrfs_attach_transaction+0x17/0x19
 [<ffffffff812277a8>] transaction_kthread+0xd6/0x1ab
 [<ffffffff812276d2>] ? btrfs_cleanup_transaction+0x43f/0x43f
 [<ffffffff8106bc56>] kthread+0xae/0xb6
 [<ffffffff8106bba8>] ? __kthread_parkme+0x61/0x61
 [<ffffffff816153fc>] ret_from_fork+0x7c/0xb0
 [<ffffffff8106bba8>] ? __kthread_parkme+0x61/0x61
INFO: task btrfs-transacti:3633 blocked for more than 120 seconds.
      Not tainted 3.14.0-rc5-amd64-i915-preempt-20140216c #1

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
btrfs-transacti D ffff88020d762680 0 3633 2 0x00000000
ffff88020c6c7dc0 0000000000000046 ffff88020c6c7fd8 ffff88020d762150 00000000000141c0 ffff88020d762150 ffff88020e11be90 ffff8802106271e8 0000000000000000 ffff880210627000 ffff8800c5c82740 ffff88020c6c7dd0

Call Trace:
 [<ffffffff8160c331>] schedule+0x73/0x75
 [<ffffffff8122a5f9>] wait_current_trans.isra.15+0x98/0xf4
 [<ffffffff810850c9>] ? finish_wait+0x65/0x65
 [<ffffffff8122b812>] start_transaction+0x202/0x4f2
 [<ffffffff8122bb9e>] btrfs_attach_transaction+0x17/0x19
 [<ffffffff812277a8>] transaction_kthread+0xd6/0x1ab
 [<ffffffff812276d2>] ? btrfs_cleanup_transaction+0x43f/0x43f
 [<ffffffff8106bc56>] kthread+0xae/0xb6
 [<ffffffff8106bba8>] ? __kthread_parkme+0x61/0x61
 [<ffffffff816153fc>] ret_from_fork+0x7c/0xb0
 [<ffffffff8106bba8>] ? __kthread_parkme+0x61/0x61
INFO: task btrfs-transacti:3633 blocked for more than 120 seconds.
      Not tainted 3.14.0-rc5-amd64-i915-preempt-20140216c #1

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
btrfs-transacti D ffff88020d762680 0 3633 2 0x00000000
ffff88020c6c7dc0 0000000000000046 ffff88020c6c7fd8 ffff88020d762150 00000000000141c0 ffff88020d762150 ffff88020e11be90 ffff8802106271e8 0000000000000000 ffff880210627000 ffff8800c5c82740 ffff88020c6c7dd0

Call Trace:
 [<ffffffff8160c331>] schedule+0x73/0x75
 [<ffffffff8122a5f9>] wait_current_trans.isra.15+0x98/0xf4
 [<ffffffff810850c9>] ? finish_wait+0x65/0x65
 [<ffffffff8122b812>] start_transaction+0x202/0x4f2
 [<ffffffff8122bb9e>] btrfs_attach_transaction+0x17/0x19
 [<ffffffff812277a8>] transaction_kthread+0xd6/0x1ab
 [<ffffffff812276d2>] ? btrfs_cleanup_transaction+0x43f/0x43f
 [<ffffffff8106bc56>] kthread+0xae/0xb6
 [<ffffffff8106bba8>] ? __kthread_parkme+0x61/0x61
 [<ffffffff816153fc>] ret_from_fork+0x7c/0xb0
 [<ffffffff8106bba8>] ? __kthread_parkme+0x61/0x61

Eventually the boot finishes, but it hangs way too long.

Thanks,
Marc

"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/                         | PGP 1024R/763BE901

Right now the fixes for this are in the integration branch on my git tree. I think we've shaken out all the problems, but if you want to wait until tomorrow I'll have it in my next branch (for linux-next).

-chris

I can wait, even a few more days if needed.
But just to be clear: will this new kernel be something that will be required for me to run from there on to avoid all those deadlocks and very poor performance I'm seeing, or the new kernel will fix things up, and then if other stuff isn't quite stable, I can downgrade back to 3.14 stable?

By the way, I think I know which filesystem is causing this, and one unusual thing is that it uses a lot of hardlinks.

In case that helps, there are only 40 snapshots on it, but many inodes, of which many are hardlinked together:

gargamel:/mnt/btrfs_pool2# btrfs filesystem df `pwd`
Data, single: total=3.28TiB, used=2.30TiB
System, DUP: total=8.00MiB, used=384.00KiB
System, single: total=4.00MiB, used=0.00
Metadata, DUP: total=74.50GiB, used=70.11GiB
Metadata, single: total=8.00MiB, used=0.00
gargamel:/mnt/btrfs_pool2# btrfs filesystem show `pwd`
Label: btrfs_pool2  uuid: cb9df6d3-a528-4afc-9a45-4fed5ec358d6
	Total devices 1 FS bytes used 2.37TiB
	devid    1 size 7.28TiB used 3.43TiB path /dev/mapper/dshelf2

Marc

"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/  

Back on that front, while debugging the other problem I sent you, I've been having more issues with this device too.

At boot time, I've been getting multiple of these after boot:
gargamel login: [ 1328.241302] INFO: task btrfs-cleaner:3571 blocked for more than 120 seconds.

[ 1328.264046]       Not tainted 3.14.0-amd64-i915-preempt-20140216 #2
[ 1328.284413] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1328.309394] btrfs-cleaner   D ffff88020d5ea800     0  3571      2 0x00000000
[ 1328.331996]  ffff8800c8985d00 0000000000000046 ffff8800c8985fd8 ffff88020d5ea2d0
[ 1328.355774]  00000000000141c0 ffff88020d5ea2d0 ffff8801d9a7ee50 ffff880213bfc9e8
[ 1328.379408]  0000000000000000 ffff880213bfc800 ffff88020c5b7ce0 ffff8800c8985d10
[ 1328.403654] Call Trace:
[ 1328.412617]  [<ffffffff8160d2a1>] schedule+0x73/0x75
[ 1328.429189]  [<ffffffff8122aa77>] wait_current_trans.isra.15+0x98/0xf4
[ 1328.450402]  [<ffffffff81085116>] ? finish_wait+0x65/0x65
[ 1328.467957]  [<ffffffff8122bf1c>] start_transaction+0x48e/0x4f2
[ 1328.487315]  [<ffffffff8122c2ff>] ? __btrfs_end_transaction+0x2a1/0x2c6
[ 1328.508614]  [<ffffffff8122bf9b>] btrfs_start_transaction+0x1b/0x1d
[ 1328.528842]  [<ffffffff8121cc7d>] btrfs_drop_snapshot+0x443/0x610
[ 1328.548481]  [<ffffffff8122c73d>] btrfs_clean_one_deleted_snapshot+0x103/0x10f
[ 1328.571518]  [<ffffffff81224f09>] cleaner_kthread+0x103/0x136
[ 1328.590436]  [<ffffffff81224e06>] ? btrfs_alloc_root+0x26/0x26
[ 1328.609348]  [<ffffffff8106bc62>] kthread+0xae/0xb6
[ 1328.625275]  [<ffffffff8106bbb4>] ? __kthread_parkme+0x61/0x61
[ 1328.644406]  [<ffffffff8161637c>] ret_from_fork+0x7c/0xb0
[ 1328.662075]  [<ffffffff8106bbb4>] ? __kthread_parkme+0x61/0x61

But more annoyingly, accessing the mountpoint was hanging, so I've now mounted it with recovery,ro, and backing up all the data to another device so that I can destroy/recreate this device that clearly has severe performance issues.

Do you want btrfsck output and an image of that one too? (this one is not raid0, it's on top of an dm encrypted md raid5 array)

Thanks,
Marc

"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/  

I've posted about this before, and I'm about to delete and recreate the filesystem.
I took an image, but the image is 18GB, so not very convenient to give around, although I can if needed.

As a reminder, the problems are that everything is super slow, including btrfs's own background processes that hang and create tracebacks. (initially I complained about rm, but it's just everything that is slow).

If I mount with ro,recovery, then it's actually normal speed to copy data off it, quite weird. It seems like btrfs' background processes are grinding the FS down to a halt, and I didn't turn on autodefrag.

I haven't gotten confirmation that this a known problem that has been root-caused, so I'm a bit hesitant about wiping the filesystem before getting potentially useful debug data off it, but honestly I'm not sure what to take.

(I have a btrfsck running, looks like it may take over an hour, so I'll post that after it's finished)

Other suggestions welcome.

Thanks,
Marc

"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/  

Marc MERLIN posted on Sat, 12 Apr 2014 13:25:42 -0700 as excerpted:

What happens if you simply mount it ro, without the recovery option? Is it still normal-speed or is that slow as a rw mount?

Speed hasn't been an issue here, but FWIW I normally keep my rootfs ro mounted as I decided that's lower risk in the event of a system crash or power outage and I don't actually /need/ it rw most of the time (I have a dedicated /var/log, /home on an entirely separate btrfs, and the bits of /var that need to be writable in normal operation symlinked into /home/var/), only mounting the rootfs rw to update or do other system maintenance.

If a ro filesystem is normal speed but rw slow, the problem must be in the write path, which is what I suspect. If a ro filesystem is slow and only a recover,ro filesystem is fast, then there's something strange going on with btrfs internals that recovery obviously bypasses. Knowing one way or the other should definitely help to pin things down.

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

I just tried in ro without recovery, and I could copy data out at 52MB/s for a big file, so that's quite good.

As soon as I mount it r/w, then everything goes to crap, even before I start using it.
So from what I'm seeing, some structures are messed up, btrfs then goes into some almost infinite loops to fix them if the filesystem is in writeable mode.

I just tried to mount it and umount it, but I couldn't even unmount it.

I'll wait until tomorrow night to see if the devs want anything else out of it, but otherwise I'll wipe it and start over.

I'm all with you here, but that's not very practical on an array that is only there to _receive_ backups from other systems :)

So, I made the FS read-write, I was still able to copy big files at 50MB/s, and then did:

gargamel:/mnt/btrfs_pool2/backup/polgara# time cp -al ../legolas/current/ .
(copying a full system with many small files)

Within, minutes I got:

[114821.950649] INFO: task btrfs-cleaner:14442 blocked for more than 120 seconds.
[114821.984252]       Not tainted 3.14.0-amd64-i915-preempt-20140216 #2
[114822.007214] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[114822.035962] btrfs-cleaner   D ffff88009ea74640     0 14442      2 0x00000080
[114822.061879]  ffff880046bd7d00 0000000000000046 ffff880046bd7fd8 ffff88009ea74110
[114822.088179]  00000000000141c0 ffff88009ea74110 ffff88019f812350 ffff8801dafaa9e8
[114822.114363]  0000000000000000 ffff8801dafaa800 ffff8801bb957460 ffff880046bd7d10
[114822.140443] Call Trace:
[114822.151120]  [<ffffffff8160d2a1>] schedule+0x73/0x75
[114822.169217]  [<ffffffff8122aa77>] wait_current_trans.isra.15+0x98/0xf4
[114822.192089]  [<ffffffff81085116>] ? finish_wait+0x65/0x65
[114822.211381]  [<ffffffff8122bf1c>] start_transaction+0x48e/0x4f2
[114822.232292]  [<ffffffff8122c2ff>] ? __btrfs_end_transaction+0x2a1/0x2c6
[114822.255258]  [<ffffffff8122bf9b>] btrfs_start_transaction+0x1b/0x1d
[114822.277115]  [<ffffffff8121cc7d>] btrfs_drop_snapshot+0x443/0x610
[114822.298422]  [<ffffffff8122c73d>] btrfs_clean_one_deleted_snapshot+0x103/0x10f
[114822.323108]  [<ffffffff81224f09>] cleaner_kthread+0x103/0x136
[114822.343280]  [<ffffffff81224e06>] ? btrfs_alloc_root+0x26/0x26
[114822.363587]  [<ffffffff8106bc62>] kthread+0xae/0xb6
[114822.381042]  [<ffffffff8106bbb4>] ? __kthread_parkme+0x61/0x61
[114822.401319]  [<ffffffff8161637c>] ret_from_fork+0x7c/0xb0
[114822.420054]  [<ffffffff8106bbb4>] ? __kthread_parkme+0x61/0x61
[114822.440419] INFO: task cp:23902 blocked for more than 120 seconds.
[114822.461583]       Not tainted 3.14.0-amd64-i915-preempt-20140216 #2
[114822.482967] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[114822.509029] cp              D ffff88009e782800     0 23902  19922 0x20020080
[114822.532913]  ffff8802081f7d98 0000000000000082 ffff8802081f7fd8 ffff88009e7822d0
[114822.558306]  00000000000141c0 ffff88009e7822d0 ffff88019f812350 ffff8801d08f81e8
[114822.583381]  0000000000000000 ffff8801d08f8000 ffff880160b29640 ffff8802081f7da8
[114822.608434] Call Trace:
[114822.618046]  [<ffffffff8160d2a1>] schedule+0x73/0x75
[114822.635275]  [<ffffffff8122aa77>] wait_current_trans.isra.15+0x98/0xf4
[114822.657098]  [<ffffffff81085116>] ? finish_wait+0x65/0x65
[114822.675586]  [<ffffffff8122bf1c>] start_transaction+0x48e/0x4f2
[114822.695525]  [<ffffffff8122bf9b>] btrfs_start_transaction+0x1b/0x1d
[114822.716469]  [<ffffffff812364cc>] btrfs_link+0x74/0x18e
[114822.734272]  [<ffffffff811607db>] vfs_link+0x101/0x1a5
[114822.751830]  [<ffffffff811627a7>] SYSC_linkat+0x171/0x213
[114822.770100]  [<ffffffff81162ad4>] SyS_linkat+0xe/0x10
[114822.787314]  [<ffffffff8161812c>] sysenter_dispatch+0x7/0x21

After that, it took a long time for the ^C of my cp to work. Actually, ^C just didn't work at all, and kill -9 didn't work either.

cp is stuck in kernel state:
23902 01:05:47 wait_current_trans.isra.15 cp -i -al ../legolas/current/ .

I was forced to reboot.
And then as soon as I reboot and mount that partition read/write, I get:

[  485.375223] INFO: task btrfs-cleaner:3552 blocked for more than 120 seconds.
[  485.396430]       Not tainted 3.14.0-amd64-i915-preempt-20140216 #2
[  485.415282] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  485.438832] btrfs-cleaner   D ffff880211d2eb80     0  3552      2 0x00000000
[  485.460134]  ffff8800c7f0fd00 0000000000000046 ffff8800c7f0ffd8 ffff880211d2e650
[  485.482503]  00000000000141c0 ffff880211d2e650 ffff88020cea6130 ffff880213fda1e8
[  485.504934]  0000000000000000 ffff880213fda000 ffff88020cfb2a60 ffff8800c7f0fd10
[  485.527342] Call Trace:
[  485.534706]  [<ffffffff8160d2a1>] schedule+0x73/0x75
[  485.549628]  [<ffffffff8122aa77>] wait_current_trans.isra.15+0x98/0xf4
[  485.569235]  [<ffffffff81085116>] ? finish_wait+0x65/0x65
[  485.585458]  [<ffffffff8122bf1c>] start_transaction+0x48e/0x4f2
[  485.603237]  [<ffffffff8122c2ff>] ? __btrfs_end_transaction+0x2a1/0x2c6
[  485.623096]  [<ffffffff8122bf9b>] btrfs_start_transaction+0x1b/0x1d
[  485.641932]  [<ffffffff8121cc7d>] btrfs_drop_snapshot+0x443/0x610
[  485.660256]  [<ffffffff8122c73d>] btrfs_clean_one_deleted_snapshot+0x103/0x10f
[  485.681961]  [<ffffffff81224f09>] cleaner_kthread+0x103/0x136
[  485.699226]  [<ffffffff81224e06>] ? btrfs_alloc_root+0x26/0x26
[  485.716746]  [<ffffffff8106bc62>] kthread+0xae/0xb6
[  485.731410]  [<ffffffff8106bbb4>] ? __kthread_parkme+0x61/0x61
[  485.748927]  [<ffffffff8161637c>] ret_from_fork+0x7c/0xb0
[  485.765147]  [<ffffffff8106bbb4>] ? __kthread_parkme+0x61/0x61

This is with 0 file IO to it.
Turns out even umount of that filesystem hangs.

Marc

"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/  

Marc MERLIN posted on Sun, 13 Apr 2014 18:43:37 -0700 as excerpted:

Pretty much what I expected in terms of ro vs. rw, but I had forgotten the details on the why, and your explanation both prompted my memory and agrees with what I had seen before.

IIRC, Hugo mentioned others seeing something similar at times, where read- only forced btrfs to leave alone what it was going into loops over, so you're not the only one to have seen this.

But you might well be the first report where the devs have good access to enough detail to actually trace down the problem.

Given that our exchange happened over the weekend and "tomorrow" is Monday, I'd consider waiting until Tuesday nite if possible, just to be sure. Because Monday is of course back to work day, and it's possible if there's something urgent (or if they're taking a long weekend for some reason), they won't get fully caught up from the weekend until Tuesday. So if you can wait until Tuesday and you don't get a request for anything else by then, it's probably safe to wipe and redo, but I'd try to wait until then, just in case you have something useful, and they simply don't get to it the first day back after the weekend. Because once it's gone it's gone, and now that I'm remembering what Hugo mentioned, it does seem you're not the only one to have come across this, but you might indeed have the missing key the others couldn't provide, so...

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

So it seems that no one is interested in that filesystem.

I probably won't have time to wipe and rebuild it until this weekend, so I'll see how it works after a rebuild.
Hopefully I won't hit the same problems again.

Marc

"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/  

I ran out of patience after 18 hours of waiting since it seemed to have not progressed after 12 hours (it was still doing stuff, but no more output on the screen).

Let's look at the output:
1794407 lines of lines similar to:
Extent back ref already exists for 2148837945344 parent 0 root 257

61 lines of
leaf parent key incorrect 504993210368

67 lines of
bad block 504993210368
=> just curious, what is this one supposed to mean? Is the data checksum bad, or something else?

Marc

"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/  

We had a chat about btrfsck running clean in some cases. Sure enough, it did for me on a filesystem I had just created.

But on existing filesystems I've been using for a while, it never has for me has per the example above.

I've added some info to:
https://btrfs.wiki.kernel.org/index.php/Btrfsck

Two questions:
1) are others seeing errors like these:
Extent back ref already exists for 2148837945344 parent 0 root 257 leaf parent key incorrect 504993210368
bad block 504993210368

2) do you know how bad each one is, and should they all be picked up by a scrub? (I'm under the impression that they were not for me)

I'm happy to further update the wiki on btrfsck with info you can contribute.

Thanks,
Marc

"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/