Filesystem hang on kernel 4.2.0 with copy reflink

Hi there, I've run into a very strange hang with btrfs. I was trying to restore a directory (postgres database) from a readonly snapshot. To do this i used the command cp -ar --reflink=always. This worked fine for 100s of files, however when it got to a particular file 16 kworker threads (I have 8 processors in this system) got marked as being in D state (with 0 cpu usage or disk usage) and I could not access the btrfs file system any more. I can't see any kernel message or OOPS. Can you please let me know what additional debug information I can provide to help track this issue down in the kernel?

System is latest ubuntu 14.04 LTS with a backported wily kernel (package linux-image-4.2.0-22-generic):

4.2.0-22-generic #27~14.04.1-Ubuntu SMP Fri Dec 18 10:57:53 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux

Thanks

Mark

Hi Mark,

Could you do below when the hang happens, and post the dmesg.

echo w > /proc/sysrq-trigger

2016-01-04 9:35 GMT+01:00 Mark Zealey <[email protected]>:

It overflowed the dmesg buffer but hopefully contains enough cores - https://mark.zealey.org/download/btrfs_crash.txt

Some other output:

# mount
/dev/sdb1 on / type btrfs (rw,noatime,skip_balance,subvol=@)
proc on /proc type proc (rw,noexec,nosuid,nodev)
sysfs on /sys type sysfs (rw,noexec,nosuid,nodev)
none on /sys/fs/cgroup type tmpfs (rw)
none on /sys/fs/fuse/connections type fusectl (rw)
none on /sys/kernel/debug type debugfs (rw)
none on /sys/kernel/security type securityfs (rw)
none on /sys/firmware/efi/efivars type efivarfs (rw)
udev on /dev type devtmpfs (rw,mode=0755)
devpts on /dev/pts type devpts (rw,noexec,nosuid,gid=5,mode=0620)
tmpfs on /run type tmpfs (rw,noexec,nosuid,size=10%,mode=0755)
none on /run/lock type tmpfs (rw,noexec,nosuid,nodev,size=5242880)
none on /run/shm type tmpfs (rw,nosuid,nodev)
none on /run/user type tmpfs (rw,noexec,nosuid,nodev,size=104857600,mode=0755)
none on /sys/fs/pstore type pstore (rw)
cgroup on /sys/fs/cgroup/cpuset type cgroup (rw,relatime,cpuset)
cgroup on /sys/fs/cgroup/cpu type cgroup (rw,relatime,cpu)
cgroup on /sys/fs/cgroup/cpuacct type cgroup (rw,relatime,cpuacct)
cgroup on /sys/fs/cgroup/blkio type cgroup (rw,relatime,blkio)
cgroup on /sys/fs/cgroup/memory type cgroup (rw,relatime,memory)
cgroup on /sys/fs/cgroup/devices type cgroup (rw,relatime,devices)
cgroup on /sys/fs/cgroup/freezer type cgroup (rw,relatime,freezer,release_agent=/run/cgmanager/agents/cgm-release-agent.freezer)
cgroup on /sys/fs/cgroup/net_cls type cgroup (rw,relatime,net_cls,release_agent=/run/cgmanager/agents/cgm-release-agent.net_cls)
/dev/sdb1 on /home type btrfs (rw,noatime,skip_balance,subvol=@home)
/dev/sdb3 on /boot/efi type vfat (rw)
binfmt_misc on /proc/sys/fs/binfmt_misc type binfmt_misc (rw,noexec,nosuid,nodev)
rpc_pipefs on /run/rpc_pipefs type rpc_pipefs (rw)
systemd on /sys/fs/cgroup/systemd type cgroup (rw,noexec,nosuid,nodev,none,name=systemd)

ps auwx|grep ' D'

root       275  0.0  0.0      0     0 ?        D    Jan02   2:29 [btrfs-transacti]
root       361  0.0  0.0      0     0 ?        D    13:30   0:00 [kworker/u16:5]
root       404  0.0  0.0      0     0 ?        D    13:31   0:00 [kworker/u16:7]
root      1127  0.0  0.0      0     0 ?        D    13:54   0:00 [kworker/u16:0]
root      1137  0.0  0.0      0     0 ?        D    13:54   0:00 [kworker/u16:2]
root      1189  2.3  0.0  25932  2216 pts/7    D+   13:55   0:02 cp -vax --reflink=always /.snapshots/psql/var/lib/postgresql/ .
root      1191  0.0  0.0      0     0 ?        D    13:55   0:00 [kworker/u16:3]
root      1197  0.0  0.0      0     0 ?        D    13:55   0:00 [kworker/u16:4]
root      1200  0.0  0.0      0     0 ?        D    13:55   0:00 [kworker/u16:8]
root      1201  0.0  0.0      0     0 ?        D    13:55   0:00 [kworker/u16:10]
root      1230  0.0  0.0      0     0 ?        D    13:55   0:00 [kworker/u16:15]
root      1231  0.0  0.0      0     0 ?        D    13:55   0:00 [kworker/u16:16]
root     14569  0.0  0.0      0     0 ?        D    12:18   0:00 [kworker/u16:9]
root     14572  0.0  0.0      0     0 ?        D    12:19   0:00 [kworker/u16:11]
root     14573  0.0  0.0      0     0 ?        D    12:19   0:00 [kworker/u16:12]
root     14582  0.0  0.0      0     0 ?        D    12:19   0:00 [kworker/u16:13]
root     32228  0.0  0.0      0     0 ?        D    13:17   0:00 [kworker/u16:1]

The last output of the cp:

‘/.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25009’ -> ‘./postgresql/9.5/main/base/16385/25009’ ‘/.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25011’ -> ‘./postgresql/9.5/main/base/16385/25011’ ‘/.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25012’ -> ‘./postgresql/9.5/main/base/16385/25012’ ‘/.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25243’ -> ‘./postgresql/9.5/main/base/16385/25243’ ‘/.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25246’ -> ‘./postgresql/9.5/main/base/16385/25246’ ‘/.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25248’ -> ‘./postgresql/9.5/main/base/16385/25248’ ‘/.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25249’ -> ‘./postgresql/9.5/main/base/16385/25249’ ‘/.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25251’ -> ‘./postgresql/9.5/main/base/16385/25251’ ‘/.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25254’ -> ‘./postgresql/9.5/main/base/16385/25254’ ‘/.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25256’ -> ‘./postgresql/9.5/main/base/16385/25256’ ‘/.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25257’ -> ‘./postgresql/9.5/main/base/16385/25257’ ‘/.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25283’ -> ‘./postgresql/9.5/main/base/16385/25283’

And those (and other files) that it would have copied:

-rw------- 1 postgres postgres 0 Dec 30 18:11 /.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25243
-rw------- 1 postgres postgres 0 Dec 30 18:11 /.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25246
-rw------- 1 postgres postgres 8192 Dec 30 18:11 /.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25248
-rw------- 1 postgres postgres 8192 Dec 30 18:11 /.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25249
-rw------- 1 postgres postgres 0 Dec 30 18:11 /.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25251
-rw------- 1 postgres postgres 0 Dec 30 18:11 /.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25254
-rw------- 1 postgres postgres 8192 Dec 30 18:11 /.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25256
-rw------- 1 postgres postgres 8192 Dec 30 18:11 /.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25257
-rw------- 1 postgres postgres 409624576 Dec 30 19:10 /.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25283
-rw------- 1 postgres postgres 122880 Dec 30 18:29 /.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25283_fsm
-rw------- 1 postgres postgres 0 Dec 30 18:22 /.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25284
-rw------- 1 postgres postgres 8192 Dec 30 18:22 /.snapshots/psql/var/lib/postgresql/9.5/main/base/16385/25285

Also I have quota tracking enabled on the btrfs volume if that makes any difference.

Mark

Mark Zealey posted on Mon, 04 Jan 2016 14:11:00 +0200 as excerpted:

I'm not sure whether it makes a difference for this particular hang, but I do know that btrfs quotas are simply not stable thru at least 4.3. I'm not sure what 4.4 status is, but my general recommendation regarding btrfs quotas is...

If you need quotas, use a more mature filesystem where they work reliably, if you don't, then turn them off for now, and don't turn them on again until at least two complete kernel cycles have passed without a known quota bug or instability, which, if 4.4 is indeed known-bug-free and it and 4.5 remain so thru 4.6, means that would be the earliest I could recommend turning it on, and that's only if there's no known quota bugs in 4.4 or 4.5 or 4.6 by the time of 4.6 release.

Unless of course you're deliberately and specifically testing btrfs quotas and working with the devs on fixing quota specific issues, in which case, thank you. =:^)

Meanwhile, the rather long history of problems with quotas on btrfs is both the reason I'm suggesting two complete cycles without quota issues before enabling them, and a good reason to be skeptical as to current releases' quota code or the likelihood of that two-releases-quota-bug- free happening any time soon. There's definitely a lot of work going into the feature and there's gotta be a point where it actually works, but they've rewritten the code three times and are still dealing with bugs, and it has been in a "try back in a couple kernel cycles" state for years, now, so... who knows? Kinda reminds me of how long the raid56 code took, only quota was being worked on before that, and is still being worked on, 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