* btrfs send hung in pipe_wait
@ 2018-09-06 9:22 Stefan Löwen
2018-09-06 15:04 ` Stefan Loewen
0 siblings, 1 reply; 17+ messages in thread
From: Stefan Löwen @ 2018-09-06 9:22 UTC (permalink / raw)
To: linux-btrfs
[-- Attachment #1: Type: text/plain, Size: 2149 bytes --]
Hello linux-btrfs,
I'm trying to clone a subvolume with 'btrfs send' but it always hangs
for hours.
I tested this on multiple systems. All showed the same result:
- Manjaro (btrfs-progs v4.17.1; linux v4.18.5-1-MANJARO)
- Ubuntu 18.04 in VirtualBox (btrfs-progs v4.15.1; linux v4.15.0-33-generic)
- ArchLinux in VirtualBox (btrfs-progs v4.17.1; linux v4.18.5-arch1-1-ARCH)
All following logs are from the ArchLinux VM.
To make sure it's not the 'btrfs receive' at fault I tried sending into
a file using the following command:
'strace -o btrfs-send.strace btrfs send -vvv -f intenso_white.snapshot
/mnt/intenso_white/@data/.snapshots/test-snapshot'
The 'btrfs send' process always copies around 1.2-1.4G of data, then
stops all disk IO and fully loads one cpu core. btrfs scrub found 0
errors. Neither did btrfsck. 'btrfs device stats' is all 0.
I would be thankful for all ideas and tips.
Regards
Stefan
---------------------------------------------
The btrfs-send.strace is attached. So is the dmesg.log during the hang.
Stack traces of the hung process:
--- /proc/3022/task/3022/stack ---
[<0>] 0xffffffffffffffff
--- /proc/3022/task/3023/stack ---
[<0>] pipe_wait+0x6c/0xb0
[<0>] splice_from_pipe_next.part.3+0x24/0xa0
[<0>] __splice_from_pipe+0x43/0x180
[<0>] splice_from_pipe+0x5d/0x90
[<0>] default_file_splice_write+0x15/0x20
[<0>] __se_sys_splice+0x31b/0x770
[<0>] do_syscall_64+0x5b/0x170
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[<0>] 0xffffffffffffffff
[vagrant@archlinux mnt]$ uname -a
Linux archlinux 4.18.5-arch1-1-ARCH #1 SMP PREEMPT Fri Aug 24 12:48:58
UTC 2018 x86_64 GNU/Linux
[vagrant@archlinux mnt]$ btrfs --version
btrfs-progs v4.17.1
[vagrant@archlinux mnt]$ sudo btrfs fi show /dev/sdb1
Label: 'intenso_white' uuid: 07bf61ed-7728-4151-a784-c4b840e343ed
Total devices 1 FS bytes used 655.82GiB
devid 1 size 911.51GiB used 703.09GiB path /dev/sdb1
[vagrant@archlinux mnt]$ sudo btrfs fi df /mnt/intenso_white/
Data, single: total=695.01GiB, used=653.69GiB
System, DUP: total=40.00MiB, used=96.00KiB
Metadata, DUP: total=4.00GiB, used=2.13GiB
GlobalReserve, single: total=512.00MiB, used=0.00B
[-- Attachment #2: btrfs-send.strace --]
[-- Type: text/plain, Size: 11194 bytes --]
execve("/usr/bin/btrfs", ["btrfs", "send", "-vvv", "-f", "intenso_white.snapshot", "/mnt/intenso_white/@data/.snapsh"...], 0x7ffcb8f52718 /* 16 vars */) = 0
brk(NULL) = 0x555c9eddb000
arch_prctl(0x3001 /* ARCH_??? */, 0x7ffe8c9971e0) = -1 EINVAL (Invalid argument)
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=28542, ...}) = 0
mmap(NULL, 28542, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7ffa9a016000
close(3) = 0
openat(AT_FDCWD, "/usr/lib/libuuid.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0`\24\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=26552, ...}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ffa9a014000
mmap(NULL, 2121752, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7ffa99e0d000
mprotect(0x7ffa99e13000, 2093056, PROT_NONE) = 0
mmap(0x7ffa9a012000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x5000) = 0x7ffa9a012000
close(3) = 0
openat(AT_FDCWD, "/usr/lib/libblkid.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\240\231\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=326480, ...}) = 0
mmap(NULL, 2426656, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7ffa99bbc000
mprotect(0x7ffa99c06000, 2097152, PROT_NONE) = 0
mmap(0x7ffa99e06000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x4a000) = 0x7ffa99e06000
mmap(0x7ffa99e0c000, 1824, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7ffa99e0c000
close(3) = 0
openat(AT_FDCWD, "/usr/lib/libz.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\320!\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=91912, ...}) = 0
mmap(NULL, 2187280, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7ffa999a5000
mprotect(0x7ffa999bb000, 2093056, PROT_NONE) = 0
mmap(0x7ffa99bba000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x15000) = 0x7ffa99bba000
close(3) = 0
openat(AT_FDCWD, "/usr/lib/liblzo2.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\20'\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=137432, ...}) = 0
mmap(NULL, 2232528, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7ffa99783000
mprotect(0x7ffa997a4000, 2093056, PROT_NONE) = 0
mmap(0x7ffa999a3000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x20000) = 0x7ffa999a3000
close(3) = 0
openat(AT_FDCWD, "/usr/lib/libzstd.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260E\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=620224, ...}) = 0
mmap(NULL, 2715704, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7ffa994eb000
mprotect(0x7ffa99582000, 2093056, PROT_NONE) = 0
mmap(0x7ffa99781000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x96000) = 0x7ffa99781000
close(3) = 0
openat(AT_FDCWD, "/usr/lib/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\340f\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=155408, ...}) = 0
lseek(3, 808, SEEK_SET) = 808
read(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32) = 32
mmap(NULL, 131528, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7ffa994ca000
mmap(0x7ffa994d0000, 61440, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6000) = 0x7ffa994d0000
mmap(0x7ffa994df000, 24576, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x15000) = 0x7ffa994df000
mmap(0x7ffa994e5000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1a000) = 0x7ffa994e5000
mmap(0x7ffa994e7000, 12744, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7ffa994e7000
close(3) = 0
openat(AT_FDCWD, "/usr/lib/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0000C\2\0\0\0\0\0"..., 832) = 832
lseek(3, 792, SEEK_SET) = 792
read(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\210o7\21\1\307=\311\366\263\256\202p\3777\335"..., 68) = 68
fstat(3, {st_mode=S_IFREG|0755, st_size=2136840, ...}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ffa994c8000
lseek(3, 792, SEEK_SET) = 792
read(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\210o7\21\1\307=\311\366\263\256\202p\3777\335"..., 68) = 68
lseek(3, 864, SEEK_SET) = 864
read(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32) = 32
mmap(NULL, 1848896, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7ffa99304000
mprotect(0x7ffa99326000, 1671168, PROT_NONE) = 0
mmap(0x7ffa99326000, 1355776, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x22000) = 0x7ffa99326000
mmap(0x7ffa99471000, 311296, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x16d000) = 0x7ffa99471000
mmap(0x7ffa994be000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b9000) = 0x7ffa994be000
mmap(0x7ffa994c4000, 13888, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7ffa994c4000
close(3) = 0
mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ffa99301000
arch_prctl(ARCH_SET_FS, 0x7ffa993018c0) = 0
mprotect(0x7ffa994be000, 16384, PROT_READ) = 0
mprotect(0x7ffa994e5000, 4096, PROT_READ) = 0
mprotect(0x7ffa99781000, 4096, PROT_READ) = 0
mprotect(0x7ffa999a3000, 4096, PROT_READ) = 0
mprotect(0x7ffa99bba000, 4096, PROT_READ) = 0
mprotect(0x7ffa9a012000, 4096, PROT_READ) = 0
mprotect(0x7ffa99e06000, 20480, PROT_READ) = 0
mprotect(0x555c9e101000, 20480, PROT_READ) = 0
mprotect(0x7ffa9a046000, 4096, PROT_READ) = 0
munmap(0x7ffa9a016000, 28542) = 0
set_tid_address(0x7ffa99301b90) = 3022
set_robust_list(0x7ffa99301ba0, 24) = 0
rt_sigaction(SIGRTMIN, {sa_handler=0x7ffa994d0130, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7ffa994dc3c0}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {sa_handler=0x7ffa994d01d0, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0x7ffa994dc3c0}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
openat(AT_FDCWD, "intenso_white.snapshot", O_WRONLY|O_TRUNC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "intenso_white.snapshot", O_WRONLY|O_CREAT|O_TRUNC, 0600) = 3
ioctl(3, TCGETS, 0x7ffe8c995f90) = -1 ENOTTY (Inappropriate ioctl for device)
brk(NULL) = 0x555c9eddb000
brk(0x555c9edfc000) = 0x555c9edfc000
lstat("/mnt", {st_mode=S_IFDIR|0755, st_size=60, ...}) = 0
lstat("/mnt/intenso_white", {st_mode=S_IFDIR|0777, st_size=24, ...}) = 0
lstat("/mnt/intenso_white/@data", {st_mode=S_IFDIR|0755, st_size=28, ...}) = 0
lstat("/mnt/intenso_white/@data/.snapshots", {st_mode=S_IFDIR|0755, st_size=76, ...}) = 0
lstat("/mnt/intenso_white/@data/.snapshots/test-snapshot", {st_mode=S_IFDIR|0755, st_size=28, ...}) = 0
openat(AT_FDCWD, "/mnt/intenso_white/@data/.snapshots/test-snapshot", O_RDONLY|O_NOATIME) = 4
close(4) = 0
openat(AT_FDCWD, "/proc/self/mounts", O_RDONLY|O_CLOEXEC) = 4
futex(0x7ffa994c4fc8, FUTEX_WAKE_PRIVATE, 2147483647) = 0
fstat(4, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
read(4, "proc /proc proc rw,nosuid,nodev,"..., 1024) = 1024
read(4, "ime,perf_event 0 0\ncgroup /sys/f"..., 1024) = 1024
read(4, "size=2M 0 0\ndebugfs /sys/kernel/"..., 1024) = 318
read(4, "", 1024) = 0
close(4) = 0
lstat("/mnt", {st_mode=S_IFDIR|0755, st_size=60, ...}) = 0
lstat("/mnt/intenso_white", {st_mode=S_IFDIR|0777, st_size=24, ...}) = 0
openat(AT_FDCWD, "/mnt/intenso_white", O_RDONLY|O_NOATIME) = 4
ioctl(4, BTRFS_IOC_TREE_SEARCH, {key={tree_id=BTRFS_ROOT_TREE_OBJECTID, min_objectid=BTRFS_UUID_TREE_OBJECTID, max_objectid=BTRFS_UUID_TREE_OBJECTID, min_offset=0, max_offset=UINT64_MAX, min_transid=0, max_transid=UINT64_MAX, min_type=BTRFS_ROOT_ITEM_KEY, max_type=BTRFS_ROOT_ITEM_KEY, nr_items=1}} => {key={nr_items=1}, ...}) = 0
lstat("/mnt", {st_mode=S_IFDIR|0755, st_size=60, ...}) = 0
lstat("/mnt/intenso_white", {st_mode=S_IFDIR|0777, st_size=24, ...}) = 0
lstat("/mnt/intenso_white/@data", {st_mode=S_IFDIR|0755, st_size=28, ...}) = 0
lstat("/mnt/intenso_white/@data/.snapshots", {st_mode=S_IFDIR|0755, st_size=76, ...}) = 0
lstat("/mnt/intenso_white/@data/.snapshots/test-snapshot", {st_mode=S_IFDIR|0755, st_size=28, ...}) = 0
openat(AT_FDCWD, "/mnt/intenso_white/@data/.snapshots/test-snapshot", O_RDONLY|O_NOATIME) = 5
close(5) = 0
openat(AT_FDCWD, "/proc/self/mounts", O_RDONLY|O_CLOEXEC) = 5
fstat(5, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
read(5, "proc /proc proc rw,nosuid,nodev,"..., 1024) = 1024
read(5, "ime,perf_event 0 0\ncgroup /sys/f"..., 1024) = 1024
read(5, "size=2M 0 0\ndebugfs /sys/kernel/"..., 1024) = 318
read(5, "", 1024) = 0
close(5) = 0
lstat("/mnt", {st_mode=S_IFDIR|0755, st_size=60, ...}) = 0
lstat("/mnt/intenso_white", {st_mode=S_IFDIR|0777, st_size=24, ...}) = 0
openat(4, "/mnt/intenso_white/@data/.snapshots/test-snapshot", O_RDONLY|O_NOATIME) = 5
ioctl(5, BTRFS_IOC_SUBVOL_GETFLAGS, BTRFS_SUBVOL_RDONLY) = 0
close(5) = 0
write(2, "At subvol /mnt/intenso_white/@da"..., 60) = 60
lstat("/mnt", {st_mode=S_IFDIR|0755, st_size=60, ...}) = 0
lstat("/mnt/intenso_white", {st_mode=S_IFDIR|0777, st_size=24, ...}) = 0
lstat("/mnt/intenso_white/@data", {st_mode=S_IFDIR|0755, st_size=28, ...}) = 0
lstat("/mnt/intenso_white/@data/.snapshots", {st_mode=S_IFDIR|0755, st_size=76, ...}) = 0
lstat("/mnt/intenso_white/@data/.snapshots/test-snapshot", {st_mode=S_IFDIR|0755, st_size=28, ...}) = 0
openat(4, "/mnt/intenso_white/@data/.snapshots/test-snapshot", O_RDONLY|O_NOATIME) = 5
pipe([6, 7]) = 0
mmap(NULL, 8392704, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7ffa98b00000
mprotect(0x7ffa98b01000, 8388608, PROT_READ|PROT_WRITE) = 0
clone(child_stack=0x7ffa992ffe30, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7ffa993009d0, tls=0x7ffa99300700, child_tidptr=0x7ffa993009d0) = 3023
ioctl(5, BTRFS_IOC_SEND, {send_fd=7, clone_sources_count=0, clone_sources=NULL, parent_root=0, flags=0}) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
--- SIGWINCH {si_signo=SIGWINCH, si_code=SI_KERNEL} ---
ioctl(5, BTRFS_IOC_SEND, {send_fd=7, clone_sources_count=0, clone_sources=NULL, parent_root=0, flags=0}
[-- Attachment #3: dmesg.log --]
[-- Type: text/x-log, Size: 34765 bytes --]
[ 0.000000] Linux version 4.18.5-arch1-1-ARCH (builduser@heftig-12250) (gcc version 8.2.0 (GCC)) #1 SMP PREEMPT Fri Aug 24 12:48:58 UTC 2018
[ 0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-linux root=UUID=a83c9650-c8f8-4afe-90a6-4e80156d523d rw quiet
[ 0.000000] KERNEL supported cpus:
[ 0.000000] Intel GenuineIntel
[ 0.000000] AMD AuthenticAMD
[ 0.000000] Centaur CentaurHauls
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
[ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256
[ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format.
[ 0.000000] BIOS-provided physical RAM map:
[ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
[ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
[ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000dffeffff] usable
[ 0.000000] BIOS-e820: [mem 0x00000000dfff0000-0x00000000dfffffff] ACPI data
[ 0.000000] BIOS-e820: [mem 0x00000000fec00000-0x00000000fec00fff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000fee00000-0x00000000fee00fff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
[ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x000000011fffffff] usable
[ 0.000000] NX (Execute Disable) protection: active
[ 0.000000] SMBIOS 2.5 present.
[ 0.000000] DMI: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
[ 0.000000] Hypervisor detected: KVM
[ 0.000000] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
[ 0.000000] e820: remove [mem 0x000a0000-0x000fffff] usable
[ 0.000000] last_pfn = 0x120000 max_arch_pfn = 0x400000000
[ 0.000000] MTRR default type: uncachable
[ 0.000000] MTRR variable ranges disabled:
[ 0.000000] Disabled
[ 0.000000] x86/PAT: MTRRs disabled, skipping PAT initialization too.
[ 0.000000] CPU MTRRs all blank - virtualized system.
[ 0.000000] x86/PAT: Configuration [0-7]: WB WT UC- UC WB WT UC- UC
[ 0.000000] last_pfn = 0xdfff0 max_arch_pfn = 0x400000000
[ 0.000000] found SMP MP-table at [mem 0x0009fff0-0x0009ffff] mapped at [(____ptrval____)]
[ 0.000000] Scanning 1 areas for low memory corruption
[ 0.000000] Base memory trampoline at [(____ptrval____)] 99000 size 24576
[ 0.000000] BRK [0x111677000, 0x111677fff] PGTABLE
[ 0.000000] BRK [0x111678000, 0x111678fff] PGTABLE
[ 0.000000] BRK [0x111679000, 0x111679fff] PGTABLE
[ 0.000000] BRK [0x11167a000, 0x11167afff] PGTABLE
[ 0.000000] BRK [0x11167b000, 0x11167bfff] PGTABLE
[ 0.000000] BRK [0x11167c000, 0x11167cfff] PGTABLE
[ 0.000000] BRK [0x11167d000, 0x11167dfff] PGTABLE
[ 0.000000] BRK [0x11167e000, 0x11167efff] PGTABLE
[ 0.000000] BRK [0x11167f000, 0x11167ffff] PGTABLE
[ 0.000000] RAMDISK: [mem 0x37131000-0x3788ffff]
[ 0.000000] ACPI: Early table checksum verification disabled
[ 0.000000] ACPI: RSDP 0x00000000000E0000 000024 (v02 VBOX )
[ 0.000000] ACPI: XSDT 0x00000000DFFF0030 00003C (v01 VBOX VBOXXSDT 00000001 ASL 00000061)
[ 0.000000] ACPI: FACP 0x00000000DFFF00F0 0000F4 (v04 VBOX VBOXFACP 00000001 ASL 00000061)
[ 0.000000] ACPI: DSDT 0x00000000DFFF0470 0021FF (v02 VBOX VBOXBIOS 00000002 INTL 20180629)
[ 0.000000] ACPI: FACS 0x00000000DFFF0200 000040
[ 0.000000] ACPI: FACS 0x00000000DFFF0200 000040
[ 0.000000] ACPI: APIC 0x00000000DFFF0240 00005C (v02 VBOX VBOXAPIC 00000001 ASL 00000061)
[ 0.000000] ACPI: SSDT 0x00000000DFFF02A0 0001CC (v01 VBOX VBOXCPUT 00000002 INTL 20180629)
[ 0.000000] ACPI: Local APIC address 0xfee00000
[ 0.000000] No NUMA configuration found
[ 0.000000] Faking a node at [mem 0x0000000000000000-0x000000011fffffff]
[ 0.000000] NODE_DATA(0) allocated [mem 0x11fffc000-0x11fffffff]
[ 0.000000] kvm-clock: cpu 0, msr 1:1fff6001, primary cpu clock
[ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00
[ 0.000000] kvm-clock: using sched offset of 5269732913 cycles
[ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
[ 0.000000] Zone ranges:
[ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff]
[ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff]
[ 0.000000] Normal [mem 0x0000000100000000-0x000000011fffffff]
[ 0.000000] Device empty
[ 0.000000] Movable zone start for each node
[ 0.000000] Early memory node ranges
[ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff]
[ 0.000000] node 0: [mem 0x0000000000100000-0x00000000dffeffff]
[ 0.000000] node 0: [mem 0x0000000100000000-0x000000011fffffff]
[ 0.000000] Reserved but unavailable: 114 pages
[ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x000000011fffffff]
[ 0.000000] On node 0 totalpages: 1048462
[ 0.000000] DMA zone: 64 pages used for memmap
[ 0.000000] DMA zone: 21 pages reserved
[ 0.000000] DMA zone: 3998 pages, LIFO batch:0
[ 0.000000] DMA32 zone: 14272 pages used for memmap
[ 0.000000] DMA32 zone: 913392 pages, LIFO batch:31
[ 0.000000] Normal zone: 2048 pages used for memmap
[ 0.000000] Normal zone: 131072 pages, LIFO batch:31
[ 0.000000] ACPI: PM-Timer IO Port: 0x4008
[ 0.000000] ACPI: Local APIC address 0xfee00000
[ 0.000000] IOAPIC[0]: apic_id 2, version 32, address 0xfec00000, GSI 0-23
[ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 low level)
[ 0.000000] ACPI: IRQ0 used by override.
[ 0.000000] ACPI: IRQ9 used by override.
[ 0.000000] Using ACPI (MADT) for SMP configuration information
[ 0.000000] smpboot: Allowing 2 CPUs, 0 hotplug CPUs
[ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff]
[ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff]
[ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff]
[ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff]
[ 0.000000] PM: Registered nosave memory: [mem 0xdfff0000-0xdfffffff]
[ 0.000000] PM: Registered nosave memory: [mem 0xe0000000-0xfebfffff]
[ 0.000000] PM: Registered nosave memory: [mem 0xfec00000-0xfec00fff]
[ 0.000000] PM: Registered nosave memory: [mem 0xfec01000-0xfedfffff]
[ 0.000000] PM: Registered nosave memory: [mem 0xfee00000-0xfee00fff]
[ 0.000000] PM: Registered nosave memory: [mem 0xfee01000-0xfffbffff]
[ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff]
[ 0.000000] [mem 0xe0000000-0xfebfffff] available for PCI devices
[ 0.000000] Booting paravirtualized kernel on KVM
[ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 6370452778343963 ns
[ 0.000000] random: get_random_bytes called from start_kernel+0x95/0x535 with crng_init=0
[ 0.000000] setup_percpu: NR_CPUS:320 nr_cpumask_bits:320 nr_cpu_ids:2 nr_node_ids:1
[ 0.000000] percpu: Embedded 46 pages/cpu @(____ptrval____) s151552 r8192 d28672 u1048576
[ 0.000000] pcpu-alloc: s151552 r8192 d28672 u1048576 alloc=1*2097152
[ 0.000000] pcpu-alloc: [0] 0 1
[ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes)
[ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1032057
[ 0.000000] Policy zone: Normal
[ 0.000000] Kernel command line: BOOT_IMAGE=/boot/vmlinuz-linux root=UUID=a83c9650-c8f8-4afe-90a6-4e80156d523d rw quiet
[ 0.000000] Calgary: detecting Calgary via BIOS EBDA area
[ 0.000000] Calgary: Unable to locate Rio Grande table in EBDA - bailing!
[ 0.000000] Memory: 4031212K/4193848K available (10252K kernel code, 1297K rwdata, 3528K rodata, 1492K init, 612K bss, 162636K reserved, 0K cma-reserved)
[ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=1
[ 0.000000] Kernel/User page tables isolation: enabled
[ 0.000000] ftrace: allocating 33395 entries in 131 pages
[ 0.003333] Preemptible hierarchical RCU implementation.
[ 0.003333] CONFIG_RCU_FANOUT set to non-default value of 32
[ 0.003333] RCU dyntick-idle grace-period acceleration is enabled.
[ 0.003333] RCU restricting CPUs from NR_CPUS=320 to nr_cpu_ids=2.
[ 0.003333] RCU priority boosting: priority 1 delay 500 ms.
[ 0.003333] Tasks RCU enabled.
[ 0.003333] RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=2
[ 0.003333] NR_IRQS: 20736, nr_irqs: 440, preallocated irqs: 16
[ 0.003333] Offload RCU callbacks from CPUs: (none).
[ 0.003333] Console: colour dummy device 80x25
[ 0.003333] console [tty0] enabled
[ 0.003333] ACPI: Core revision 20180531
[ 0.003333] APIC: Switch to symmetric I/O mode setup
[ 0.003333] x2apic enabled
[ 0.003333] Switched APIC routing to physical x2apic.
[ 0.003333] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[ 0.003333] tsc: Detected 2593.992 MHz processor
[ 0.003333] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x25641074d3b, max_idle_ns: 440795244898 ns
[ 0.003333] Calibrating delay loop (skipped) preset value.. 5190.15 BogoMIPS (lpj=8646640)
[ 0.003333] pid_max: default: 32768 minimum: 301
[ 0.003333] Security Framework initialized
[ 0.003333] Yama: becoming mindful.
[ 0.003333] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes)
[ 0.003971] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes)
[ 0.004014] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes)
[ 0.004025] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes)
[ 0.004309] mce: CPU supports 0 MCE banks
[ 0.004325] Last level iTLB entries: 4KB 1024, 2MB 1024, 4MB 1024
[ 0.004325] Last level dTLB entries: 4KB 1024, 2MB 1024, 4MB 1024, 1GB 4
[ 0.004328] Spectre V2 : Mitigation: Full generic retpoline
[ 0.004328] Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch
[ 0.004329] Speculative Store Bypass: Vulnerable
[ 0.004417] Freeing SMP alternatives memory: 28K
[ 0.006666] smpboot: CPU0: Intel(R) Core(TM) i5-4310U CPU @ 2.00GHz (family: 0x6, model: 0x45, stepping: 0x1)
[ 0.023365] Performance Events: unsupported p6 CPU model 69 no PMU driver, software events only.
[ 0.030022] Hierarchical SRCU implementation.
[ 0.044332] NMI watchdog: Perf event create on CPU 0 failed with -2
[ 0.044336] NMI watchdog: Perf NMI watchdog permanently disabled
[ 0.056697] smp: Bringing up secondary CPUs ...
[ 0.096727] x86: Booting SMP configuration:
[ 0.096731] .... node #0, CPUs: #1
[ 0.003333] kvm-clock: cpu 1, msr 1:1fff6041, secondary cpu clock
[ 0.003333] mce: CPU supports 0 MCE banks
[ 0.099385] smp: Brought up 1 node, 2 CPUs
[ 0.099385] smpboot: Max logical packages: 1
[ 0.099385] smpboot: Total of 2 processors activated (10380.30 BogoMIPS)
[ 0.100140] devtmpfs: initialized
[ 0.100140] x86/mm: Memory block size: 128MB
[ 0.101099] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 6370867519511994 ns
[ 0.101099] futex hash table entries: 512 (order: 3, 32768 bytes)
[ 0.101099] pinctrl core: initialized pinctrl subsystem
[ 0.101099] RTC time: 8:32:36, date: 09/06/18
[ 0.101099] NET: Registered protocol family 16
[ 0.101180] audit: initializing netlink subsys (disabled)
[ 0.103375] audit: type=2000 audit(1536222763.843:1): state=initialized audit_enabled=0 res=1
[ 0.103791] cpuidle: using governor ladder
[ 0.103791] cpuidle: using governor menu
[ 0.103791] ACPI: bus type PCI registered
[ 0.103791] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
[ 0.103791] PCI: Using configuration type 1 for base access
[ 0.106775] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
[ 0.106935] ACPI: Added _OSI(Module Device)
[ 0.106937] ACPI: Added _OSI(Processor Device)
[ 0.106938] ACPI: Added _OSI(3.0 _SCP Extensions)
[ 0.106939] ACPI: Added _OSI(Processor Aggregator Device)
[ 0.106941] ACPI: Added _OSI(Linux-Dell-Video)
[ 0.112542] ACPI: 2 ACPI AML tables successfully acquired and loaded
[ 0.115629] ACPI: Interpreter enabled
[ 0.115639] ACPI: (supports S0 S5)
[ 0.115641] ACPI: Using IOAPIC for interrupt routing
[ 0.115897] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[ 0.116004] ACPI: Enabled 2 GPEs in block 00 to 07
[ 0.121998] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[ 0.122014] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI]
[ 0.122046] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI]
[ 0.122063] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge.
[ 0.122567] PCI host bridge to bus 0000:00
[ 0.122573] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window]
[ 0.122576] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window]
[ 0.122577] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
[ 0.122578] pci_bus 0000:00: root bus resource [mem 0xe0000000-0xfdffffff window]
[ 0.122581] pci_bus 0000:00: root bus resource [bus 00-ff]
[ 0.122629] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000
[ 0.123555] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100
[ 0.124275] pci 0000:00:01.1: [8086:7111] type 00 class 0x01018a
[ 0.124606] pci 0000:00:01.1: reg 0x20: [io 0xd000-0xd00f]
[ 0.124735] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7]
[ 0.124737] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6]
[ 0.124738] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177]
[ 0.124739] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376]
[ 0.125144] pci 0000:00:02.0: [80ee:beef] type 00 class 0x030000
[ 0.126910] pci 0000:00:02.0: reg 0x10: [mem 0xe0000000-0xe07fffff pref]
[ 0.164284] pci 0000:00:03.0: [8086:100e] type 00 class 0x020000
[ 0.170084] pci 0000:00:03.0: reg 0x10: [mem 0xf0000000-0xf001ffff]
[ 0.176805] pci 0000:00:03.0: reg 0x18: [io 0xd010-0xd017]
[ 0.207840] pci 0000:00:04.0: [80ee:cafe] type 00 class 0x088000
[ 0.210134] pci 0000:00:04.0: reg 0x10: [io 0xd020-0xd03f]
[ 0.213550] pci 0000:00:04.0: reg 0x14: [mem 0xf0400000-0xf07fffff]
[ 0.223363] pci 0000:00:04.0: reg 0x18: [mem 0xf0800000-0xf0803fff pref]
[ 0.243975] pci 0000:00:05.0: [8086:2415] type 00 class 0x040100
[ 0.244123] pci 0000:00:05.0: reg 0x10: [io 0xd100-0xd1ff]
[ 0.244189] pci 0000:00:05.0: reg 0x14: [io 0xd200-0xd23f]
[ 0.245644] pci 0000:00:07.0: [8086:7113] type 00 class 0x068000
[ 0.247128] pci 0000:00:07.0: quirk: [io 0x4000-0x403f] claimed by PIIX4 ACPI
[ 0.247150] pci 0000:00:07.0: quirk: [io 0x4100-0x410f] claimed by PIIX4 SMB
[ 0.249317] pci 0000:00:0c.0: [8086:1e31] type 00 class 0x0c0330
[ 0.253369] pci 0000:00:0c.0: reg 0x10: [mem 0xf0810000-0xf081ffff]
[ 0.302124] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 9 10 *11)
[ 0.302675] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 9 *10 11)
[ 0.302861] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 *9 10 11)
[ 0.303031] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 9 10 *11)
[ 0.303482] pci 0000:00:02.0: vgaarb: setting as boot VGA device
[ 0.303482] pci 0000:00:02.0: vgaarb: VGA device added: decodes=io+mem,owns=io+mem,locks=none
[ 0.303482] pci 0000:00:02.0: vgaarb: bridge control possible
[ 0.303482] vgaarb: loaded
[ 0.303679] pps_core: LinuxPPS API ver. 1 registered
[ 0.303680] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[ 0.303683] PTP clock support registered
[ 0.303697] EDAC MC: Ver: 3.0.0
[ 0.304315] PCI: Using ACPI for IRQ routing
[ 0.304315] PCI: pci_cache_line_size set to 64 bytes
[ 0.304315] e820: reserve RAM buffer [mem 0x0009fc00-0x0009ffff]
[ 0.304315] e820: reserve RAM buffer [mem 0xdfff0000-0xdfffffff]
[ 0.304315] NetLabel: Initializing
[ 0.304315] NetLabel: domain hash size = 128
[ 0.304315] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO
[ 0.304315] NetLabel: unlabeled traffic allowed by default
[ 0.304315] clocksource: Switched to clocksource kvm-clock
[ 0.321206] VFS: Disk quotas dquot_6.6.0
[ 0.321225] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[ 0.321307] pnp: PnP ACPI init
[ 0.321392] pnp 00:00: Plug and Play ACPI device, IDs PNP0303 (active)
[ 0.321472] pnp 00:01: Plug and Play ACPI device, IDs PNP0f03 (active)
[ 0.322299] pnp: PnP ACPI: found 2 devices
[ 0.339603] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
[ 0.339617] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window]
[ 0.339620] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window]
[ 0.339622] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window]
[ 0.339625] pci_bus 0000:00: resource 7 [mem 0xe0000000-0xfdffffff window]
[ 0.339717] NET: Registered protocol family 2
[ 0.339945] tcp_listen_portaddr_hash hash table entries: 2048 (order: 3, 32768 bytes)
[ 0.339962] TCP established hash table entries: 32768 (order: 6, 262144 bytes)
[ 0.340053] TCP bind hash table entries: 32768 (order: 7, 524288 bytes)
[ 0.340119] TCP: Hash tables configured (established 32768 bind 32768)
[ 0.340155] UDP hash table entries: 2048 (order: 4, 65536 bytes)
[ 0.340169] UDP-Lite hash table entries: 2048 (order: 4, 65536 bytes)
[ 0.340221] NET: Registered protocol family 1
[ 0.340228] NET: Registered protocol family 44
[ 0.340235] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
[ 0.340279] pci 0000:00:01.0: Activating ISA DMA hang workarounds
[ 0.340343] pci 0000:00:02.0: Video device with shadowed ROM at [mem 0x000c0000-0x000dffff]
[ 0.342324] PCI: CLS 0 bytes, default 64
[ 0.342428] Unpacking initramfs...
[ 0.468721] Freeing initrd memory: 7548K
[ 0.468736] PCI-DMA: Using software bounce buffering for IO (SWIOTLB)
[ 0.468739] software IO TLB [mem 0xdbff0000-0xdfff0000] (64MB) mapped at [(____ptrval____)-(____ptrval____)]
[ 0.468792] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x25641074d3b, max_idle_ns: 440795244898 ns
[ 0.468834] platform rtc_cmos: registered platform RTC device (no PNP device found)
[ 0.468875] Scanning for low memory corruption every 60 seconds
[ 0.469442] Initialise system trusted keyrings
[ 0.469452] Key type blacklist registered
[ 0.469562] workingset: timestamp_bits=41 max_order=20 bucket_order=0
[ 0.470683] zbud: loaded
[ 0.470999] pstore: using lz4hc compression
[ 0.473446] Key type asymmetric registered
[ 0.473447] Asymmetric key parser 'x509' registered
[ 0.473477] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 245)
[ 0.477094] io scheduler noop registered
[ 0.477098] io scheduler deadline registered
[ 0.477270] io scheduler cfq registered (default)
[ 0.477272] io scheduler mq-deadline registered
[ 0.477274] io scheduler kyber registered
[ 0.477324] io scheduler bfq registered
[ 0.477881] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
[ 0.478023] vesafb: mode is 640x480x32, linelength=2560, pages=0
[ 0.478025] vesafb: scrolling: redraw
[ 0.478027] vesafb: Truecolor: size=8:8:8:8, shift=24:16:8:0
[ 0.478055] vesafb: framebuffer at 0xe0000000, mapped to 0x(____ptrval____), using 1216k, total 1216k
[ 0.480489] Console: switching to colour frame buffer device 80x30
[ 0.481244] fb0: VESA VGA frame buffer device
[ 0.481294] intel_idle: Please enable MWAIT in BIOS SETUP
[ 0.481389] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
[ 0.481414] ACPI: Power Button [PWRF]
[ 0.481485] input: Sleep Button as /devices/LNXSYSTM:00/LNXSLPBN:00/input/input1
[ 0.481491] ACPI: Sleep Button [SLPF]
[ 0.481593] ACPI: Video Device [GFX0] (multi-head: yes rom: no post: no)
[ 0.481678] input: Video Bus as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A03:00/LNXVIDEO:00/input/input2
[ 0.482373] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[ 0.490476] ledtrig-cpu: registered to indicate activity on CPUs
[ 0.490710] NET: Registered protocol family 10
[ 0.505142] Segment Routing with IPv6
[ 0.505185] NET: Registered protocol family 17
[ 0.505572] RAS: Correctable Errors collector initialized.
[ 0.505588] sched_clock: Marking stable (505509868, 0)->(823528256, -318018388)
[ 0.506354] registered taskstats version 1
[ 0.506365] Loading compiled-in X.509 certificates
[ 0.506387] zswap: loaded using pool lzo/zbud
[ 0.515022] Key type big_key registered
[ 0.515264] Magic number: 2:792:522
[ 0.515302] hctosys: unable to open rtc device (rtc0)
[ 0.525768] Freeing unused kernel image memory: 1492K
[ 0.525876] Write protecting the kernel read-only data: 16384k
[ 0.527846] Freeing unused kernel image memory: 2016K
[ 0.528593] Freeing unused kernel image memory: 568K
[ 0.607501] SCSI subsystem initialized
[ 0.636094] ACPI: bus type USB registered
[ 0.636122] usbcore: registered new interface driver usbfs
[ 0.636133] usbcore: registered new interface driver hub
[ 0.636341] usbcore: registered new device driver usb
[ 0.642061] libata version 3.00 loaded.
[ 0.643517] ata_piix 0000:00:01.1: version 2.13
[ 0.662205] scsi host0: ata_piix
[ 0.664586] i8042: PNP: PS/2 Controller [PNP0303:PS2K,PNP0f03:PS2M] at 0x60,0x64 irq 1,12
[ 0.665193] serio: i8042 KBD port at 0x60,0x64 irq 1
[ 0.668522] serio: i8042 AUX port at 0x60,0x64 irq 12
[ 0.670605] scsi host1: ata_piix
[ 0.670700] ata1: PATA max UDMA/33 cmd 0x1f0 ctl 0x3f6 bmdma 0xd000 irq 14
[ 0.670703] ata2: PATA max UDMA/33 cmd 0x170 ctl 0x376 bmdma 0xd008 irq 15
[ 0.684217] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input3
[ 0.684738] xhci_hcd 0000:00:0c.0: xHCI Host Controller
[ 0.684747] xhci_hcd 0000:00:0c.0: new USB bus registered, assigned bus number 1
[ 1.075827] ata1.01: NODEV after polling detection
[ 1.076074] ata1.00: ATA-6: VBOX HARDDISK, 1.0, max UDMA/133
[ 1.076076] ata1.00: 41943040 sectors, multi 128: LBA
[ 1.076669] xhci_hcd 0000:00:0c.0: hcc params 0x04000000 hci version 0x100 quirks 0x000000000000b930
[ 1.076748] scsi 0:0:0:0: Direct-Access ATA VBOX HARDDISK 1.0 PQ: 0 ANSI: 5
[ 1.077547] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.18
[ 1.077551] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 1.077553] usb usb1: Product: xHCI Host Controller
[ 1.077555] usb usb1: Manufacturer: Linux 4.18.5-arch1-1-ARCH xhci-hcd
[ 1.077557] usb usb1: SerialNumber: 0000:00:0c.0
[ 1.078078] hub 1-0:1.0: USB hub found
[ 1.078187] hub 1-0:1.0: 8 ports detected
[ 1.080347] xhci_hcd 0000:00:0c.0: xHCI Host Controller
[ 1.080353] xhci_hcd 0000:00:0c.0: new USB bus registered, assigned bus number 2
[ 1.080359] xhci_hcd 0000:00:0c.0: Host supports USB 3.0 SuperSpeed
[ 1.080645] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 4.18
[ 1.080648] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 1.080650] usb usb2: Product: xHCI Host Controller
[ 1.080652] usb usb2: Manufacturer: Linux 4.18.5-arch1-1-ARCH xhci-hcd
[ 1.080653] usb usb2: SerialNumber: 0000:00:0c.0
[ 1.080868] hub 2-0:1.0: USB hub found
[ 1.080908] hub 2-0:1.0: 6 ports detected
[ 1.088766] sd 0:0:0:0: [sda] 41943040 512-byte logical blocks: (21.5 GB/20.0 GiB)
[ 1.088781] sd 0:0:0:0: [sda] Write Protect is off
[ 1.088783] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[ 1.088801] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 1.098859] sda: sda1 sda2
[ 1.099630] sd 0:0:0:0: [sda] Attached SCSI disk
[ 1.226504] raid6: sse2x1 gen() 5525 MB/s
[ 1.286935] raid6: sse2x1 xor() 3925 MB/s
[ 1.351882] raid6: sse2x2 gen() 6373 MB/s
[ 1.409812] raid6: sse2x2 xor() 5337 MB/s
[ 1.466925] raid6: sse2x4 gen() 7334 MB/s
[ 1.530167] usb 1-1: new high-speed USB device number 2 using xhci_hcd
[ 1.530205] raid6: sse2x4 xor() 3160 MB/s
[ 1.586811] raid6: avx2x1 gen() 2545 MB/s
[ 1.647330] raid6: avx2x1 xor() 4374 MB/s
[ 1.689474] usb 1-1: New USB device found, idVendor=152d, idProduct=0539, bcdDevice= 2.06
[ 1.689478] usb 1-1: New USB device strings: Mfr=10, Product=11, SerialNumber=3
[ 1.689480] usb 1-1: Product: External USB 3.0
[ 1.689482] usb 1-1: Manufacturer: Intenso
[ 1.689484] usb 1-1: SerialNumber: 20120625001B2
[ 1.698164] usb-storage 1-1:1.0: USB Mass Storage device detected
[ 1.705386] usb-storage 1-1:1.0: Quirks match for vid 152d pid 0539: 4000000
[ 1.705467] scsi host2: usb-storage 1-1:1.0
[ 1.706162] usbcore: registered new interface driver usb-storage
[ 1.711960] raid6: avx2x2 gen() 10713 MB/s
[ 1.766779] raid6: avx2x2 xor() 5911 MB/s
[ 1.823481] raid6: avx2x4 gen() 12573 MB/s
[ 1.882040] raid6: avx2x4 xor() 8853 MB/s
[ 1.882046] raid6: using algorithm avx2x4 gen() 12573 MB/s
[ 1.882048] raid6: .... xor() 8853 MB/s, rmw enabled
[ 1.882051] raid6: using avx2x2 recovery algorithm
[ 1.882382] usb 2-1: new SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 1.888787] xor: automatically using best checksumming function avx
[ 1.898493] usb 2-1: New USB device found, idVendor=152d, idProduct=0539, bcdDevice= 2.06
[ 1.898496] usb 2-1: New USB device strings: Mfr=10, Product=11, SerialNumber=3
[ 1.898498] usb 2-1: Product: External USB 3.0
[ 1.898500] usb 2-1: Manufacturer: Intenso
[ 1.898502] usb 2-1: SerialNumber: 2012071215002
[ 1.899974] usb-storage 2-1:1.0: USB Mass Storage device detected
[ 1.903413] usb-storage 2-1:1.0: Quirks match for vid 152d pid 0539: 4000000
[ 1.903466] scsi host3: usb-storage 2-1:1.0
[ 1.918187] Btrfs loaded, crc32c=crc32c-intel
[ 1.918798] BTRFS: device label rootfs devid 1 transid 42 /dev/sda2
[ 1.949726] BTRFS info (device sda2): disk space caching is enabled
[ 1.949728] BTRFS info (device sda2): has skinny extents
[ 2.054552] random: fast init done
[ 2.220202] systemd[1]: systemd 239 running in system mode. (+PAM -AUDIT -SELINUX -IMA -APPARMOR +SMACK -SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN +PCRE2 default-hierarchy=hybrid)
[ 2.220232] systemd[1]: Detected virtualization oracle.
[ 2.220236] systemd[1]: Detected architecture x86-64.
[ 2.225882] systemd[1]: Set hostname to <archlinux>.
[ 2.356325] random: systemd: uninitialized urandom read (16 bytes read)
[ 2.356378] systemd[1]: Listening on Device-mapper event daemon FIFOs.
[ 2.356424] random: systemd: uninitialized urandom read (16 bytes read)
[ 2.356535] systemd[1]: Listening on Journal Socket.
[ 2.356711] random: systemd: uninitialized urandom read (16 bytes read)
[ 2.360224] systemd[1]: Mounting Kernel Configuration File System...
[ 2.361606] systemd[1]: Listening on udev Kernel Socket.
[ 2.361764] systemd[1]: Reached target Remote Encrypted Volumes.
[ 2.361941] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[ 2.422287] BTRFS info (device sda2): disk space caching is enabled
[ 2.550188] systemd-journald[216]: Received request to flush runtime journal from PID 1
[ 2.662915] systemd-journald[216]: File /var/log/journal/d8b7d823fa4b4e219a8c84bf6d1fe82c/system.journal corrupted or uncleanly shut down, renaming and replacing.
[ 2.717817] scsi 2:0:0:0: Direct-Access Intenso External USB 3.0 0206 PQ: 0 ANSI: 6
[ 2.719008] sd 2:0:0:0: [sdb] 1953523712 512-byte logical blocks: (1.00 TB/932 GiB)
[ 2.719866] sd 2:0:0:0: [sdb] Write Protect is off
[ 2.719869] sd 2:0:0:0: [sdb] Mode Sense: 27 00 00 00
[ 2.721935] sd 2:0:0:0: [sdb] No Caching mode page found
[ 2.722009] sd 2:0:0:0: [sdb] Assuming drive cache: write through
[ 2.728515] sdb: sdb1 sdb2
[ 2.729066] sdb: p2 size 19914992 extends beyond EOD, enabling native capacity
[ 2.733219] sdb: sdb1 sdb2
[ 2.733988] sdb: p2 size 19914992 extends beyond EOD, truncated
[ 2.737554] sd 2:0:0:0: [sdb] Attached SCSI disk
[ 2.870788] ACPI: Battery Slot [BAT0] (battery present)
[ 2.871906] Linux agpgart interface v0.103
[ 2.875858] ACPI: AC Adapter [AC] (on-line)
[ 2.881081] piix4_smbus 0000:00:07.0: SMBus Host Controller at 0x4100, revision 0
[ 2.885979] vboxguest: host-version: 5.2.18r123745 0x1
[ 2.886675] vbg_heartbeat_init: Setting up heartbeat to trigger every 2000 milliseconds
[ 2.889343] input: VirtualBox mouse integration as /devices/pci0000:00/0000:00:04.0/input/input5
[ 2.890385] vboxguest: misc device minor 57, IRQ 20, I/O port d020, MMIO at 0x00000000f0400000 (size 0x0000000000400000)
[ 2.905724] e1000: Intel(R) PRO/1000 Network Driver - version 7.3.21-k8-NAPI
[ 2.905725] e1000: Copyright (c) 1999-2006 Intel Corporation.
[ 2.931231] rtc_cmos rtc_cmos: registered as rtc0
[ 2.931249] rtc_cmos rtc_cmos: alarms up to one day, 114 bytes nvram
[ 2.934276] scsi 3:0:0:0: Direct-Access Intenso External USB 3.0 0206 PQ: 0 ANSI: 6
[ 2.934913] sd 3:0:0:0: [sdc] 1953523712 512-byte logical blocks: (1.00 TB/932 GiB)
[ 2.935369] sd 3:0:0:0: [sdc] Write Protect is off
[ 2.935372] sd 3:0:0:0: [sdc] Mode Sense: 27 00 00 00
[ 2.935803] sd 3:0:0:0: [sdc] No Caching mode page found
[ 2.935862] sd 3:0:0:0: [sdc] Assuming drive cache: write through
[ 2.939364] sdc: sdc1
[ 2.941245] sd 3:0:0:0: [sdc] Attached SCSI disk
[ 2.971012] usbcore: registered new interface driver uas
[ 2.976712] RAPL PMU: API unit is 2^-32 Joules, 4 fixed counters, 10737418240 ms ovfl timer
[ 2.976713] RAPL PMU: hw unit of domain pp0-core 2^-0 Joules
[ 2.976714] RAPL PMU: hw unit of domain package 2^-0 Joules
[ 2.976715] RAPL PMU: hw unit of domain dram 2^-0 Joules
[ 2.976716] RAPL PMU: hw unit of domain pp1-gpu 2^-0 Joules
[ 2.997577] input: PC Speaker as /devices/platform/pcspkr/input/input7
[ 3.022025] Adding 2024444k swap on /dev/sda1. Priority:-2 extents:1 across:2024444k FS
[ 3.058370] cryptd: max_cpu_qlen set to 1000
[ 3.086189] AVX2 version of gcm_enc/dec engaged.
[ 3.086191] AES CTR mode by8 optimization enabled
[ 3.089852] mousedev: PS/2 mouse device common for all mice
[ 3.168389] vboxvideo: module is from the staging directory, the quality is unknown, you have been warned.
[ 3.171996] [drm] VRAM 00800000
[ 3.176777] [TTM] Zone kernel: Available graphics memory: 2021432 kiB
[ 3.176779] [TTM] Initializing pool allocator
[ 3.176782] [TTM] Initializing DMA pool allocator
[ 3.179667] checking generic (e0000000 130000) vs hw (e0000000 800000)
[ 3.179668] fb: switching to vboxdrmfb from VESA VGA
[ 3.179689] Console: switching to colour dummy device 80x25
[ 3.181528] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input6
[ 3.181887] fbcon: vboxdrmfb (fb0) is primary device
[ 3.182621] Console: switching to colour frame buffer device 100x37
[ 3.183900] vboxvideo 0000:00:02.0: fb0: vboxdrmfb frame buffer device
[ 3.203426] [drm] Initialized vboxvideo 1.0.0 20130823 for 0000:00:02.0 on minor 0
[ 3.262796] BTRFS: device label intenso_usb_black devid 1 transid 57 /dev/sdc1
[ 3.272853] BTRFS: device label intenso_white devid 1 transid 4790 /dev/sdb1
[ 3.811983] vboxsf: loading out-of-tree module taints kernel.
[ 4.009067] random: crng init done
[ 4.009080] random: 7 urandom warning(s) missed due to ratelimiting
[ 4.020238] snd_intel8x0 0000:00:05.0: intel8x0_measure_ac97_clock: measured 58895 usecs (14336 samples)
[ 4.020242] snd_intel8x0 0000:00:05.0: measured clock 243416 rejected
[ 4.099036] e1000 0000:00:03.0 eth0: (PCI:33MHz:32-bit) 08:00:27:b4:cd:7d
[ 4.099043] e1000 0000:00:03.0 eth0: Intel(R) PRO/1000 Network Connection
[ 4.111316] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 4.415332] snd_intel8x0 0000:00:05.0: intel8x0_measure_ac97_clock: measured 57377 usecs (14336 samples)
[ 4.415338] snd_intel8x0 0000:00:05.0: measured clock 249856 rejected
[ 4.838448] snd_intel8x0 0000:00:05.0: intel8x0_measure_ac97_clock: measured 47261 usecs (11264 samples)
[ 4.838452] snd_intel8x0 0000:00:05.0: measured clock 238336 rejected
[ 4.838454] snd_intel8x0 0000:00:05.0: clocking to 48000
[ 6.299323] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
[ 6.299751] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[ 10.588498] audit: type=1006 audit(1536222772.771:2): pid=319 uid=0 old-auid=4294967295 auid=1000 tty=(none) old-ses=4294967295 ses=1 res=1
[ 10.653278] audit: type=1006 audit(1536222772.834:3): pid=322 uid=0 old-auid=4294967295 auid=1000 tty=(none) old-ses=4294967295 ses=2 res=1
[ 10.799356] systemd-journald[216]: File /var/log/journal/d8b7d823fa4b4e219a8c84bf6d1fe82c/user-1000.journal corrupted or uncleanly shut down, renaming and replacing.
[ 141.213745] usb 2-1: USB disconnect, device number 2
[ 239.329476] audit: type=1006 audit(1536223001.473:4): pid=510 uid=0 old-auid=4294967295 auid=1000 tty=(none) old-ses=4294967295 ses=3 res=1
[ 239.353422] audit: type=1006 audit(1536223001.497:5): pid=513 uid=0 old-auid=4294967295 auid=1000 tty=(none) old-ses=4294967295 ses=4 res=1
[ 260.645105] audit: type=1006 audit(1536223022.793:6): pid=528 uid=0 old-auid=4294967295 auid=1000 tty=(none) old-ses=4294967295 ses=5 res=1
[ 260.666712] audit: type=1006 audit(1536223022.816:7): pid=531 uid=0 old-auid=4294967295 auid=1000 tty=(none) old-ses=4294967295 ses=6 res=1
[ 285.729540] audit: type=1006 audit(1536223047.883:8): pid=2951 uid=0 old-auid=4294967295 auid=1000 tty=(none) old-ses=4294967295 ses=7 res=1
[ 285.750233] audit: type=1006 audit(1536223047.900:9): pid=2954 uid=0 old-auid=4294967295 auid=1000 tty=(none) old-ses=4294967295 ses=8 res=1
[ 302.217171] BTRFS info (device sdb1): disk space caching is enabled
[ 302.217173] BTRFS info (device sdb1): has skinny extents
[ 631.223843] audit: type=1006 audit(1536223393.390:10): pid=3029 uid=0 old-auid=4294967295 auid=1000 tty=(none) old-ses=4294967295 ses=9 res=1
^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: btrfs send hung in pipe_wait
2018-09-06 9:22 btrfs send hung in pipe_wait Stefan Löwen
@ 2018-09-06 15:04 ` Stefan Loewen
2018-09-06 15:48 ` Chris Murphy
0 siblings, 1 reply; 17+ messages in thread
From: Stefan Loewen @ 2018-09-06 15:04 UTC (permalink / raw)
To: linux-btrfs
Update:
It seems like btrfs-send is not completely hung. It somewhat regularly
wakes up every hour to transfer a few bytes. I noticed this via a
periodic 'ls -l' on the snapshot file. These are the last outputs
(uniq'ed):
-rw------- 1 root root 1492797759 Sep 6 08:44 intenso_white.snapshot
-rw------- 1 root root 1493087856 Sep 6 09:44 intenso_white.snapshot
-rw------- 1 root root 1773825308 Sep 6 10:44 intenso_white.snapshot
-rw------- 1 root root 1773976853 Sep 6 11:58 intenso_white.snapshot
-rw------- 1 root root 1774122301 Sep 6 12:59 intenso_white.snapshot
-rw------- 1 root root 1774274264 Sep 6 13:58 intenso_white.snapshot
-rw------- 1 root root 1774435235 Sep 6 14:57 intenso_white.snapshot
I also monitor the /proc/3022/task/*/stack files with 'tail -f' (I
have no idea if this is useful) but there are no changes, even during
the short wakeups.
Am Do., 6. Sep. 2018 um 11:22 Uhr schrieb Stefan Löwen
<stefan.loewen@gmail.com>:
>
> Hello linux-btrfs,
>
> I'm trying to clone a subvolume with 'btrfs send' but it always hangs
> for hours.
>
> I tested this on multiple systems. All showed the same result:
> - Manjaro (btrfs-progs v4.17.1; linux v4.18.5-1-MANJARO)
> - Ubuntu 18.04 in VirtualBox (btrfs-progs v4.15.1; linux v4.15.0-33-generic)
> - ArchLinux in VirtualBox (btrfs-progs v4.17.1; linux v4.18.5-arch1-1-ARCH)
> All following logs are from the ArchLinux VM.
>
> To make sure it's not the 'btrfs receive' at fault I tried sending into
> a file using the following command:
> 'strace -o btrfs-send.strace btrfs send -vvv -f intenso_white.snapshot
> /mnt/intenso_white/@data/.snapshots/test-snapshot'
>
> The 'btrfs send' process always copies around 1.2-1.4G of data, then
> stops all disk IO and fully loads one cpu core. btrfs scrub found 0
> errors. Neither did btrfsck. 'btrfs device stats' is all 0.
>
> I would be thankful for all ideas and tips.
>
> Regards
> Stefan
>
> ---------------------------------------------
>
> The btrfs-send.strace is attached. So is the dmesg.log during the hang.
>
> Stack traces of the hung process:
> --- /proc/3022/task/3022/stack ---
> [<0>] 0xffffffffffffffff
> --- /proc/3022/task/3023/stack ---
> [<0>] pipe_wait+0x6c/0xb0
> [<0>] splice_from_pipe_next.part.3+0x24/0xa0
> [<0>] __splice_from_pipe+0x43/0x180
> [<0>] splice_from_pipe+0x5d/0x90
> [<0>] default_file_splice_write+0x15/0x20
> [<0>] __se_sys_splice+0x31b/0x770
> [<0>] do_syscall_64+0x5b/0x170
> [<0>] entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [<0>] 0xffffffffffffffff
>
> [vagrant@archlinux mnt]$ uname -a
> Linux archlinux 4.18.5-arch1-1-ARCH #1 SMP PREEMPT Fri Aug 24 12:48:58
> UTC 2018 x86_64 GNU/Linux
>
> [vagrant@archlinux mnt]$ btrfs --version
> btrfs-progs v4.17.1
>
> [vagrant@archlinux mnt]$ sudo btrfs fi show /dev/sdb1
> Label: 'intenso_white' uuid: 07bf61ed-7728-4151-a784-c4b840e343ed
> Total devices 1 FS bytes used 655.82GiB
> devid 1 size 911.51GiB used 703.09GiB path /dev/sdb1
>
> [vagrant@archlinux mnt]$ sudo btrfs fi df /mnt/intenso_white/
> Data, single: total=695.01GiB, used=653.69GiB
> System, DUP: total=40.00MiB, used=96.00KiB
> Metadata, DUP: total=4.00GiB, used=2.13GiB
> GlobalReserve, single: total=512.00MiB, used=0.00B
>
^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: btrfs send hung in pipe_wait
2018-09-06 15:04 ` Stefan Loewen
@ 2018-09-06 15:48 ` Chris Murphy
2018-09-06 16:03 ` Stefan Löwen
0 siblings, 1 reply; 17+ messages in thread
From: Chris Murphy @ 2018-09-06 15:48 UTC (permalink / raw)
To: Stefan Loewen; +Cc: Btrfs BTRFS
On Thu, Sep 6, 2018 at 9:04 AM, Stefan Loewen <stefan.loewen@gmail.com> wrote:
> Update:
> It seems like btrfs-send is not completely hung. It somewhat regularly
> wakes up every hour to transfer a few bytes. I noticed this via a
> periodic 'ls -l' on the snapshot file. These are the last outputs
> (uniq'ed):
>
> -rw------- 1 root root 1492797759 Sep 6 08:44 intenso_white.snapshot
> -rw------- 1 root root 1493087856 Sep 6 09:44 intenso_white.snapshot
> -rw------- 1 root root 1773825308 Sep 6 10:44 intenso_white.snapshot
> -rw------- 1 root root 1773976853 Sep 6 11:58 intenso_white.snapshot
> -rw------- 1 root root 1774122301 Sep 6 12:59 intenso_white.snapshot
> -rw------- 1 root root 1774274264 Sep 6 13:58 intenso_white.snapshot
> -rw------- 1 root root 1774435235 Sep 6 14:57 intenso_white.snapshot
>
> I also monitor the /proc/3022/task/*/stack files with 'tail -f' (I
> have no idea if this is useful) but there are no changes, even during
> the short wakeups.
I have a sort of "me too" here. I definitely see btrfs send just hang
for no apparent reason, but in my case it's for maybe 15-30 seconds.
Not an hour. Looking at top and iotop at the same time as the LED
lights on the drives, there's definitely zero activity happening. I
can make things happen during this time - like I can read a file or
save a file from/to any location including the send source or receive
destination. It really just behaves as if the send thread is saying
"OK I'm gonna nap now, back in a bit" and then it is.
So what I end up with on drives with a minimum read-write of 80M/s, is
a send receive that's getting me a net of about 30M/s.
I have around 100 snapshots on the source device. How many total
snapshots do you have on your source? That does appear to affect
performance for some things, including send/receive.
--
Chris Murphy
^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: btrfs send hung in pipe_wait
2018-09-06 15:48 ` Chris Murphy
@ 2018-09-06 16:03 ` Stefan Löwen
2018-09-06 18:16 ` Chris Murphy
0 siblings, 1 reply; 17+ messages in thread
From: Stefan Löwen @ 2018-09-06 16:03 UTC (permalink / raw)
To: Chris Murphy; +Cc: Btrfs BTRFS
[-- Attachment #1: Type: text/plain, Size: 2237 bytes --]
I have one subvolume (rw) and 2 snapshots (ro) of it.
I just tested 'btrfs send <subvol> > /dev/null' and that also shows no
IO after a while but also no significant CPU usage.
During this I tried 'ls' on the source subvolume and it hangs as well.
dmesg has some interesting messages I think (see attached dmesg.log)
On 9/6/18 5:48 PM, Chris Murphy wrote:
> On Thu, Sep 6, 2018 at 9:04 AM, Stefan Loewen <stefan.loewen@gmail.com> wrote:
>> Update:
>> It seems like btrfs-send is not completely hung. It somewhat regularly
>> wakes up every hour to transfer a few bytes. I noticed this via a
>> periodic 'ls -l' on the snapshot file. These are the last outputs
>> (uniq'ed):
>>
>> -rw------- 1 root root 1492797759 Sep 6 08:44 intenso_white.snapshot
>> -rw------- 1 root root 1493087856 Sep 6 09:44 intenso_white.snapshot
>> -rw------- 1 root root 1773825308 Sep 6 10:44 intenso_white.snapshot
>> -rw------- 1 root root 1773976853 Sep 6 11:58 intenso_white.snapshot
>> -rw------- 1 root root 1774122301 Sep 6 12:59 intenso_white.snapshot
>> -rw------- 1 root root 1774274264 Sep 6 13:58 intenso_white.snapshot
>> -rw------- 1 root root 1774435235 Sep 6 14:57 intenso_white.snapshot
>>
>> I also monitor the /proc/3022/task/*/stack files with 'tail -f' (I
>> have no idea if this is useful) but there are no changes, even during
>> the short wakeups.
> I have a sort of "me too" here. I definitely see btrfs send just hang
> for no apparent reason, but in my case it's for maybe 15-30 seconds.
> Not an hour. Looking at top and iotop at the same time as the LED
> lights on the drives, there's definitely zero activity happening. I
> can make things happen during this time - like I can read a file or
> save a file from/to any location including the send source or receive
> destination. It really just behaves as if the send thread is saying
> "OK I'm gonna nap now, back in a bit" and then it is.
>
> So what I end up with on drives with a minimum read-write of 80M/s, is
> a send receive that's getting me a net of about 30M/s.
>
> I have around 100 snapshots on the source device. How many total
> snapshots do you have on your source? That does appear to affect
> performance for some things, including send/receive.
>
>
[-- Attachment #2: dmesg.log --]
[-- Type: text/x-log, Size: 54560 bytes --]
[ 0.000000] Linux version 4.18.5-arch1-1-ARCH (builduser@heftig-12250) (gcc version 8.2.0 (GCC)) #1 SMP PREEMPT Fri Aug 24 12:48:58 UTC 2018
[ 0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-linux root=UUID=a83c9650-c8f8-4afe-90a6-4e80156d523d rw quiet
[ 0.000000] KERNEL supported cpus:
[ 0.000000] Intel GenuineIntel
[ 0.000000] AMD AuthenticAMD
[ 0.000000] Centaur CentaurHauls
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
[ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256
[ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format.
[ 0.000000] BIOS-provided physical RAM map:
[ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
[ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
[ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000dffeffff] usable
[ 0.000000] BIOS-e820: [mem 0x00000000dfff0000-0x00000000dfffffff] ACPI data
[ 0.000000] BIOS-e820: [mem 0x00000000fec00000-0x00000000fec00fff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000fee00000-0x00000000fee00fff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
[ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x000000011fffffff] usable
[ 0.000000] NX (Execute Disable) protection: active
[ 0.000000] SMBIOS 2.5 present.
[ 0.000000] DMI: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
[ 0.000000] Hypervisor detected: KVM
[ 0.000000] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
[ 0.000000] e820: remove [mem 0x000a0000-0x000fffff] usable
[ 0.000000] last_pfn = 0x120000 max_arch_pfn = 0x400000000
[ 0.000000] MTRR default type: uncachable
[ 0.000000] MTRR variable ranges disabled:
[ 0.000000] Disabled
[ 0.000000] x86/PAT: MTRRs disabled, skipping PAT initialization too.
[ 0.000000] CPU MTRRs all blank - virtualized system.
[ 0.000000] x86/PAT: Configuration [0-7]: WB WT UC- UC WB WT UC- UC
[ 0.000000] last_pfn = 0xdfff0 max_arch_pfn = 0x400000000
[ 0.000000] found SMP MP-table at [mem 0x0009fff0-0x0009ffff] mapped at [(____ptrval____)]
[ 0.000000] Scanning 1 areas for low memory corruption
[ 0.000000] Base memory trampoline at [(____ptrval____)] 99000 size 24576
[ 0.000000] BRK [0x115a77000, 0x115a77fff] PGTABLE
[ 0.000000] BRK [0x115a78000, 0x115a78fff] PGTABLE
[ 0.000000] BRK [0x115a79000, 0x115a79fff] PGTABLE
[ 0.000000] BRK [0x115a7a000, 0x115a7afff] PGTABLE
[ 0.000000] BRK [0x115a7b000, 0x115a7bfff] PGTABLE
[ 0.000000] BRK [0x115a7c000, 0x115a7cfff] PGTABLE
[ 0.000000] BRK [0x115a7d000, 0x115a7dfff] PGTABLE
[ 0.000000] BRK [0x115a7e000, 0x115a7efff] PGTABLE
[ 0.000000] BRK [0x115a7f000, 0x115a7ffff] PGTABLE
[ 0.000000] RAMDISK: [mem 0x3712d000-0x3788dfff]
[ 0.000000] ACPI: Early table checksum verification disabled
[ 0.000000] ACPI: RSDP 0x00000000000E0000 000024 (v02 VBOX )
[ 0.000000] ACPI: XSDT 0x00000000DFFF0030 00003C (v01 VBOX VBOXXSDT 00000001 ASL 00000061)
[ 0.000000] ACPI: FACP 0x00000000DFFF00F0 0000F4 (v04 VBOX VBOXFACP 00000001 ASL 00000061)
[ 0.000000] ACPI: DSDT 0x00000000DFFF0470 0021FF (v02 VBOX VBOXBIOS 00000002 INTL 20180629)
[ 0.000000] ACPI: FACS 0x00000000DFFF0200 000040
[ 0.000000] ACPI: FACS 0x00000000DFFF0200 000040
[ 0.000000] ACPI: APIC 0x00000000DFFF0240 00005C (v02 VBOX VBOXAPIC 00000001 ASL 00000061)
[ 0.000000] ACPI: SSDT 0x00000000DFFF02A0 0001CC (v01 VBOX VBOXCPUT 00000002 INTL 20180629)
[ 0.000000] ACPI: Local APIC address 0xfee00000
[ 0.000000] No NUMA configuration found
[ 0.000000] Faking a node at [mem 0x0000000000000000-0x000000011fffffff]
[ 0.000000] NODE_DATA(0) allocated [mem 0x11fffc000-0x11fffffff]
[ 0.000000] kvm-clock: cpu 0, msr 1:1fff6001, primary cpu clock
[ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00
[ 0.000000] kvm-clock: using sched offset of 4903144421 cycles
[ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
[ 0.000000] Zone ranges:
[ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff]
[ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff]
[ 0.000000] Normal [mem 0x0000000100000000-0x000000011fffffff]
[ 0.000000] Device empty
[ 0.000000] Movable zone start for each node
[ 0.000000] Early memory node ranges
[ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff]
[ 0.000000] node 0: [mem 0x0000000000100000-0x00000000dffeffff]
[ 0.000000] node 0: [mem 0x0000000100000000-0x000000011fffffff]
[ 0.000000] Reserved but unavailable: 114 pages
[ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x000000011fffffff]
[ 0.000000] On node 0 totalpages: 1048462
[ 0.000000] DMA zone: 64 pages used for memmap
[ 0.000000] DMA zone: 21 pages reserved
[ 0.000000] DMA zone: 3998 pages, LIFO batch:0
[ 0.000000] DMA32 zone: 14272 pages used for memmap
[ 0.000000] DMA32 zone: 913392 pages, LIFO batch:31
[ 0.000000] Normal zone: 2048 pages used for memmap
[ 0.000000] Normal zone: 131072 pages, LIFO batch:31
[ 0.000000] ACPI: PM-Timer IO Port: 0x4008
[ 0.000000] ACPI: Local APIC address 0xfee00000
[ 0.000000] IOAPIC[0]: apic_id 2, version 32, address 0xfec00000, GSI 0-23
[ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 low level)
[ 0.000000] ACPI: IRQ0 used by override.
[ 0.000000] ACPI: IRQ9 used by override.
[ 0.000000] Using ACPI (MADT) for SMP configuration information
[ 0.000000] smpboot: Allowing 2 CPUs, 0 hotplug CPUs
[ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff]
[ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff]
[ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff]
[ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff]
[ 0.000000] PM: Registered nosave memory: [mem 0xdfff0000-0xdfffffff]
[ 0.000000] PM: Registered nosave memory: [mem 0xe0000000-0xfebfffff]
[ 0.000000] PM: Registered nosave memory: [mem 0xfec00000-0xfec00fff]
[ 0.000000] PM: Registered nosave memory: [mem 0xfec01000-0xfedfffff]
[ 0.000000] PM: Registered nosave memory: [mem 0xfee00000-0xfee00fff]
[ 0.000000] PM: Registered nosave memory: [mem 0xfee01000-0xfffbffff]
[ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff]
[ 0.000000] [mem 0xe0000000-0xfebfffff] available for PCI devices
[ 0.000000] Booting paravirtualized kernel on KVM
[ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 6370452778343963 ns
[ 0.000000] random: get_random_bytes called from start_kernel+0x95/0x535 with crng_init=0
[ 0.000000] setup_percpu: NR_CPUS:320 nr_cpumask_bits:320 nr_cpu_ids:2 nr_node_ids:1
[ 0.000000] percpu: Embedded 46 pages/cpu @(____ptrval____) s151552 r8192 d28672 u1048576
[ 0.000000] pcpu-alloc: s151552 r8192 d28672 u1048576 alloc=1*2097152
[ 0.000000] pcpu-alloc: [0] 0 1
[ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes)
[ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1032057
[ 0.000000] Policy zone: Normal
[ 0.000000] Kernel command line: BOOT_IMAGE=/boot/vmlinuz-linux root=UUID=a83c9650-c8f8-4afe-90a6-4e80156d523d rw quiet
[ 0.000000] Calgary: detecting Calgary via BIOS EBDA area
[ 0.000000] Calgary: Unable to locate Rio Grande table in EBDA - bailing!
[ 0.000000] Memory: 4031204K/4193848K available (10252K kernel code, 1297K rwdata, 3528K rodata, 1492K init, 612K bss, 162644K reserved, 0K cma-reserved)
[ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=1
[ 0.000000] Kernel/User page tables isolation: enabled
[ 0.000000] ftrace: allocating 33395 entries in 131 pages
[ 0.003333] Preemptible hierarchical RCU implementation.
[ 0.003333] CONFIG_RCU_FANOUT set to non-default value of 32
[ 0.003333] RCU dyntick-idle grace-period acceleration is enabled.
[ 0.003333] RCU restricting CPUs from NR_CPUS=320 to nr_cpu_ids=2.
[ 0.003333] RCU priority boosting: priority 1 delay 500 ms.
[ 0.003333] Tasks RCU enabled.
[ 0.003333] RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=2
[ 0.003333] NR_IRQS: 20736, nr_irqs: 440, preallocated irqs: 16
[ 0.003333] Offload RCU callbacks from CPUs: (none).
[ 0.003333] Console: colour dummy device 80x25
[ 0.003333] console [tty0] enabled
[ 0.003333] ACPI: Core revision 20180531
[ 0.003333] APIC: Switch to symmetric I/O mode setup
[ 0.003333] x2apic enabled
[ 0.003333] Switched APIC routing to physical x2apic.
[ 0.003333] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[ 0.003333] tsc: Detected 2593.992 MHz processor
[ 0.003333] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x25641074d3b, max_idle_ns: 440795244898 ns
[ 0.003333] Calibrating delay loop (skipped) preset value.. 5190.15 BogoMIPS (lpj=8646640)
[ 0.003333] pid_max: default: 32768 minimum: 301
[ 0.003333] Security Framework initialized
[ 0.003333] Yama: becoming mindful.
[ 0.003570] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes)
[ 0.004426] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes)
[ 0.004459] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes)
[ 0.004470] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes)
[ 0.004756] mce: CPU supports 0 MCE banks
[ 0.004773] Last level iTLB entries: 4KB 1024, 2MB 1024, 4MB 1024
[ 0.004774] Last level dTLB entries: 4KB 1024, 2MB 1024, 4MB 1024, 1GB 4
[ 0.004776] Spectre V2 : Mitigation: Full generic retpoline
[ 0.004776] Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch
[ 0.004777] Speculative Store Bypass: Vulnerable
[ 0.004874] Freeing SMP alternatives memory: 28K
[ 0.006666] smpboot: CPU0: Intel(R) Core(TM) i5-4310U CPU @ 2.00GHz (family: 0x6, model: 0x45, stepping: 0x1)
[ 0.023376] Performance Events: unsupported p6 CPU model 69 no PMU driver, software events only.
[ 0.030018] Hierarchical SRCU implementation.
[ 0.044001] NMI watchdog: Perf event create on CPU 0 failed with -2
[ 0.044003] NMI watchdog: Perf NMI watchdog permanently disabled
[ 0.056691] smp: Bringing up secondary CPUs ...
[ 0.096721] x86: Booting SMP configuration:
[ 0.096726] .... node #0, CPUs: #1
[ 0.003333] kvm-clock: cpu 1, msr 1:1fff6041, secondary cpu clock
[ 0.003333] mce: CPU supports 0 MCE banks
[ 0.099496] smp: Brought up 1 node, 2 CPUs
[ 0.099496] smpboot: Max logical packages: 1
[ 0.099496] smpboot: Total of 2 processors activated (10380.30 BogoMIPS)
[ 0.100155] devtmpfs: initialized
[ 0.100155] x86/mm: Memory block size: 128MB
[ 0.100565] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 6370867519511994 ns
[ 0.100565] futex hash table entries: 512 (order: 3, 32768 bytes)
[ 0.100565] pinctrl core: initialized pinctrl subsystem
[ 0.100565] RTC time: 15:48:04, date: 09/06/18
[ 0.100565] NET: Registered protocol family 16
[ 0.100565] audit: initializing netlink subsys (disabled)
[ 0.100565] audit: type=2000 audit(1536248891.398:1): state=initialized audit_enabled=0 res=1
[ 0.100565] cpuidle: using governor ladder
[ 0.100565] cpuidle: using governor menu
[ 0.100565] ACPI: bus type PCI registered
[ 0.100565] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
[ 0.100565] PCI: Using configuration type 1 for base access
[ 0.101195] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
[ 0.101195] ACPI: Added _OSI(Module Device)
[ 0.101195] ACPI: Added _OSI(Processor Device)
[ 0.101195] ACPI: Added _OSI(3.0 _SCP Extensions)
[ 0.101195] ACPI: Added _OSI(Processor Aggregator Device)
[ 0.101195] ACPI: Added _OSI(Linux-Dell-Video)
[ 0.106958] ACPI: 2 ACPI AML tables successfully acquired and loaded
[ 0.111640] ACPI: Interpreter enabled
[ 0.111652] ACPI: (supports S0 S5)
[ 0.111653] ACPI: Using IOAPIC for interrupt routing
[ 0.111886] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[ 0.112007] ACPI: Enabled 2 GPEs in block 00 to 07
[ 0.116829] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[ 0.116833] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI]
[ 0.116851] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI]
[ 0.116859] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge.
[ 0.117159] PCI host bridge to bus 0000:00
[ 0.117161] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window]
[ 0.117163] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window]
[ 0.117164] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
[ 0.117165] pci_bus 0000:00: root bus resource [mem 0xe0000000-0xfdffffff window]
[ 0.117167] pci_bus 0000:00: root bus resource [bus 00-ff]
[ 0.117199] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000
[ 0.118042] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100
[ 0.118603] pci 0000:00:01.1: [8086:7111] type 00 class 0x01018a
[ 0.118932] pci 0000:00:01.1: reg 0x20: [io 0xd000-0xd00f]
[ 0.119062] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7]
[ 0.119063] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6]
[ 0.119064] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177]
[ 0.119065] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376]
[ 0.119506] pci 0000:00:02.0: [80ee:beef] type 00 class 0x030000
[ 0.120267] pci 0000:00:02.0: reg 0x10: [mem 0xe0000000-0xe07fffff pref]
[ 0.141342] pci 0000:00:03.0: [8086:100e] type 00 class 0x020000
[ 0.143476] pci 0000:00:03.0: reg 0x10: [mem 0xf0000000-0xf001ffff]
[ 0.150098] pci 0000:00:03.0: reg 0x18: [io 0xd010-0xd017]
[ 0.160890] pci 0000:00:04.0: [80ee:cafe] type 00 class 0x088000
[ 0.163493] pci 0000:00:04.0: reg 0x10: [io 0xd020-0xd03f]
[ 0.166746] pci 0000:00:04.0: reg 0x14: [mem 0xf0400000-0xf07fffff]
[ 0.170071] pci 0000:00:04.0: reg 0x18: [mem 0xf0800000-0xf0803fff pref]
[ 0.180657] pci 0000:00:05.0: [8086:2415] type 00 class 0x040100
[ 0.180816] pci 0000:00:05.0: reg 0x10: [io 0xd100-0xd1ff]
[ 0.180900] pci 0000:00:05.0: reg 0x14: [io 0xd200-0xd23f]
[ 0.181967] pci 0000:00:07.0: [8086:7113] type 00 class 0x068000
[ 0.183532] pci 0000:00:07.0: quirk: [io 0x4000-0x403f] claimed by PIIX4 ACPI
[ 0.183540] pci 0000:00:07.0: quirk: [io 0x4100-0x410f] claimed by PIIX4 SMB
[ 0.184839] pci 0000:00:0c.0: [8086:1e31] type 00 class 0x0c0330
[ 0.186796] pci 0000:00:0c.0: reg 0x10: [mem 0xf0810000-0xf081ffff]
[ 0.209673] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 9 10 *11)
[ 0.209968] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 9 *10 11)
[ 0.210051] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 *9 10 11)
[ 0.210144] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 9 10 *11)
[ 0.210380] pci 0000:00:02.0: vgaarb: setting as boot VGA device
[ 0.210380] pci 0000:00:02.0: vgaarb: VGA device added: decodes=io+mem,owns=io+mem,locks=none
[ 0.210380] pci 0000:00:02.0: vgaarb: bridge control possible
[ 0.210380] vgaarb: loaded
[ 0.210380] pps_core: LinuxPPS API ver. 1 registered
[ 0.210380] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[ 0.210380] PTP clock support registered
[ 0.210380] EDAC MC: Ver: 3.0.0
[ 0.210399] PCI: Using ACPI for IRQ routing
[ 0.210399] PCI: pci_cache_line_size set to 64 bytes
[ 0.210399] e820: reserve RAM buffer [mem 0x0009fc00-0x0009ffff]
[ 0.210399] e820: reserve RAM buffer [mem 0xdfff0000-0xdfffffff]
[ 0.210399] NetLabel: Initializing
[ 0.210399] NetLabel: domain hash size = 128
[ 0.210399] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO
[ 0.210821] NetLabel: unlabeled traffic allowed by default
[ 0.210867] clocksource: Switched to clocksource kvm-clock
[ 0.221523] VFS: Disk quotas dquot_6.6.0
[ 0.221540] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[ 0.221613] pnp: PnP ACPI init
[ 0.221685] pnp 00:00: Plug and Play ACPI device, IDs PNP0303 (active)
[ 0.221750] pnp 00:01: Plug and Play ACPI device, IDs PNP0f03 (active)
[ 0.222377] pnp: PnP ACPI: found 2 devices
[ 0.232385] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
[ 0.232395] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window]
[ 0.232396] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window]
[ 0.232397] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window]
[ 0.232399] pci_bus 0000:00: resource 7 [mem 0xe0000000-0xfdffffff window]
[ 0.232449] NET: Registered protocol family 2
[ 0.232635] tcp_listen_portaddr_hash hash table entries: 2048 (order: 3, 32768 bytes)
[ 0.232672] TCP established hash table entries: 32768 (order: 6, 262144 bytes)
[ 0.232753] TCP bind hash table entries: 32768 (order: 7, 524288 bytes)
[ 0.232827] TCP: Hash tables configured (established 32768 bind 32768)
[ 0.232863] UDP hash table entries: 2048 (order: 4, 65536 bytes)
[ 0.232878] UDP-Lite hash table entries: 2048 (order: 4, 65536 bytes)
[ 0.232931] NET: Registered protocol family 1
[ 0.232939] NET: Registered protocol family 44
[ 0.232945] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
[ 0.232980] pci 0000:00:01.0: Activating ISA DMA hang workarounds
[ 0.233032] pci 0000:00:02.0: Video device with shadowed ROM at [mem 0x000c0000-0x000dffff]
[ 0.234370] PCI: CLS 0 bytes, default 64
[ 0.234409] Unpacking initramfs...
[ 0.338213] Freeing initrd memory: 7556K
[ 0.338223] PCI-DMA: Using software bounce buffering for IO (SWIOTLB)
[ 0.338225] software IO TLB [mem 0xdbff0000-0xdfff0000] (64MB) mapped at [(____ptrval____)-(____ptrval____)]
[ 0.338262] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x25641074d3b, max_idle_ns: 440795244898 ns
[ 0.338303] platform rtc_cmos: registered platform RTC device (no PNP device found)
[ 0.338345] Scanning for low memory corruption every 60 seconds
[ 0.338913] Initialise system trusted keyrings
[ 0.338924] Key type blacklist registered
[ 0.339028] workingset: timestamp_bits=41 max_order=20 bucket_order=0
[ 0.340478] zbud: loaded
[ 0.341015] pstore: using lz4hc compression
[ 0.344288] Key type asymmetric registered
[ 0.344289] Asymmetric key parser 'x509' registered
[ 0.344338] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 245)
[ 0.353464] io scheduler noop registered
[ 0.353466] io scheduler deadline registered
[ 0.353537] io scheduler cfq registered (default)
[ 0.353539] io scheduler mq-deadline registered
[ 0.353540] io scheduler kyber registered
[ 0.353562] io scheduler bfq registered
[ 0.353807] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
[ 0.353898] vesafb: mode is 640x480x32, linelength=2560, pages=0
[ 0.353899] vesafb: scrolling: redraw
[ 0.353900] vesafb: Truecolor: size=8:8:8:8, shift=24:16:8:0
[ 0.353911] vesafb: framebuffer at 0xe0000000, mapped to 0x(____ptrval____), using 1216k, total 1216k
[ 0.355641] Console: switching to colour frame buffer device 80x30
[ 0.356625] fb0: VESA VGA frame buffer device
[ 0.356695] intel_idle: Please enable MWAIT in BIOS SETUP
[ 0.356790] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
[ 0.356822] ACPI: Power Button [PWRF]
[ 0.357042] input: Sleep Button as /devices/LNXSYSTM:00/LNXSLPBN:00/input/input1
[ 0.357054] ACPI: Sleep Button [SLPF]
[ 0.357286] ACPI: Video Device [GFX0] (multi-head: yes rom: no post: no)
[ 0.357382] input: Video Bus as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A03:00/LNXVIDEO:00/input/input2
[ 0.359419] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[ 0.369028] ledtrig-cpu: registered to indicate activity on CPUs
[ 0.369586] NET: Registered protocol family 10
[ 0.375703] Segment Routing with IPv6
[ 0.375741] NET: Registered protocol family 17
[ 0.376325] RAS: Correctable Errors collector initialized.
[ 0.376337] sched_clock: Marking stable (376110511, 0)->(772889041, -396778530)
[ 0.377247] registered taskstats version 1
[ 0.377258] Loading compiled-in X.509 certificates
[ 0.377279] zswap: loaded using pool lzo/zbud
[ 0.382531] Key type big_key registered
[ 0.382765] Magic number: 2:846:840
[ 0.382805] hctosys: unable to open rtc device (rtc0)
[ 0.397622] Freeing unused kernel image memory: 1492K
[ 0.397694] Write protecting the kernel read-only data: 16384k
[ 0.398620] Freeing unused kernel image memory: 2016K
[ 0.398913] Freeing unused kernel image memory: 568K
[ 0.486290] i8042: PNP: PS/2 Controller [PNP0303:PS2K,PNP0f03:PS2M] at 0x60,0x64 irq 1,12
[ 0.509470] serio: i8042 KBD port at 0x60,0x64 irq 1
[ 0.509519] serio: i8042 AUX port at 0x60,0x64 irq 12
[ 0.514588] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input3
[ 0.516109] SCSI subsystem initialized
[ 0.517459] ACPI: bus type USB registered
[ 0.517481] usbcore: registered new interface driver usbfs
[ 0.517490] usbcore: registered new interface driver hub
[ 0.517934] usbcore: registered new device driver usb
[ 0.525643] libata version 3.00 loaded.
[ 0.526568] ata_piix 0000:00:01.1: version 2.13
[ 0.526918] xhci_hcd 0000:00:0c.0: xHCI Host Controller
[ 0.526924] xhci_hcd 0000:00:0c.0: new USB bus registered, assigned bus number 1
[ 0.626802] scsi host0: ata_piix
[ 0.627903] xhci_hcd 0000:00:0c.0: hcc params 0x04000000 hci version 0x100 quirks 0x000000000000b930
[ 0.628808] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.18
[ 0.628812] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 0.628815] usb usb1: Product: xHCI Host Controller
[ 0.628817] usb usb1: Manufacturer: Linux 4.18.5-arch1-1-ARCH xhci-hcd
[ 0.628820] usb usb1: SerialNumber: 0000:00:0c.0
[ 0.629055] hub 1-0:1.0: USB hub found
[ 0.629119] hub 1-0:1.0: 8 ports detected
[ 0.629706] xhci_hcd 0000:00:0c.0: xHCI Host Controller
[ 0.629713] xhci_hcd 0000:00:0c.0: new USB bus registered, assigned bus number 2
[ 0.629719] xhci_hcd 0000:00:0c.0: Host supports USB 3.0 SuperSpeed
[ 0.630001] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 4.18
[ 0.630005] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 0.630007] usb usb2: Product: xHCI Host Controller
[ 0.630010] usb usb2: Manufacturer: Linux 4.18.5-arch1-1-ARCH xhci-hcd
[ 0.630013] usb usb2: SerialNumber: 0000:00:0c.0
[ 0.630263] hub 2-0:1.0: USB hub found
[ 0.630313] hub 2-0:1.0: 6 ports detected
[ 0.633536] scsi host1: ata_piix
[ 0.633660] ata1: PATA max UDMA/33 cmd 0x1f0 ctl 0x3f6 bmdma 0xd000 irq 14
[ 0.633665] ata2: PATA max UDMA/33 cmd 0x170 ctl 0x376 bmdma 0xd008 irq 15
[ 0.790468] ata1.01: NODEV after polling detection
[ 0.790776] ata1.00: ATA-6: VBOX HARDDISK, 1.0, max UDMA/133
[ 0.790780] ata1.00: 41943040 sectors, multi 128: LBA
[ 0.791653] scsi 0:0:0:0: Direct-Access ATA VBOX HARDDISK 1.0 PQ: 0 ANSI: 5
[ 0.804543] sd 0:0:0:0: [sda] 41943040 512-byte logical blocks: (21.5 GB/20.0 GiB)
[ 0.804558] sd 0:0:0:0: [sda] Write Protect is off
[ 0.804561] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[ 0.804580] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 0.805903] sda: sda1 sda2
[ 0.806370] sd 0:0:0:0: [sda] Attached SCSI disk
[ 0.883392] raid6: sse2x1 gen() 9369 MB/s
[ 0.940060] raid6: sse2x1 xor() 7066 MB/s
[ 0.960277] usb 2-1: new SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 0.978338] usb 2-1: New USB device found, idVendor=152d, idProduct=0539, bcdDevice= 2.06
[ 0.978341] usb 2-1: New USB device strings: Mfr=10, Product=11, SerialNumber=3
[ 0.978342] usb 2-1: Product: External USB 3.0
[ 0.978343] usb 2-1: Manufacturer: Intenso
[ 0.978345] usb 2-1: SerialNumber: 20120625001B2
[ 0.982736] usb-storage 2-1:1.0: USB Mass Storage device detected
[ 0.986797] usb-storage 2-1:1.0: Quirks match for vid 152d pid 0539: 4000000
[ 0.986831] scsi host2: usb-storage 2-1:1.0
[ 0.987178] usbcore: registered new interface driver usb-storage
[ 0.987994] usbcore: registered new interface driver uas
[ 0.996720] raid6: sse2x2 gen() 11082 MB/s
[ 1.053395] raid6: sse2x2 xor() 7743 MB/s
[ 1.110074] raid6: sse2x4 gen() 14245 MB/s
[ 1.173589] raid6: sse2x4 xor() 9852 MB/s
[ 1.255531] raid6: avx2x1 gen() 24111 MB/s
[ 1.317747] raid6: avx2x1 xor() 13086 MB/s
[ 1.383351] raid6: avx2x2 gen() 24755 MB/s
[ 1.447826] raid6: avx2x2 xor() 13015 MB/s
[ 1.504458] raid6: avx2x4 gen() 24140 MB/s
[ 1.560095] raid6: avx2x4 xor() 11681 MB/s
[ 1.560098] raid6: using algorithm avx2x2 gen() 24755 MB/s
[ 1.560099] raid6: .... xor() 13015 MB/s, rmw enabled
[ 1.560101] raid6: using avx2x2 recovery algorithm
[ 1.563834] xor: automatically using best checksumming function avx
[ 1.592832] Btrfs loaded, crc32c=crc32c-intel
[ 1.593655] BTRFS: device label rootfs devid 1 transid 462 /dev/sda2
[ 1.628696] BTRFS info (device sda2): disk space caching is enabled
[ 1.628698] BTRFS info (device sda2): has skinny extents
[ 1.744316] random: fast init done
[ 1.819501] systemd[1]: systemd 239 running in system mode. (+PAM -AUDIT -SELINUX -IMA -APPARMOR +SMACK -SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN +PCRE2 default-hierarchy=hybrid)
[ 1.819526] systemd[1]: Detected virtualization oracle.
[ 1.819532] systemd[1]: Detected architecture x86-64.
[ 1.824972] systemd[1]: Set hostname to <archlinux>.
[ 1.928707] random: systemd: uninitialized urandom read (16 bytes read)
[ 1.928773] systemd[1]: Listening on Journal Audit Socket.
[ 1.928827] random: systemd: uninitialized urandom read (16 bytes read)
[ 1.928834] systemd[1]: Reached target Remote File Systems.
[ 1.928840] random: systemd: uninitialized urandom read (16 bytes read)
[ 1.928903] systemd[1]: Listening on Journal Socket (/dev/log).
[ 1.929292] systemd[1]: Listening on udev Control Socket.
[ 1.929367] systemd[1]: Listening on Journal Socket.
[ 1.931671] systemd[1]: Mounting Huge Pages File System...
[ 1.997814] scsi 2:0:0:0: Direct-Access Intenso External USB 3.0 0206 PQ: 0 ANSI: 6
[ 1.999676] sd 2:0:0:0: [sdb] 1953523712 512-byte logical blocks: (1.00 TB/932 GiB)
[ 2.000887] sd 2:0:0:0: [sdb] Write Protect is off
[ 2.000890] sd 2:0:0:0: [sdb] Mode Sense: 27 00 00 00
[ 2.001756] sd 2:0:0:0: [sdb] No Caching mode page found
[ 2.001873] sd 2:0:0:0: [sdb] Assuming drive cache: write through
[ 2.004627] sdb: sdb1 sdb2
[ 2.004730] sdb: p2 size 19914992 extends beyond EOD, enabling native capacity
[ 2.009831] sdb: sdb1 sdb2
[ 2.010503] sdb: p2 size 19914992 extends beyond EOD, truncated
[ 2.018523] sd 2:0:0:0: [sdb] Attached SCSI disk
[ 2.042042] BTRFS info (device sda2): disk space caching is enabled
[ 2.080132] systemd-journald[201]: Received request to flush runtime journal from PID 1
[ 2.249713] ACPI: AC Adapter [AC] (on-line)
[ 2.288169] ACPI: Battery Slot [BAT0] (battery present)
[ 2.301989] vboxguest: host-version: 5.2.18r123745 0x1
[ 2.302808] vbg_heartbeat_init: Setting up heartbeat to trigger every 2000 milliseconds
[ 2.302929] input: VirtualBox mouse integration as /devices/pci0000:00/0000:00:04.0/input/input5
[ 2.303794] vboxguest: misc device minor 57, IRQ 20, I/O port d020, MMIO at 0x00000000f0400000 (size 0x0000000000400000)
[ 2.312124] Linux agpgart interface v0.103
[ 2.344296] input: PC Speaker as /devices/platform/pcspkr/input/input6
[ 2.345557] piix4_smbus 0000:00:07.0: SMBus Host Controller at 0x4100, revision 0
[ 2.356878] RAPL PMU: API unit is 2^-32 Joules, 4 fixed counters, 10737418240 ms ovfl timer
[ 2.356880] RAPL PMU: hw unit of domain pp0-core 2^-0 Joules
[ 2.356881] RAPL PMU: hw unit of domain package 2^-0 Joules
[ 2.356881] RAPL PMU: hw unit of domain dram 2^-0 Joules
[ 2.356882] RAPL PMU: hw unit of domain pp1-gpu 2^-0 Joules
[ 2.358252] rtc_cmos rtc_cmos: registered as rtc0
[ 2.358271] rtc_cmos rtc_cmos: alarms up to one day, 114 bytes nvram
[ 2.422191] mousedev: PS/2 mouse device common for all mice
[ 2.469829] cryptd: max_cpu_qlen set to 1000
[ 2.471599] e1000: Intel(R) PRO/1000 Network Driver - version 7.3.21-k8-NAPI
[ 2.471601] e1000: Copyright (c) 1999-2006 Intel Corporation.
[ 2.480494] Adding 2024444k swap on /dev/sda1. Priority:-2 extents:1 across:2024444k FS
[ 2.494788] AVX2 version of gcm_enc/dec engaged.
[ 2.494790] AES CTR mode by8 optimization enabled
[ 2.503205] vboxvideo: module is from the staging directory, the quality is unknown, you have been warned.
[ 2.505559] [drm] VRAM 00800000
[ 2.509449] [TTM] Zone kernel: Available graphics memory: 2021432 kiB
[ 2.509451] [TTM] Initializing pool allocator
[ 2.509454] [TTM] Initializing DMA pool allocator
[ 2.513382] checking generic (e0000000 130000) vs hw (e0000000 800000)
[ 2.513383] fb: switching to vboxdrmfb from VESA VGA
[ 2.513403] Console: switching to colour dummy device 80x25
[ 2.513907] fbcon: vboxdrmfb (fb0) is primary device
[ 2.514513] Console: switching to colour frame buffer device 100x37
[ 2.515572] vboxvideo 0000:00:02.0: fb0: vboxdrmfb frame buffer device
[ 2.530138] [drm] Initialized vboxvideo 1.0.0 20130823 for 0000:00:02.0 on minor 0
[ 2.578072] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input7
[ 2.704296] BTRFS: device label intenso_white devid 1 transid 4791 /dev/sdb1
[ 3.122044] e1000 0000:00:03.0 eth0: (PCI:33MHz:32-bit) 08:00:27:b4:cd:7d
[ 3.122052] e1000 0000:00:03.0 eth0: Intel(R) PRO/1000 Network Connection
[ 3.150681] snd_intel8x0 0000:00:05.0: intel8x0_measure_ac97_clock: measured 59724 usecs (13312 samples)
[ 3.150684] snd_intel8x0 0000:00:05.0: measured clock 222891 rejected
[ 3.154776] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 3.231789] vboxsf: loading out-of-tree module taints kernel.
[ 3.399563] random: crng init done
[ 3.399564] random: 7 urandom warning(s) missed due to ratelimiting
[ 3.527715] snd_intel8x0 0000:00:05.0: intel8x0_measure_ac97_clock: measured 55413 usecs (13312 samples)
[ 3.527719] snd_intel8x0 0000:00:05.0: measured clock 240232 rejected
[ 3.935298] snd_intel8x0 0000:00:05.0: intel8x0_measure_ac97_clock: measured 57301 usecs (12288 samples)
[ 3.935303] snd_intel8x0 0000:00:05.0: measured clock 214446 rejected
[ 3.935305] snd_intel8x0 0000:00:05.0: clocking to 48000
[ 5.270127] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
[ 5.270996] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[ 10.639523] audit: type=1006 audit(1536248901.077:2): pid=305 uid=0 old-auid=4294967295 auid=1000 tty=(none) old-ses=4294967295 ses=1 res=1
[ 10.669563] audit: type=1006 audit(1536248901.107:3): pid=308 uid=0 old-auid=4294967295 auid=1000 tty=(none) old-ses=4294967295 ses=2 res=1
[ 35.191243] audit: type=1006 audit(1536248925.619:4): pid=487 uid=0 old-auid=4294967295 auid=1000 tty=(none) old-ses=4294967295 ses=3 res=1
[ 35.216098] audit: type=1006 audit(1536248925.646:5): pid=490 uid=0 old-auid=4294967295 auid=1000 tty=(none) old-ses=4294967295 ses=4 res=1
[ 66.009078] BTRFS info (device sdb1): disk space caching is enabled
[ 66.009082] BTRFS info (device sdb1): has skinny extents
[ 114.645853] audit: type=1006 audit(1536249005.057:6): pid=532 uid=0 old-auid=4294967295 auid=1000 tty=(none) old-ses=4294967295 ses=5 res=1
[ 185.862211] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 186.074356] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 186.284605] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 186.491055] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 186.680460] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 186.879242] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 186.898756] sd 2:0:0:0: [sdb] tag#0 FAILED Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
[ 186.898762] sd 2:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 15 26 a0 d0 00 08 00 00
[ 186.898764] print_req_error: I/O error, dev sdb, sector 354853072
[ 187.109641] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 187.345245] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 187.657844] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 187.851336] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 188.026882] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 188.215881] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 188.247028] sd 2:0:0:0: [sdb] tag#0 FAILED Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
[ 188.247041] sd 2:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 15 26 a8 d0 00 08 00 00
[ 188.247048] print_req_error: I/O error, dev sdb, sector 354855120
[ 188.247221] BTRFS error (device sdb1): bdev /dev/sdb1 errs: wr 0, rd 1, flush 0, corrupt 0, gen 0
[ 188.255311] xhci_hcd 0000:00:0c.0: WARN: HC couldn't access mem fast enough for slot 1 ep 2
[ 188.413306] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 188.597731] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 188.775025] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 188.937851] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 189.108001] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 189.331634] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 189.350312] sd 2:0:0:0: [sdb] tag#0 FAILED Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
[ 189.350315] sd 2:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 15 26 b0 d0 00 01 c0 00
[ 189.350318] print_req_error: I/O error, dev sdb, sector 354857168
[ 189.350360] BTRFS error (device sdb1): bdev /dev/sdb1 errs: wr 0, rd 2, flush 0, corrupt 0, gen 0
[ 189.504163] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 189.712556] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 200.694085] audit: type=1006 audit(1536249091.095:7): pid=542 uid=0 old-auid=4294967295 auid=1000 tty=(none) old-ses=4294967295 ses=6 res=1
[ 221.883915] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 326.168580] audit: type=1006 audit(1536249216.567:8): pid=554 uid=0 old-auid=4294967295 auid=1000 tty=(none) old-ses=4294967295 ses=7 res=1
[ 368.371741] INFO: task btrfs:540 blocked for more than 120 seconds.
[ 368.371901] Tainted: G C O 4.18.5-arch1-1-ARCH #1
[ 368.372027] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 368.372179] btrfs D 0 540 539 0x80000080
[ 368.372193] Call Trace:
[ 368.372221] ? __schedule+0x29b/0x8b0
[ 368.372318] ? btrfs_bio_counter_sub+0x1e/0x50 [btrfs]
[ 368.372331] schedule+0x32/0x90
[ 368.372347] io_schedule+0x12/0x40
[ 368.372361] __lock_page+0xf9/0x140
[ 368.372375] ? add_to_page_cache_lru+0xe0/0xe0
[ 368.372458] send_extent_data+0x503/0x600 [btrfs]
[ 368.372547] process_extent+0x26f/0xb90 [btrfs]
[ 368.372616] ? __record_deleted_ref+0x20/0x20 [btrfs]
[ 368.372684] changed_cb+0xb17/0xd30 [btrfs]
[ 368.372739] ? btrfs_next_old_leaf+0x1ca/0x420 [btrfs]
[ 368.372794] btrfs_ioctl_send+0xf6d/0x1060 [btrfs]
[ 368.372806] ? kmem_cache_alloc_trace+0x181/0x1d0
[ 368.372849] ? btrfs_opendir+0x3e/0x70 [btrfs]
[ 368.372901] _btrfs_ioctl_send+0xdd/0x110 [btrfs]
[ 368.372912] ? task_change_group_fair+0xb3/0x100
[ 368.372921] ? _raw_spin_unlock_irqrestore+0x20/0x40
[ 368.372928] ? cpu_cgroup_fork+0x64/0x80
[ 368.372977] btrfs_ioctl+0x1145/0x2d00 [btrfs]
[ 368.372984] ? enqueue_entity+0x3d0/0xc20
[ 368.372991] ? __update_load_avg_se.isra.4+0x1f2/0x200
[ 368.373000] ? do_vfs_ioctl+0xa4/0x620
[ 368.373005] do_vfs_ioctl+0xa4/0x620
[ 368.373014] ? syscall_slow_exit_work+0x19b/0x1b0
[ 368.373021] ksys_ioctl+0x60/0x90
[ 368.373028] __x64_sys_ioctl+0x16/0x20
[ 368.373034] do_syscall_64+0x5b/0x170
[ 368.373043] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 368.373050] RIP: 0033:0x7f5fc276179b
[ 368.373051] Code: Bad RIP value.
[ 368.373069] RSP: 002b:00007ffeef93b958 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 368.373075] RAX: ffffffffffffffda RBX: 00007ffeef93de00 RCX: 00007f5fc276179b
[ 368.373078] RDX: 00007ffeef93ba50 RSI: 0000000040489426 RDI: 0000000000000004
[ 368.373081] RBP: 0000000000000004 R08: 00007ffeef93ba50 R09: 00007f5fc266b700
[ 368.373084] R10: 00007f5fc266b9d0 R11: 0000000000000246 R12: 0000000000000001
[ 368.373087] R13: 0000555c74d3b260 R14: 0000000000000000 R15: 00007ffeef93cbf8
[ 368.373098] INFO: task ls:551 blocked for more than 120 seconds.
[ 368.373165] Tainted: G C O 4.18.5-arch1-1-ARCH #1
[ 368.373228] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 368.373303] ls D 0 551 545 0x00000080
[ 368.373310] Call Trace:
[ 368.373319] ? __schedule+0x29b/0x8b0
[ 368.373353] ? percpu_counter_add_batch+0x84/0xb0
[ 368.373360] schedule+0x32/0x90
[ 368.373367] io_schedule+0x12/0x40
[ 368.373375] wait_on_page_bit+0xea/0x130
[ 368.373383] ? add_to_page_cache_lru+0xe0/0xe0
[ 368.373436] read_extent_buffer_pages+0x2b0/0x2d0 [btrfs]
[ 368.373480] btree_read_extent_buffer_pages+0xb6/0x200 [btrfs]
[ 368.373526] read_tree_block+0x51/0x70 [btrfs]
[ 368.373567] read_block_for_search.isra.15+0x18e/0x340 [btrfs]
[ 368.373623] btrfs_search_slot+0x45e/0xa00 [btrfs]
[ 368.373686] btrfs_lookup_inode+0x3a/0xc0 [btrfs]
[ 368.373697] ? kmem_cache_alloc+0x179/0x1d0
[ 368.373749] btrfs_iget+0x113/0x690 [btrfs]
[ 368.373797] btrfs_lookup_dentry+0x3e2/0x4b0 [btrfs]
[ 368.373995] btrfs_lookup+0xe/0x30 [btrfs]
[ 368.374013] __lookup_slow+0x97/0x160
[ 368.374026] lookup_slow+0x35/0x50
[ 368.374034] walk_component+0x1bd/0x2d0
[ 368.374044] path_lookupat.isra.11+0x75/0x200
[ 368.374054] filename_lookup.part.19+0xa0/0x170
[ 368.374063] ? preempt_count_add+0x68/0xa0
[ 368.374075] ? __check_object_size+0xfb/0x180
[ 368.374084] ? strncpy_from_user+0x4a/0x160
[ 368.374095] vfs_statx+0x73/0xe0
[ 368.374106] ? __audit_syscall_exit+0x22a/0x290
[ 368.374115] __se_sys_newlstat+0x3e/0x70
[ 368.374125] ? syscall_trace_enter+0x1d3/0x2d0
[ 368.374137] do_syscall_64+0x5b/0x170
[ 368.374148] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 368.374156] RIP: 0033:0x7fba592ffdd9
[ 368.374158] Code: Bad RIP value.
[ 368.374174] RSP: 002b:00007ffed6ec54b8 EFLAGS: 00000246 ORIG_RAX: 0000000000000006
[ 368.374180] RAX: ffffffffffffffda RBX: 0000560b2c69d218 RCX: 00007fba592ffdd9
[ 368.374183] RDX: 0000560b2c69d230 RSI: 0000560b2c69d230 RDI: 00007ffed6ec54c0
[ 368.374186] RBP: 00007ffed6ec5890 R08: 0000000000000000 R09: 0000560b2c6a203e
[ 368.374189] R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffed6ec54c0
[ 368.374191] R13: 0000000000000000 R14: 0000000000000005 R15: 0000560b2c69d230
[ 491.226820] INFO: task scsi_eh_2:144 blocked for more than 120 seconds.
[ 491.227094] Tainted: G C O 4.18.5-arch1-1-ARCH #1
[ 491.227220] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 491.227293] scsi_eh_2 D 0 144 2 0x80000000
[ 491.227300] Call Trace:
[ 491.227319] ? __schedule+0x29b/0x8b0
[ 491.227327] ? __switch_to_asm+0x34/0x70
[ 491.227333] ? __switch_to_asm+0x40/0x70
[ 491.227339] schedule+0x32/0x90
[ 491.227344] schedule_preempt_disabled+0x14/0x20
[ 491.227349] __mutex_lock.isra.0+0x220/0x530
[ 491.227356] ? __switch_to_asm+0x34/0x70
[ 491.227364] ? try_module_get.part.12+0x52/0xf0
[ 491.227376] device_reset+0x1d/0x50 [usb_storage]
[ 491.227396] scsi_eh_ready_devs+0x559/0xb80 [scsi_mod]
[ 491.227405] ? _raw_spin_unlock_irqrestore+0x20/0x40
[ 491.227430] ? __pm_runtime_resume+0x47/0x50
[ 491.227444] ? scsi_try_target_reset+0x90/0x90 [scsi_mod]
[ 491.227457] ? scsi_eh_get_sense+0x1f0/0x1f0 [scsi_mod]
[ 491.227469] scsi_error_handler+0x494/0x5b0 [scsi_mod]
[ 491.227483] ? scsi_eh_get_sense+0x1f0/0x1f0 [scsi_mod]
[ 491.227492] kthread+0x112/0x130
[ 491.227499] ? kthread_flush_work_fn+0x10/0x10
[ 491.227506] ret_from_fork+0x35/0x40
[ 491.227534] INFO: task btrfs-transacti:531 blocked for more than 120 seconds.
[ 491.227599] Tainted: G C O 4.18.5-arch1-1-ARCH #1
[ 491.227655] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 491.227722] btrfs-transacti D 0 531 2 0x80000080
[ 491.227727] Call Trace:
[ 491.227735] ? __schedule+0x29b/0x8b0
[ 491.227741] ? preempt_count_add+0x68/0xa0
[ 491.227746] schedule+0x32/0x90
[ 491.227806] btrfs_tree_lock+0xd1/0x1f0 [btrfs]
[ 491.227814] ? wait_woken+0x80/0x80
[ 491.227845] btrfs_lock_root_node+0x2f/0x40 [btrfs]
[ 491.227876] btrfs_search_slot+0x170/0xa00 [btrfs]
[ 491.227883] ? __switch_to_asm+0x34/0x70
[ 491.227891] ? ktime_get+0x36/0xa0
[ 491.227928] btrfs_lookup_inode+0x3a/0xc0 [btrfs]
[ 491.227974] ? btrfs_delete_delayed_items+0x1d2/0x350 [btrfs]
[ 491.228019] __btrfs_update_delayed_inode+0x75/0x220 [btrfs]
[ 491.228075] __btrfs_run_delayed_items+0x141/0x1d0 [btrfs]
[ 491.228113] btrfs_commit_transaction+0x18a/0x8a0 [btrfs]
[ 491.228160] ? start_transaction+0x9c/0x3f0 [btrfs]
[ 491.228209] transaction_kthread+0x13f/0x170 [btrfs]
[ 491.228258] ? btrfs_cleanup_transaction+0x560/0x560 [btrfs]
[ 491.228266] kthread+0x112/0x130
[ 491.228273] ? kthread_flush_work_fn+0x10/0x10
[ 491.228281] ret_from_fork+0x35/0x40
[ 491.228292] INFO: task btrfs:540 blocked for more than 120 seconds.
[ 491.228359] Tainted: G C O 4.18.5-arch1-1-ARCH #1
[ 491.228409] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 491.228470] btrfs D 0 540 539 0x80000080
[ 491.228475] Call Trace:
[ 491.228481] ? __schedule+0x29b/0x8b0
[ 491.228521] ? btrfs_bio_counter_sub+0x1e/0x50 [btrfs]
[ 491.228527] schedule+0x32/0x90
[ 491.228533] io_schedule+0x12/0x40
[ 491.228541] __lock_page+0xf9/0x140
[ 491.228547] ? add_to_page_cache_lru+0xe0/0xe0
[ 491.228586] send_extent_data+0x503/0x600 [btrfs]
[ 491.228628] process_extent+0x26f/0xb90 [btrfs]
[ 491.228667] ? __record_deleted_ref+0x20/0x20 [btrfs]
[ 491.228704] changed_cb+0xb17/0xd30 [btrfs]
[ 491.228733] ? btrfs_next_old_leaf+0x1ca/0x420 [btrfs]
[ 491.228770] btrfs_ioctl_send+0xf6d/0x1060 [btrfs]
[ 491.228779] ? kmem_cache_alloc_trace+0x181/0x1d0
[ 491.228813] ? btrfs_opendir+0x3e/0x70 [btrfs]
[ 491.228853] _btrfs_ioctl_send+0xdd/0x110 [btrfs]
[ 491.228860] ? task_change_group_fair+0xb3/0x100
[ 491.228865] ? _raw_spin_unlock_irqrestore+0x20/0x40
[ 491.228870] ? cpu_cgroup_fork+0x64/0x80
[ 491.228909] btrfs_ioctl+0x1145/0x2d00 [btrfs]
[ 491.228915] ? enqueue_entity+0x3d0/0xc20
[ 491.228920] ? __update_load_avg_se.isra.4+0x1f2/0x200
[ 491.228928] ? do_vfs_ioctl+0xa4/0x620
[ 491.228932] do_vfs_ioctl+0xa4/0x620
[ 491.228938] ? syscall_slow_exit_work+0x19b/0x1b0
[ 491.228944] ksys_ioctl+0x60/0x90
[ 491.228949] __x64_sys_ioctl+0x16/0x20
[ 491.228954] do_syscall_64+0x5b/0x170
[ 491.228961] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 491.228966] RIP: 0033:0x7f5fc276179b
[ 491.228967] Code: Bad RIP value.
[ 491.228982] RSP: 002b:00007ffeef93b958 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 491.228998] RAX: ffffffffffffffda RBX: 00007ffeef93de00 RCX: 00007f5fc276179b
[ 491.229001] RDX: 00007ffeef93ba50 RSI: 0000000040489426 RDI: 0000000000000004
[ 491.229004] RBP: 0000000000000004 R08: 00007ffeef93ba50 R09: 00007f5fc266b700
[ 491.229006] R10: 00007f5fc266b9d0 R11: 0000000000000246 R12: 0000000000000001
[ 491.229008] R13: 0000555c74d3b260 R14: 0000000000000000 R15: 00007ffeef93cbf8
[ 491.229018] INFO: task ls:551 blocked for more than 120 seconds.
[ 491.229068] Tainted: G C O 4.18.5-arch1-1-ARCH #1
[ 491.229117] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 491.229178] ls D 0 551 545 0x00000080
[ 491.229182] Call Trace:
[ 491.229189] ? __schedule+0x29b/0x8b0
[ 491.229196] ? percpu_counter_add_batch+0x84/0xb0
[ 491.229201] schedule+0x32/0x90
[ 491.229207] io_schedule+0x12/0x40
[ 491.229213] wait_on_page_bit+0xea/0x130
[ 491.229219] ? add_to_page_cache_lru+0xe0/0xe0
[ 491.229261] read_extent_buffer_pages+0x2b0/0x2d0 [btrfs]
[ 491.229296] btree_read_extent_buffer_pages+0xb6/0x200 [btrfs]
[ 491.229331] read_tree_block+0x51/0x70 [btrfs]
[ 491.229359] read_block_for_search.isra.15+0x18e/0x340 [btrfs]
[ 491.229389] btrfs_search_slot+0x45e/0xa00 [btrfs]
[ 491.229422] btrfs_lookup_inode+0x3a/0xc0 [btrfs]
[ 491.229429] ? kmem_cache_alloc+0x179/0x1d0
[ 491.229465] btrfs_iget+0x113/0x690 [btrfs]
[ 491.229502] btrfs_lookup_dentry+0x3e2/0x4b0 [btrfs]
[ 491.229540] btrfs_lookup+0xe/0x30 [btrfs]
[ 491.229546] __lookup_slow+0x97/0x160
[ 491.229553] lookup_slow+0x35/0x50
[ 491.229557] walk_component+0x1bd/0x2d0
[ 491.229563] path_lookupat.isra.11+0x75/0x200
[ 491.229568] filename_lookup.part.19+0xa0/0x170
[ 491.229573] ? preempt_count_add+0x68/0xa0
[ 491.229578] ? __check_object_size+0xfb/0x180
[ 491.229584] ? strncpy_from_user+0x4a/0x160
[ 491.229590] vfs_statx+0x73/0xe0
[ 491.229595] ? __audit_syscall_exit+0x22a/0x290
[ 491.229600] __se_sys_newlstat+0x3e/0x70
[ 491.229607] ? syscall_trace_enter+0x1d3/0x2d0
[ 491.229613] do_syscall_64+0x5b/0x170
[ 491.229619] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 491.229623] RIP: 0033:0x7fba592ffdd9
[ 491.229624] Code: Bad RIP value.
[ 491.229631] RSP: 002b:00007ffed6ec54b8 EFLAGS: 00000246 ORIG_RAX: 0000000000000006
[ 491.229636] RAX: ffffffffffffffda RBX: 0000560b2c69d218 RCX: 00007fba592ffdd9
[ 491.229638] RDX: 0000560b2c69d230 RSI: 0000560b2c69d230 RDI: 00007ffed6ec54c0
[ 491.229640] RBP: 00007ffed6ec5890 R08: 0000000000000000 R09: 0000560b2c6a203e
[ 491.229643] R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffed6ec54c0
[ 491.229645] R13: 0000000000000000 R14: 0000000000000005 R15: 0000560b2c69d230
[ 614.095081] INFO: task scsi_eh_2:144 blocked for more than 120 seconds.
[ 614.095184] Tainted: G C O 4.18.5-arch1-1-ARCH #1
[ 614.095248] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 614.095392] scsi_eh_2 D 0 144 2 0x80000000
[ 614.095401] Call Trace:
[ 614.095426] ? __schedule+0x29b/0x8b0
[ 614.095436] ? __switch_to_asm+0x34/0x70
[ 614.095443] ? __switch_to_asm+0x40/0x70
[ 614.095449] schedule+0x32/0x90
[ 614.095456] schedule_preempt_disabled+0x14/0x20
[ 614.095462] __mutex_lock.isra.0+0x220/0x530
[ 614.095469] ? __switch_to_asm+0x34/0x70
[ 614.095481] ? try_module_get.part.12+0x52/0xf0
[ 614.095497] device_reset+0x1d/0x50 [usb_storage]
[ 614.095527] scsi_eh_ready_devs+0x559/0xb80 [scsi_mod]
[ 614.095538] ? _raw_spin_unlock_irqrestore+0x20/0x40
[ 614.095572] ? __pm_runtime_resume+0x47/0x50
[ 614.095589] ? scsi_try_target_reset+0x90/0x90 [scsi_mod]
[ 614.095605] ? scsi_eh_get_sense+0x1f0/0x1f0 [scsi_mod]
[ 614.095620] scsi_error_handler+0x494/0x5b0 [scsi_mod]
[ 614.095637] ? scsi_eh_get_sense+0x1f0/0x1f0 [scsi_mod]
[ 614.095650] kthread+0x112/0x130
[ 614.095659] ? kthread_flush_work_fn+0x10/0x10
[ 614.095667] ret_from_fork+0x35/0x40
[ 614.095705] INFO: task btrfs-transacti:531 blocked for more than 120 seconds.
[ 614.095779] Tainted: G C O 4.18.5-arch1-1-ARCH #1
[ 614.095841] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 614.095917] btrfs-transacti D 0 531 2 0x80000080
[ 614.095923] Call Trace:
[ 614.095932] ? __schedule+0x29b/0x8b0
[ 614.095939] ? preempt_count_add+0x68/0xa0
[ 614.095945] schedule+0x32/0x90
[ 614.096216] btrfs_tree_lock+0xd1/0x1f0 [btrfs]
[ 614.096235] ? wait_woken+0x80/0x80
[ 614.096280] btrfs_lock_root_node+0x2f/0x40 [btrfs]
[ 614.096319] btrfs_search_slot+0x170/0xa00 [btrfs]
[ 614.096328] ? __switch_to_asm+0x34/0x70
[ 614.096336] ? ktime_get+0x36/0xa0
[ 614.096381] btrfs_lookup_inode+0x3a/0xc0 [btrfs]
[ 614.096438] ? btrfs_delete_delayed_items+0x1d2/0x350 [btrfs]
[ 614.096491] __btrfs_update_delayed_inode+0x75/0x220 [btrfs]
[ 614.096546] __btrfs_run_delayed_items+0x141/0x1d0 [btrfs]
[ 614.096594] btrfs_commit_transaction+0x18a/0x8a0 [btrfs]
[ 614.096641] ? start_transaction+0x9c/0x3f0 [btrfs]
[ 614.096686] transaction_kthread+0x13f/0x170 [btrfs]
[ 614.096731] ? btrfs_cleanup_transaction+0x560/0x560 [btrfs]
[ 614.096739] kthread+0x112/0x130
[ 614.096795] ? kthread_flush_work_fn+0x10/0x10
[ 614.096805] ret_from_fork+0x35/0x40
[ 614.096817] INFO: task btrfs:540 blocked for more than 120 seconds.
[ 614.096889] Tainted: G C O 4.18.5-arch1-1-ARCH #1
[ 614.096951] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 614.097027] btrfs D 0 540 539 0x80000080
[ 614.097033] Call Trace:
[ 614.097042] ? __schedule+0x29b/0x8b0
[ 614.097099] ? btrfs_bio_counter_sub+0x1e/0x50 [btrfs]
[ 614.097106] schedule+0x32/0x90
[ 614.097114] io_schedule+0x12/0x40
[ 614.097123] __lock_page+0xf9/0x140
[ 614.097166] ? add_to_page_cache_lru+0xe0/0xe0
[ 614.097223] send_extent_data+0x503/0x600 [btrfs]
[ 614.097277] process_extent+0x26f/0xb90 [btrfs]
[ 614.097325] ? __record_deleted_ref+0x20/0x20 [btrfs]
[ 614.097372] changed_cb+0xb17/0xd30 [btrfs]
[ 614.097408] ? btrfs_next_old_leaf+0x1ca/0x420 [btrfs]
[ 614.097463] btrfs_ioctl_send+0xf6d/0x1060 [btrfs]
[ 614.097478] ? kmem_cache_alloc_trace+0x181/0x1d0
[ 614.097539] ? btrfs_opendir+0x3e/0x70 [btrfs]
[ 614.097605] _btrfs_ioctl_send+0xdd/0x110 [btrfs]
[ 614.097616] ? task_change_group_fair+0xb3/0x100
[ 614.097624] ? _raw_spin_unlock_irqrestore+0x20/0x40
[ 614.097630] ? cpu_cgroup_fork+0x64/0x80
[ 614.097696] btrfs_ioctl+0x1145/0x2d00 [btrfs]
[ 614.097712] ? enqueue_entity+0x3d0/0xc20
[ 614.097720] ? __update_load_avg_se.isra.4+0x1f2/0x200
[ 614.097735] ? do_vfs_ioctl+0xa4/0x620
[ 614.097742] do_vfs_ioctl+0xa4/0x620
[ 614.097754] ? syscall_slow_exit_work+0x19b/0x1b0
[ 614.097764] ksys_ioctl+0x60/0x90
[ 614.097773] __x64_sys_ioctl+0x16/0x20
[ 614.097780] do_syscall_64+0x5b/0x170
[ 614.097789] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 614.097796] RIP: 0033:0x7f5fc276179b
[ 614.097798] Code: Bad RIP value.
[ 614.097816] RSP: 002b:00007ffeef93b958 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 614.097822] RAX: ffffffffffffffda RBX: 00007ffeef93de00 RCX: 00007f5fc276179b
[ 614.097825] RDX: 00007ffeef93ba50 RSI: 0000000040489426 RDI: 0000000000000004
[ 614.097828] RBP: 0000000000000004 R08: 00007ffeef93ba50 R09: 00007f5fc266b700
[ 614.097831] R10: 00007f5fc266b9d0 R11: 0000000000000246 R12: 0000000000000001
[ 614.097834] R13: 0000555c74d3b260 R14: 0000000000000000 R15: 00007ffeef93cbf8
[ 614.097845] INFO: task ls:551 blocked for more than 120 seconds.
[ 614.097913] Tainted: G C O 4.18.5-arch1-1-ARCH #1
[ 614.101076] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 614.103035] ls D 0 551 545 0x00000080
[ 614.103040] Call Trace:
[ 614.103052] ? __schedule+0x29b/0x8b0
[ 614.103057] ? percpu_counter_add_batch+0x84/0xb0
[ 614.103063] schedule+0x32/0x90
[ 614.103068] io_schedule+0x12/0x40
[ 614.103074] wait_on_page_bit+0xea/0x130
[ 614.103079] ? add_to_page_cache_lru+0xe0/0xe0
[ 614.103119] read_extent_buffer_pages+0x2b0/0x2d0 [btrfs]
[ 614.103149] btree_read_extent_buffer_pages+0xb6/0x200 [btrfs]
[ 614.103177] read_tree_block+0x51/0x70 [btrfs]
[ 614.103200] read_block_for_search.isra.15+0x18e/0x340 [btrfs]
[ 614.103225] btrfs_search_slot+0x45e/0xa00 [btrfs]
[ 614.103251] btrfs_lookup_inode+0x3a/0xc0 [btrfs]
[ 614.103256] ? kmem_cache_alloc+0x179/0x1d0
[ 614.103283] btrfs_iget+0x113/0x690 [btrfs]
[ 614.103312] btrfs_lookup_dentry+0x3e2/0x4b0 [btrfs]
[ 614.103339] btrfs_lookup+0xe/0x30 [btrfs]
[ 614.103344] __lookup_slow+0x97/0x160
[ 614.103349] lookup_slow+0x35/0x50
[ 614.103352] walk_component+0x1bd/0x2d0
[ 614.103356] path_lookupat.isra.11+0x75/0x200
[ 614.103360] filename_lookup.part.19+0xa0/0x170
[ 614.103365] ? preempt_count_add+0x68/0xa0
[ 614.103368] ? __check_object_size+0xfb/0x180
[ 614.103372] ? strncpy_from_user+0x4a/0x160
[ 614.103377] vfs_statx+0x73/0xe0
[ 614.103382] ? __audit_syscall_exit+0x22a/0x290
[ 614.103386] __se_sys_newlstat+0x3e/0x70
[ 614.103391] ? syscall_trace_enter+0x1d3/0x2d0
[ 614.103396] do_syscall_64+0x5b/0x170
[ 614.103402] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 614.103406] RIP: 0033:0x7fba592ffdd9
[ 614.103407] Code: Bad RIP value.
[ 614.103415] RSP: 002b:00007ffed6ec54b8 EFLAGS: 00000246 ORIG_RAX: 0000000000000006
[ 614.103419] RAX: ffffffffffffffda RBX: 0000560b2c69d218 RCX: 00007fba592ffdd9
[ 614.103421] RDX: 0000560b2c69d230 RSI: 0000560b2c69d230 RDI: 00007ffed6ec54c0
[ 614.103422] RBP: 00007ffed6ec5890 R08: 0000000000000000 R09: 0000560b2c6a203e
[ 614.103424] R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffed6ec54c0
[ 614.103426] R13: 0000000000000000 R14: 0000000000000005 R15: 0000560b2c69d230
^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: btrfs send hung in pipe_wait
2018-09-06 16:03 ` Stefan Löwen
@ 2018-09-06 18:16 ` Chris Murphy
2018-09-06 18:36 ` Stefan Loewen
0 siblings, 1 reply; 17+ messages in thread
From: Chris Murphy @ 2018-09-06 18:16 UTC (permalink / raw)
To: Stefan Löwen; +Cc: Chris Murphy, Btrfs BTRFS
On Thu, Sep 6, 2018 at 10:03 AM, Stefan Löwen <stefan.loewen@gmail.com> wrote:
> I have one subvolume (rw) and 2 snapshots (ro) of it.
>
> I just tested 'btrfs send <subvol> > /dev/null' and that also shows no IO
> after a while but also no significant CPU usage.
> During this I tried 'ls' on the source subvolume and it hangs as well.
> dmesg has some interesting messages I think (see attached dmesg.log)
>
OK you've got a different problem.
[ 186.898756] sd 2:0:0:0: [sdb] tag#0 FAILED Result:
hostbyte=DID_ERROR driverbyte=DRIVER_OK
[ 186.898762] sd 2:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 15 26 a0 d0
00 08 00 00
[ 186.898764] print_req_error: I/O error, dev sdb, sector 354853072
[ 187.109641] usb 2-1: reset SuperSpeed Gen 1 USB device number 2
using xhci_hcd
[ 187.345245] usb 2-1: reset SuperSpeed Gen 1 USB device number 2
using xhci_hcd
[ 187.657844] usb 2-1: reset SuperSpeed Gen 1 USB device number 2
using xhci_hcd
[ 187.851336] usb 2-1: reset SuperSpeed Gen 1 USB device number 2
using xhci_hcd
[ 188.026882] usb 2-1: reset SuperSpeed Gen 1 USB device number 2
using xhci_hcd
[ 188.215881] usb 2-1: reset SuperSpeed Gen 1 USB device number 2
using xhci_hcd
[ 188.247028] sd 2:0:0:0: [sdb] tag#0 FAILED Result:
hostbyte=DID_ERROR driverbyte=DRIVER_OK
[ 188.247041] sd 2:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 15 26 a8 d0
00 08 00 00
[ 188.247048] print_req_error: I/O error, dev sdb, sector 354855120
This is a read error for a specific sector. So your drive has media
problems. And I think that's the instigating problem here, from which
a bunch of other tasks that depend on one or more reads completing but
never do. But weirdly there also isn't any kind of libata reset. At
least on SATA, by default we see a link reset after a command has not
returned in 30 seconds. That reset would totally clear the drive's
command queue, and then things either can recover or barf. But in your
case, neither happens and it just sits there with hung tasks.
[ 189.350360] BTRFS error (device sdb1): bdev /dev/sdb1 errs: wr 0,
rd 2, flush 0, corrupt 0, gen 0
And that's the last we really see from Btrfs. After that, it's all
just hung task traces and are rather unsurprising to me.
Drives in USB cases add a whole bunch of complicating factors for
troubleshooting and repair. Including often masking the actual logical
and physical sector size, the min and max IO size, alignment offset,
and all kinds of things. They can have all sorts of bugs. And I'm also
not totally certain about the relationship between the usb reset
messages and the bad sector. As far as I know the only way we can get
a sector LBA expressly noted in dmesg along with the failed read(10)
command, is if the drive has reported back to libata that discrete
error with sense information. So I'm accepting that as a reliable
error, rather than it being something like a cable. But the reset
messages could possibly be something else in addition to that.
Anyway, the central issue is sector 354855120 is having problems. I
can't tell from the trace if it's transient or persistent. Maybe if
it's transient, that would explain how you sometimes get send to start
working again briefly but then it reverts to hanging. What do you get
for:
fdisk -l /dev/sdb
smartctl -x /dev/sdb
smartctl -l sct erc /dev/sdb
Those are all read only commands, nothing is written or changed.
--
Chris Murphy
^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: btrfs send hung in pipe_wait
2018-09-06 18:16 ` Chris Murphy
@ 2018-09-06 18:36 ` Stefan Loewen
2018-09-06 19:58 ` Chris Murphy
0 siblings, 1 reply; 17+ messages in thread
From: Stefan Loewen @ 2018-09-06 18:36 UTC (permalink / raw)
To: Chris Murphy; +Cc: Btrfs BTRFS
[-- Attachment #1: Type: text/plain, Size: 3613 bytes --]
Output of the commands is attached.
The broken-sector-theory sounds plausible and is compatible with my new
findings:
I suspected the problem to be in one specific directory, let's call it
"broken_dir".
I created a new subvolume and copied broken_dir over.
- If I copied it with cp --reflink, made a snapshot and tried to
btrfs-send that, it hung
- If I rsynced broken_dir over I could snapshot and btrfs-send without a
problem.
But shouldn't btrfs scrub or check find such errors?
On 9/6/18 8:16 PM, Chris Murphy wrote:
> OK you've got a different problem.
>
> [ 186.898756] sd 2:0:0:0: [sdb] tag#0 FAILED Result:
> hostbyte=DID_ERROR driverbyte=DRIVER_OK
> [ 186.898762] sd 2:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 15 26 a0 d0
> 00 08 00 00
> [ 186.898764] print_req_error: I/O error, dev sdb, sector 354853072
> [ 187.109641] usb 2-1: reset SuperSpeed Gen 1 USB device number 2
> using xhci_hcd
> [ 187.345245] usb 2-1: reset SuperSpeed Gen 1 USB device number 2
> using xhci_hcd
> [ 187.657844] usb 2-1: reset SuperSpeed Gen 1 USB device number 2
> using xhci_hcd
> [ 187.851336] usb 2-1: reset SuperSpeed Gen 1 USB device number 2
> using xhci_hcd
> [ 188.026882] usb 2-1: reset SuperSpeed Gen 1 USB device number 2
> using xhci_hcd
> [ 188.215881] usb 2-1: reset SuperSpeed Gen 1 USB device number 2
> using xhci_hcd
> [ 188.247028] sd 2:0:0:0: [sdb] tag#0 FAILED Result:
> hostbyte=DID_ERROR driverbyte=DRIVER_OK
> [ 188.247041] sd 2:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 15 26 a8 d0
> 00 08 00 00
> [ 188.247048] print_req_error: I/O error, dev sdb, sector 354855120
>
>
> This is a read error for a specific sector. So your drive has media
> problems. And I think that's the instigating problem here, from which
> a bunch of other tasks that depend on one or more reads completing but
> never do. But weirdly there also isn't any kind of libata reset. At
> least on SATA, by default we see a link reset after a command has not
> returned in 30 seconds. That reset would totally clear the drive's
> command queue, and then things either can recover or barf. But in your
> case, neither happens and it just sits there with hung tasks.
>
> [ 189.350360] BTRFS error (device sdb1): bdev /dev/sdb1 errs: wr 0,
> rd 2, flush 0, corrupt 0, gen 0
>
> And that's the last we really see from Btrfs. After that, it's all
> just hung task traces and are rather unsurprising to me.
>
> Drives in USB cases add a whole bunch of complicating factors for
> troubleshooting and repair. Including often masking the actual logical
> and physical sector size, the min and max IO size, alignment offset,
> and all kinds of things. They can have all sorts of bugs. And I'm also
> not totally certain about the relationship between the usb reset
> messages and the bad sector. As far as I know the only way we can get
> a sector LBA expressly noted in dmesg along with the failed read(10)
> command, is if the drive has reported back to libata that discrete
> error with sense information. So I'm accepting that as a reliable
> error, rather than it being something like a cable. But the reset
> messages could possibly be something else in addition to that.
>
> Anyway, the central issue is sector 354855120 is having problems. I
> can't tell from the trace if it's transient or persistent. Maybe if
> it's transient, that would explain how you sometimes get send to start
> working again briefly but then it reverts to hanging. What do you get
> for:
>
> fdisk -l /dev/sdb
> smartctl -x /dev/sdb
> smartctl -l sct erc /dev/sdb
>
> Those are all read only commands, nothing is written or changed.
>
>
>
[-- Attachment #2: output.log --]
[-- Type: text/x-log, Size: 14256 bytes --]
[root@archlinux ~]# fdisk -l /dev/sdb
Disk /dev/sdb: 931.5 GiB, 1000204140544 bytes, 1953523712 sectors
Units: sectors of 1 * 512 = 512 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disklabel type: dos
Disk identifier: 0x1cc21bd2
Device Boot Start End Sectors Size Id Type
/dev/sdb1 2048 1933593750 1933591703 922G 83 Linux
/dev/sdb2 1933610176 1953525167 19914992 9.5G 83 Linux
[root@archlinux ~]# smartctl -x /dev/sdb
smartctl 6.6 2017-11-05 r4594 [x86_64-linux-4.18.5-arch1-1-ARCH] (local build)
Copyright (C) 2002-17, Bruce Allen, Christian Franke, www.smartmontools.org
=== START OF INFORMATION SECTION ===
Model Family: Seagate Samsung SpinPoint M8 (AF)
Device Model: ST1000LM024 HN-M101MBB
Serial Number: S2RXJ9FCB07612
LU WWN Device Id: 5 0004cf 208d24759
Firmware Version: 2AR10002
User Capacity: 1,000,204,886,016 bytes [1.00 TB]
Sector Sizes: 512 bytes logical, 4096 bytes physical
Rotation Rate: 5400 rpm
Form Factor: 2.5 inches
Device is: In smartctl database [for details use: -P show]
ATA Version is: ATA8-ACS T13/1699-D revision 6
SATA Version is: SATA 3.0, 3.0 Gb/s (current: 3.0 Gb/s)
Local Time is: Thu Sep 6 18:23:57 2018 UTC
SMART support is: Available - device has SMART capability.
SMART support is: Enabled
AAM level is: 254 (maximum performance), recommended: 254
APM feature is: Disabled
Rd look-ahead is: Enabled
Write cache is: Enabled
DSN feature is: Unavailable
ATA Security is: Disabled, NOT FROZEN [SEC1]
Wt Cache Reorder: Unknown
=== START OF READ SMART DATA SECTION ===
SMART Status not supported: Incomplete response, ATA output registers missing
SMART overall-health self-assessment test result: PASSED
Warning: This result is based on an Attribute check.
General SMART Values:
Offline data collection status: (0x82) Offline data collection activity
was completed without error.
Auto Offline Data Collection: Enabled.
Self-test execution status: ( 0) The previous self-test routine completed
without error or no self-test has ever
been run.
Total time to complete Offline
data collection: (13560) seconds.
Offline data collection
capabilities: (0x5b) SMART execute Offline immediate.
Auto Offline data collection on/off support.
Suspend Offline collection upon new
command.
Offline surface scan supported.
Self-test supported.
No Conveyance Self-test supported.
Selective Self-test supported.
SMART capabilities: (0x0003) Saves SMART data before entering
power-saving mode.
Supports SMART auto save timer.
Error logging capability: (0x01) Error logging supported.
General Purpose Logging supported.
Short self-test routine
recommended polling time: ( 2) minutes.
Extended self-test routine
recommended polling time: ( 226) minutes.
SCT capabilities: (0x003f) SCT Status supported.
SCT Error Recovery Control supported.
SCT Feature Control supported.
SCT Data Table supported.
SMART Attributes Data Structure revision number: 16
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME FLAGS VALUE WORST THRESH FAIL RAW_VALUE
1 Raw_Read_Error_Rate POSR-K 100 100 051 - 10
2 Throughput_Performance -OS--K 252 252 000 - 0
3 Spin_Up_Time PO---K 086 086 025 - 4463
4 Start_Stop_Count -O--CK 098 098 000 - 2675
5 Reallocated_Sector_Ct PO--CK 252 252 010 - 0
7 Seek_Error_Rate -OSR-K 252 252 051 - 0
8 Seek_Time_Performance --S--K 252 252 015 - 0
9 Power_On_Hours -O--CK 100 100 000 - 339
10 Spin_Retry_Count -O--CK 252 252 051 - 0
11 Calibration_Retry_Count -O--CK 100 100 000 - 8
12 Power_Cycle_Count -O--CK 100 100 000 - 462
191 G-Sense_Error_Rate -O---K 100 100 000 - 13
192 Power-Off_Retract_Count -O---K 252 252 000 - 0
194 Temperature_Celsius -O---- 064 053 000 - 30 (Min/Max 17/51)
195 Hardware_ECC_Recovered -O-RCK 100 100 000 - 0
196 Reallocated_Event_Count -O--CK 252 252 000 - 0
197 Current_Pending_Sector -O--CK 252 252 000 - 0
198 Offline_Uncorrectable ----CK 252 252 000 - 0
199 UDMA_CRC_Error_Count -OS-CK 200 200 000 - 0
200 Multi_Zone_Error_Rate -O-R-K 100 100 000 - 31
223 Load_Retry_Count -O--CK 100 100 000 - 8
225 Load_Cycle_Count -O--CK 100 100 000 - 8580
||||||_ K auto-keep
|||||__ C event count
||||___ R error rate
|||____ S speed/performance
||_____ O updated online
|______ P prefailure warning
General Purpose Log Directory Version 1
SMART Log Directory Version 1 [multi-sector log support]
Address Access R/W Size Description
0x00 GPL,SL R/O 1 Log Directory
0x01 SL R/O 1 Summary SMART error log
0x02 SL R/O 2 Comprehensive SMART error log
0x03 GPL R/O 2 Ext. Comprehensive SMART error log
0x06 SL R/O 1 SMART self-test log
0x07 GPL R/O 2 Extended self-test log
0x08 GPL R/O 2 Power Conditions log
0x09 SL R/W 1 Selective self-test log
0x10 GPL R/O 1 NCQ Command Error log
0x11 GPL R/O 1 SATA Phy Event Counters log
0x80-0x9f GPL,SL R/W 16 Host vendor specific log
0xc0-0xdf GPL,SL VS 16 Device vendor specific log
0xe0 GPL,SL R/W 1 SCT Command/Status
0xe1 GPL,SL R/W 1 SCT Data Transfer
SMART Extended Comprehensive Error Log Version: 1 (2 sectors)
No Errors Logged
SMART Extended Self-test Log Version: 1 (2 sectors)
Num Test_Description Status Remaining LifeTime(hours) LBA_of_first_error
# 1 Short offline Completed without error 00% 264 -
# 2 Short offline Completed without error 00% 264 -
# 3 Extended offline Aborted by host 90% 165 -
SMART Selective self-test log data structure revision number 0
Note: revision number not 1 implies that no selective self-test has ever been run
SPAN MIN_LBA MAX_LBA CURRENT_TEST_STATUS
1 0 0 Completed [00% left] (0-65535)
2 0 0 Not_testing
3 0 0 Not_testing
4 0 0 Not_testing
5 0 0 Not_testing
Selective self-test flags (0x0):
After scanning selected spans, do NOT read-scan remainder of disk.
If Selective self-test is pending on power-up, resume after 0 minute delay.
SCT Status Version: 2
SCT Version (vendor specific): 256 (0x0100)
SCT Support Level: 1
Device State: Active (0)
Current Temperature: 30 Celsius
Power Cycle Min/Max Temperature: 25/31 Celsius
Lifetime Min/Max Temperature: 18/52 Celsius
Under/Over Temperature Limit Count: 0/0
SCT Temperature History Version: 2
Temperature Sampling Period: 5 minutes
Temperature Logging Interval: 5 minutes
Min/Max recommended Temperature: -5/80 Celsius
Min/Max Temperature Limit: -10/85 Celsius
Temperature History Size (Index): 128 (100)
Index Estimated Time Temperature Celsius
101 2018-09-06 07:45 30 ***********
102 2018-09-06 07:50 28 *********
... ..( 2 skipped). .. *********
105 2018-09-06 08:05 28 *********
106 2018-09-06 08:10 31 ************
107 2018-09-06 08:15 33 **************
108 2018-09-06 08:20 34 ***************
109 2018-09-06 08:25 35 ****************
110 2018-09-06 08:30 35 ****************
111 2018-09-06 08:35 35 ****************
112 2018-09-06 08:40 36 *****************
... ..( 7 skipped). .. *****************
120 2018-09-06 09:20 36 *****************
121 2018-09-06 09:25 33 **************
122 2018-09-06 09:30 33 **************
123 2018-09-06 09:35 34 ***************
124 2018-09-06 09:40 35 ****************
125 2018-09-06 09:45 31 ************
126 2018-09-06 09:50 32 *************
127 2018-09-06 09:55 34 ***************
0 2018-09-06 10:00 33 **************
1 2018-09-06 10:05 30 ***********
2 2018-09-06 10:10 33 **************
3 2018-09-06 10:15 30 ***********
4 2018-09-06 10:20 29 **********
5 2018-09-06 10:25 29 **********
6 2018-09-06 10:30 29 **********
7 2018-09-06 10:35 30 ***********
8 2018-09-06 10:40 31 ************
9 2018-09-06 10:45 31 ************
10 2018-09-06 10:50 32 *************
11 2018-09-06 10:55 32 *************
12 2018-09-06 11:00 31 ************
13 2018-09-06 11:05 30 ***********
14 2018-09-06 11:10 29 **********
... ..( 7 skipped). .. **********
22 2018-09-06 11:50 29 **********
23 2018-09-06 11:55 31 ************
24 2018-09-06 12:00 34 ***************
25 2018-09-06 12:05 35 ****************
26 2018-09-06 12:10 37 ******************
27 2018-09-06 12:15 38 *******************
28 2018-09-06 12:20 38 *******************
29 2018-09-06 12:25 39 ********************
... ..( 4 skipped). .. ********************
34 2018-09-06 12:50 39 ********************
35 2018-09-06 12:55 40 *********************
36 2018-09-06 13:00 40 *********************
37 2018-09-06 13:05 40 *********************
38 2018-09-06 13:10 39 ********************
39 2018-09-06 13:15 39 ********************
40 2018-09-06 13:20 39 ********************
41 2018-09-06 13:25 40 *********************
42 2018-09-06 13:30 39 ********************
... ..( 5 skipped). .. ********************
48 2018-09-06 14:00 39 ********************
49 2018-09-06 14:05 37 ******************
50 2018-09-06 14:10 35 ****************
51 2018-09-06 14:15 34 ***************
52 2018-09-06 14:20 31 ************
53 2018-09-06 14:25 28 *********
54 2018-09-06 14:30 31 ************
55 2018-09-06 14:35 34 ***************
56 2018-09-06 14:40 36 *****************
57 2018-09-06 14:45 37 ******************
58 2018-09-06 14:50 38 *******************
59 2018-09-06 14:55 38 *******************
60 2018-09-06 15:00 39 ********************
... ..( 3 skipped). .. ********************
64 2018-09-06 15:20 39 ********************
65 2018-09-06 15:25 40 *********************
66 2018-09-06 15:30 39 ********************
... ..( 7 skipped). .. ********************
74 2018-09-06 16:10 39 ********************
75 2018-09-06 16:15 25 ******
76 2018-09-06 16:20 26 *******
77 2018-09-06 16:25 27 ********
78 2018-09-06 16:30 29 **********
... ..( 2 skipped). .. **********
81 2018-09-06 16:45 29 **********
82 2018-09-06 16:50 27 ********
83 2018-09-06 16:55 27 ********
84 2018-09-06 17:00 26 *******
85 2018-09-06 17:05 27 ********
86 2018-09-06 17:10 27 ********
87 2018-09-06 17:15 26 *******
88 2018-09-06 17:20 26 *******
89 2018-09-06 17:25 26 *******
90 2018-09-06 17:30 28 *********
91 2018-09-06 17:35 27 ********
92 2018-09-06 17:40 27 ********
93 2018-09-06 17:45 29 **********
94 2018-09-06 17:50 30 ***********
95 2018-09-06 17:55 30 ***********
96 2018-09-06 18:00 30 ***********
97 2018-09-06 18:05 31 ************
98 2018-09-06 18:10 31 ************
99 2018-09-06 18:15 31 ************
100 2018-09-06 18:20 30 ***********
SMART WRITE LOG does not return COUNT and LBA_LOW register
SCT (Get) Error Recovery Control command failed
Device Statistics (GP/SMART Log 0x04) not supported
Pending Defects log (GP Log 0x0c) not supported
SATA Phy Event Counters (GP Log 0x11)
ID Size Value Description
0x0001 4 0 Command failed due to ICRC error
0x0002 4 0 R_ERR response for data FIS
0x0003 4 0 R_ERR response for device-to-host data FIS
0x0004 4 0 R_ERR response for host-to-device data FIS
0x0005 4 0 R_ERR response for non-data FIS
0x0006 4 0 R_ERR response for device-to-host non-data FIS
0x0007 4 0 R_ERR response for host-to-device non-data FIS
0x0008 4 0 Device-to-host non-data FIS retries
0x0009 4 13 Transition from drive PhyRdy to drive PhyNRdy
0x000a 4 12 Device-to-host register FISes sent due to a COMRESET
0x000b 4 0 CRC errors within host-to-device FIS
0x000d 4 0 Non-CRC errors within host-to-device FIS
0x000f 4 0 R_ERR response for host-to-device data FIS, CRC
0x0010 4 0 R_ERR response for host-to-device data FIS, non-CRC
0x0012 4 0 R_ERR response for host-to-device non-data FIS, CRC
0x0013 4 0 R_ERR response for host-to-device non-data FIS, non-CRC
0x8e00 4 0 Vendor specific
0x8e01 4 0 Vendor specific
0x8e02 4 0 Vendor specific
0x8e03 4 0 Vendor specific
0x8e04 4 0 Vendor specific
0x8e05 4 0 Vendor specific
0x8e06 4 0 Vendor specific
0x8e07 4 0 Vendor specific
0x8e08 4 0 Vendor specific
0x8e09 4 0 Vendor specific
0x8e0a 4 0 Vendor specific
0x8e0b 4 0 Vendor specific
0x8e0c 4 0 Vendor specific
0x8e0d 4 0 Vendor specific
0x8e0e 4 0 Vendor specific
0x8e0f 4 0 Vendor specific
0x8e10 4 0 Vendor specific
0x8e11 4 0 Vendor specific
[root@archlinux ~]# smartctl -l scterc /dev/sdb
smartctl 6.6 2017-11-05 r4594 [x86_64-linux-4.18.5-arch1-1-ARCH] (local build)
Copyright (C) 2002-17, Bruce Allen, Christian Franke, www.smartmontools.org
SMART WRITE LOG does not return COUNT and LBA_LOW register
SCT (Get) Error Recovery Control command failed
^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: btrfs send hung in pipe_wait
2018-09-06 18:36 ` Stefan Loewen
@ 2018-09-06 19:58 ` Chris Murphy
2018-09-06 20:16 ` Stefan Loewen
0 siblings, 1 reply; 17+ messages in thread
From: Chris Murphy @ 2018-09-06 19:58 UTC (permalink / raw)
To: Stefan Loewen; +Cc: Chris Murphy, Btrfs BTRFS
On Thu, Sep 6, 2018 at 12:36 PM, Stefan Loewen <stefan.loewen@gmail.com> wrote:
> Output of the commands is attached.
fdisk
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
smart
Sector Sizes: 512 bytes logical, 4096 bytes physical
So clearly the case is lying about the actual physical sector size of
the drive. It's very common. But it means to fix the bad sector by
writing to it, must be a 4K write. A 512 byte write to the reported
LBA, will fail because it is a RMW, and the read will fail. So if you
write to that sector, you'll get a read failure. Kinda confusing. So
you can convert the LBA to a 4K value, and use dd to write to that "4K
LBA" using bs=4096 and a count of 1.... but only when you're ready to
lose all 4096 bytes in that sector. If it's data, it's fine. It's the
loss of one file, and scrub will find and report path to file so you
know what was affected.
If it's metadata, it could be a problem. What do you get for 'btrfs fi
us <mountpoint>' for this volume? I'm wondering if DUP metadata is
being used across the board with no single chunks. If so, then you can
zero that sector, and Btrfs will detect the missing metadata in that
chunk on scrub, and fix it up from a copy. But if you only have single
copy metadata, it just depends what's on that block as to how
recoverable or repairable this is.
195 Hardware_ECC_Recovered -O-RCK 100 100 000 - 0
196 Reallocated_Event_Count -O--CK 252 252 000 - 0
197 Current_Pending_Sector -O--CK 252 252 000 - 0
198 Offline_Uncorrectable ----CK 252 252 000 - 0
Interesting, no complaints there. Unexpected.
11 Calibration_Retry_Count -O--CK 100 100 000 - 8
200 Multi_Zone_Error_Rate -O-R-K 100 100 000 - 31
https://kb.acronis.com/content/9136
This is a low hour device, probably still under warranty? I'd get it
swapped out. If you want more ammunition for arguing in favor of a
swap out under warranty you could do
smartctl -t long /dev/sdb
That will take just under 4 hours to run (you can use the drive in the
meantime, but it'll take a bit longer); and then after that
smartctl -x /dev/sdb
And see if it's found a bad sector or updated any of those smart
values for the worse in particular the offline values.
SCT (Get) Error Recovery Control command failed
OK so not configurable, it is whatever it is and we don't know what
that is. Probably one of the really long recoveries.
>
> The broken-sector-theory sounds plausible and is compatible with my new
> findings:
> I suspected the problem to be in one specific directory, let's call it
> "broken_dir".
> I created a new subvolume and copied broken_dir over.
> - If I copied it with cp --reflink, made a snapshot and tried to btrfs-send
> that, it hung
> - If I rsynced broken_dir over I could snapshot and btrfs-send without a
> problem.
Yeah I'm not sure what it is, maybe a data block.
>
> But shouldn't btrfs scrub or check find such errors?
Nope. Btrfs expects the drive to complete the read command, but always
second guesses the content of the read by comparing to checksums. So
if the drive just supplied corrupt data, Btrfs would detect that and
discretely report, and if there's a good copy it would self heal. But
it can't do that because the drive or USB bus also seems to hang in
such a way that a bunch of tasks are also hung, and none of them are
getting a clear pass/fail for the read. It just hangs.
Arguably the device or the link should not hang. So I'm still
wondering if something else is going on, but this is just the most
obvious first problem, and maybe it's being complicated by another
problem we haven't figure out yet. Anyway, once this problem is solve,
it'll become clear if there are additional problems or not.
In my case, I often get usb reset errors when I directly connect USB
3.0 drives to my Intel NUC, but I don't ever get them when plugging
the drive into a dyconn hub. So if you don't already have a hub in
between the drive and the computer, it might be worth considering.
Basically the hub is going to read and completely rewrite the whole
stream that goes through it (in both directions).
--
Chris Murphy
^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: btrfs send hung in pipe_wait
2018-09-06 19:58 ` Chris Murphy
@ 2018-09-06 20:16 ` Stefan Loewen
2018-09-07 3:29 ` Chris Murphy
0 siblings, 1 reply; 17+ messages in thread
From: Stefan Loewen @ 2018-09-06 20:16 UTC (permalink / raw)
To: Chris Murphy; +Cc: Btrfs BTRFS
[root@archlinux @data]# btrfs fi us /mnt/intenso_white/
Overall:
Device size: 911.51GiB
Device allocated: 703.09GiB
Device unallocated: 208.43GiB
Device missing: 0.00B
Used: 658.19GiB
Free (estimated): 249.75GiB (min: 145.53GiB)
Data ratio: 1.00
Metadata ratio: 2.00
Global reserve: 512.00MiB (used: 0.00B)
Data,single: Size:695.01GiB, Used:653.69GiB
/dev/sdb1 695.01GiB
Metadata,DUP: Size:4.00GiB, Used:2.25GiB
/dev/sdb1 8.00GiB
System,DUP: Size:40.00MiB, Used:96.00KiB
/dev/sdb1 80.00MiB
Unallocated:
/dev/sdb1 208.43GiB
Does that mean Metadata is duplicated?
Ok so to summarize and see if I understood you correctly:
There are bad sectors on disk. Running an extended selftest (smartctl -t
long) could find those and replace them with spare sectors.
If it does not I can try calculating the physical (4K) sector number and
write to that to make the drive notice and mark the bad sector.
Is there a way to find out which file I will be writing to beforehand?
Or is it easier to just write to the sector and then wait for scrub to
tell me (and the sector is broken anyways)?
For the drive: Not under warranty anymore. It's an external HDD that I
had lying around for years, mostly unused. Now I wanted to use it as
part of my small DIY NAS.
On 9/6/18 9:58 PM, Chris Murphy wrote:
> On Thu, Sep 6, 2018 at 12:36 PM, Stefan Loewen <stefan.loewen@gmail.com> wrote:
>> Output of the commands is attached.
> fdisk
> Sector size (logical/physical): 512 bytes / 512 bytes
> I/O size (minimum/optimal): 512 bytes / 512 bytes
>
> smart
> Sector Sizes: 512 bytes logical, 4096 bytes physical
>
> So clearly the case is lying about the actual physical sector size of
> the drive. It's very common. But it means to fix the bad sector by
> writing to it, must be a 4K write. A 512 byte write to the reported
> LBA, will fail because it is a RMW, and the read will fail. So if you
> write to that sector, you'll get a read failure. Kinda confusing. So
> you can convert the LBA to a 4K value, and use dd to write to that "4K
> LBA" using bs=4096 and a count of 1.... but only when you're ready to
> lose all 4096 bytes in that sector. If it's data, it's fine. It's the
> loss of one file, and scrub will find and report path to file so you
> know what was affected.
>
> If it's metadata, it could be a problem. What do you get for 'btrfs fi
> us <mountpoint>' for this volume? I'm wondering if DUP metadata is
> being used across the board with no single chunks. If so, then you can
> zero that sector, and Btrfs will detect the missing metadata in that
> chunk on scrub, and fix it up from a copy. But if you only have single
> copy metadata, it just depends what's on that block as to how
> recoverable or repairable this is.
>
>
> 195 Hardware_ECC_Recovered -O-RCK 100 100 000 - 0
> 196 Reallocated_Event_Count -O--CK 252 252 000 - 0
> 197 Current_Pending_Sector -O--CK 252 252 000 - 0
> 198 Offline_Uncorrectable ----CK 252 252 000 - 0
>
> Interesting, no complaints there. Unexpected.
>
> 11 Calibration_Retry_Count -O--CK 100 100 000 - 8
> 200 Multi_Zone_Error_Rate -O-R-K 100 100 000 - 31
>
> https://kb.acronis.com/content/9136
>
> This is a low hour device, probably still under warranty? I'd get it
> swapped out. If you want more ammunition for arguing in favor of a
> swap out under warranty you could do
>
> smartctl -t long /dev/sdb
>
> That will take just under 4 hours to run (you can use the drive in the
> meantime, but it'll take a bit longer); and then after that
>
> smartctl -x /dev/sdb
>
> And see if it's found a bad sector or updated any of those smart
> values for the worse in particular the offline values.
>
>
>
>
> SCT (Get) Error Recovery Control command failed
>
> OK so not configurable, it is whatever it is and we don't know what
> that is. Probably one of the really long recoveries.
>
>
>
>
>> The broken-sector-theory sounds plausible and is compatible with my new
>> findings:
>> I suspected the problem to be in one specific directory, let's call it
>> "broken_dir".
>> I created a new subvolume and copied broken_dir over.
>> - If I copied it with cp --reflink, made a snapshot and tried to btrfs-send
>> that, it hung
>> - If I rsynced broken_dir over I could snapshot and btrfs-send without a
>> problem.
> Yeah I'm not sure what it is, maybe a data block.
>
>> But shouldn't btrfs scrub or check find such errors?
> Nope. Btrfs expects the drive to complete the read command, but always
> second guesses the content of the read by comparing to checksums. So
> if the drive just supplied corrupt data, Btrfs would detect that and
> discretely report, and if there's a good copy it would self heal. But
> it can't do that because the drive or USB bus also seems to hang in
> such a way that a bunch of tasks are also hung, and none of them are
> getting a clear pass/fail for the read. It just hangs.
>
> Arguably the device or the link should not hang. So I'm still
> wondering if something else is going on, but this is just the most
> obvious first problem, and maybe it's being complicated by another
> problem we haven't figure out yet. Anyway, once this problem is solve,
> it'll become clear if there are additional problems or not.
>
> In my case, I often get usb reset errors when I directly connect USB
> 3.0 drives to my Intel NUC, but I don't ever get them when plugging
> the drive into a dyconn hub. So if you don't already have a hub in
> between the drive and the computer, it might be worth considering.
> Basically the hub is going to read and completely rewrite the whole
> stream that goes through it (in both directions).
>
>
>
^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: btrfs send hung in pipe_wait
2018-09-06 20:16 ` Stefan Loewen
@ 2018-09-07 3:29 ` Chris Murphy
2018-09-07 12:47 ` Stefan Loewen
0 siblings, 1 reply; 17+ messages in thread
From: Chris Murphy @ 2018-09-07 3:29 UTC (permalink / raw)
To: Stefan Loewen; +Cc: Chris Murphy, Btrfs BTRFS
On Thu, Sep 6, 2018 at 2:16 PM, Stefan Loewen <stefan.loewen@gmail.com> wrote:
> Data,single: Size:695.01GiB, Used:653.69GiB
> /dev/sdb1 695.01GiB
> Metadata,DUP: Size:4.00GiB, Used:2.25GiB
> /dev/sdb1 8.00GiB
> System,DUP: Size:40.00MiB, Used:96.00KiB
> Does that mean Metadata is duplicated?
Yes. Single copy for data. Duplicate for metadata+system, and there
are no single chunks for metadata/system.
>
> Ok so to summarize and see if I understood you correctly:
> There are bad sectors on disk. Running an extended selftest (smartctl -t
> long) could find those and replace them with spare sectors.
More likely if it finds a persistently failing sector, it will just
record the first failing sector LBA in its log, and then abort. You'll
see this info with 'smartctl -a' or with -x.
It is possible to resume the test using selective option and picking a
4K aligned 512 byte LBA value after the 4K sector with the defect.
Just because only one is reported in dmesg doesn't mean there isn't a
bad one.
It's unlikely the long test is going to actually fix anything, it'll
just give you more ammunition for getting a likely under warranty
device replaced because it really shouldn't have any issues at this
age.
> If it does not I can try calculating the physical (4K) sector number and
> write to that to make the drive notice and mark the bad sector.
> Is there a way to find out which file I will be writing to beforehand?
I'm not sure how to do it easily.
>Or is
> it easier to just write to the sector and then wait for scrub to tell me
> (and the sector is broken anyways)?
If it's a persistent read error, then it's lost. So you might as well
overwrite it. If it's data, scrub will tell you what file is corrupted
(and restore can help you recover the whole file, of course it'll have
a 4K hole of zeros in it). If it's metadata, Btrfs will fix up the 4K
hole with duplicate metadata.
Gotcha is to make certain you've got the right LBA to write to. You
can use dd to test this, by reading the suspect bad sector, and if
you've got the right one, you'll get an I/O error in user space and
dmesg will have a message like before with sector value. Use the dd
skip= flag for reading, but make *sure* you use seek= when writing
*and* make sure you always use bs=4096 count=1 so that if you make a
mistake you limit the damage haha.
>
> For the drive: Not under warranty anymore. It's an external HDD that I had
> lying around for years, mostly unused. Now I wanted to use it as part of my
> small DIY NAS.
Gotcha. Well you can read up on smartctl and smartd, and set it up for
regular extended tests, and keep an eye on rapidly changing values. It
might give you a 50/50 chance of an early heads up before it dies.
I've got an old Hitachi/Apple laptop drive that years ago developed
multiple bad sectors in different zones of the drive. They got
remapped and I haven't had a problem with that drive since. *shrug*
And in fact I did get a discrete error message from the drive for one
of those and Btrfs overwrote that bad sector with a good copy (it's in
a raid1 volume), so working as designed I guess.
Since you didn't get a fix up message from Btrfs, either the whole
thing just got confused with hanging tasks, or it's possible it's a
data block.
--
Chris Murphy
^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: btrfs send hung in pipe_wait
2018-09-07 3:29 ` Chris Murphy
@ 2018-09-07 12:47 ` Stefan Loewen
2018-09-07 15:44 ` Chris Murphy
0 siblings, 1 reply; 17+ messages in thread
From: Stefan Loewen @ 2018-09-07 12:47 UTC (permalink / raw)
To: Chris Murphy; +Cc: Btrfs BTRFS
Well... It seems it's not the hardware.
I ran a long SMART check which ran through without errors and
reallocation count is still 0.
So I used clonezilla (partclone.btrfs) to mirror the drive to another
drive (same model).
Everything copied over just fine. No I/O error im dmesg.
The new disk shows the same behavior.
So I created another subvolume, reflinked stuff over and found that it
is enough to reflink one file, create a read-only snapshot and try to
btrfs-send that. It's not happening with every file, but there are
definitely multiple different files. The one I tested with is a 3.8GB
ISO file.
Even better:
'btrfs send --no-data snap-one > /dev/null'
(snap-one containing just one iso file) hangs as well.
Still dmesg shows no IO errors, only "INFO: task btrfs-transacti:541
blocked for more than 120 seconds." with associated call trace.
btrfs-send reads some MB in the beginning, writes a few bytes and then
hangs without further IO.
copying the same file without --reflink, snapshotting and sending
works without problems.
I guess that pretty much eleminates bad sectors and points towards
some problem with reflinks / btrfs metadata.
Btw.: Thanks for taking that much time for helping me find the problem
here, Chris. Very much appreciated!
Am Fr., 7. Sep. 2018 um 05:29 Uhr schrieb Chris Murphy
<lists@colorremedies.com>:
>
> On Thu, Sep 6, 2018 at 2:16 PM, Stefan Loewen <stefan.loewen@gmail.com> wrote:
>
> > Data,single: Size:695.01GiB, Used:653.69GiB
> > /dev/sdb1 695.01GiB
> > Metadata,DUP: Size:4.00GiB, Used:2.25GiB
> > /dev/sdb1 8.00GiB
> > System,DUP: Size:40.00MiB, Used:96.00KiB
>
>
> > Does that mean Metadata is duplicated?
>
> Yes. Single copy for data. Duplicate for metadata+system, and there
> are no single chunks for metadata/system.
>
> >
> > Ok so to summarize and see if I understood you correctly:
> > There are bad sectors on disk. Running an extended selftest (smartctl -t
> > long) could find those and replace them with spare sectors.
>
> More likely if it finds a persistently failing sector, it will just
> record the first failing sector LBA in its log, and then abort. You'll
> see this info with 'smartctl -a' or with -x.
>
> It is possible to resume the test using selective option and picking a
> 4K aligned 512 byte LBA value after the 4K sector with the defect.
> Just because only one is reported in dmesg doesn't mean there isn't a
> bad one.
>
> It's unlikely the long test is going to actually fix anything, it'll
> just give you more ammunition for getting a likely under warranty
> device replaced because it really shouldn't have any issues at this
> age.
>
>
> > If it does not I can try calculating the physical (4K) sector number and
> > write to that to make the drive notice and mark the bad sector.
> > Is there a way to find out which file I will be writing to beforehand?
>
> I'm not sure how to do it easily.
>
> >Or is
> > it easier to just write to the sector and then wait for scrub to tell me
> > (and the sector is broken anyways)?
>
> If it's a persistent read error, then it's lost. So you might as well
> overwrite it. If it's data, scrub will tell you what file is corrupted
> (and restore can help you recover the whole file, of course it'll have
> a 4K hole of zeros in it). If it's metadata, Btrfs will fix up the 4K
> hole with duplicate metadata.
>
> Gotcha is to make certain you've got the right LBA to write to. You
> can use dd to test this, by reading the suspect bad sector, and if
> you've got the right one, you'll get an I/O error in user space and
> dmesg will have a message like before with sector value. Use the dd
> skip= flag for reading, but make *sure* you use seek= when writing
> *and* make sure you always use bs=4096 count=1 so that if you make a
> mistake you limit the damage haha.
>
> >
> > For the drive: Not under warranty anymore. It's an external HDD that I had
> > lying around for years, mostly unused. Now I wanted to use it as part of my
> > small DIY NAS.
>
> Gotcha. Well you can read up on smartctl and smartd, and set it up for
> regular extended tests, and keep an eye on rapidly changing values. It
> might give you a 50/50 chance of an early heads up before it dies.
>
> I've got an old Hitachi/Apple laptop drive that years ago developed
> multiple bad sectors in different zones of the drive. They got
> remapped and I haven't had a problem with that drive since. *shrug*
> And in fact I did get a discrete error message from the drive for one
> of those and Btrfs overwrote that bad sector with a good copy (it's in
> a raid1 volume), so working as designed I guess.
>
> Since you didn't get a fix up message from Btrfs, either the whole
> thing just got confused with hanging tasks, or it's possible it's a
> data block.
>
>
> --
> Chris Murphy
^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: btrfs send hung in pipe_wait
2018-09-07 12:47 ` Stefan Loewen
@ 2018-09-07 15:44 ` Chris Murphy
2018-09-07 17:07 ` Stefan Loewen
0 siblings, 1 reply; 17+ messages in thread
From: Chris Murphy @ 2018-09-07 15:44 UTC (permalink / raw)
To: Stefan Loewen; +Cc: Chris Murphy, Btrfs BTRFS
On Fri, Sep 7, 2018 at 6:47 AM, Stefan Loewen <stefan.loewen@gmail.com> wrote:
> Well... It seems it's not the hardware.
> I ran a long SMART check which ran through without errors and
> reallocation count is still 0.
That only checks the drive, it's an internal test. It doesn't check
anything else, including connections.
Also you do have a log with a read error and a sector LBA reported. So
there is a hardware issue, it could just be transient.
> So I used clonezilla (partclone.btrfs) to mirror the drive to another
> drive (same model).
> Everything copied over just fine. No I/O error im dmesg.
>
> The new disk shows the same behavior.
So now I'm suspicious of USB behavior. Like I said earlier, when I've
got USB enclosed drives connect to my NUC, regardless of file system,
I routinely get hangs and USB resets. I have to connect all of my USB
enclosed drives to a good USB hub, or I have problems.
> So I created another subvolume, reflinked stuff over and found that it
> is enough to reflink one file, create a read-only snapshot and try to
> btrfs-send that. It's not happening with every file, but there are
> definitely multiple different files. The one I tested with is a 3.8GB
> ISO file.
> Even better:
> 'btrfs send --no-data snap-one > /dev/null'
> (snap-one containing just one iso file) hangs as well.
Do you have a list of steps to make this clear? It sounds like first
you copy a 3.8G ISO file to one subvolume, then reflink copy it into
another subvolume, then snapshot that 2nd subvolume, and try to send
the snapshot? But I want to be clear.
I've got piles of reflinked files in snapshots and they send OK,
although like I said I do get sometimes a 15-30 second hang during
sends.
> Still dmesg shows no IO errors, only "INFO: task btrfs-transacti:541
> blocked for more than 120 seconds." with associated call trace.
> btrfs-send reads some MB in the beginning, writes a few bytes and then
> hangs without further IO.
>
> copying the same file without --reflink, snapshotting and sending
> works without problems.
>
> I guess that pretty much eleminates bad sectors and points towards
> some problem with reflinks / btrfs metadata.
That's pretty weird. I'll keep trying and see if I hit this. What
happens if you downgrade to an older kernel? Either 4.14 or 4.17 or
both. The send code is mainly in the kernel, where the receive code is
mainly in user space tools, for this testing you don't need to
downgrade user space tools. If there's a bug here, I expect it's
kernel.
--
Chris Murphy
^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: btrfs send hung in pipe_wait
2018-09-07 15:44 ` Chris Murphy
@ 2018-09-07 17:07 ` Stefan Loewen
2018-09-07 19:17 ` Chris Murphy
0 siblings, 1 reply; 17+ messages in thread
From: Stefan Loewen @ 2018-09-07 17:07 UTC (permalink / raw)
To: Chris Murphy; +Cc: Btrfs BTRFS
List of steps:
- 3.8G iso lays in read-only subvol A
- I create subvol B and reflink-copy the iso into it.
- I create a read-only snapshot C of B
- I "btrfs send --no-data C > /somefile"
So you got that right, yes.
Unfortunately I don't have any way to connect the drive to a SATA port
directly but I tried to switch out as much of the used setup as
possible (all changes active at the same time):
- I got the original (not the clone) HDD out of the enclosure and used
this adapter to connect it:
https://www.amazon.de/DIGITUS-Adapterkabel-40pol-480Mbps-schwarz/dp/B007X86VZK
- I used a different Notebook
- I ran the test natively on that notebook (instead of from
VirtualBox. I used VirtualBox for most of the tests as I have to
force-poweroff the PC everytime the btrfs-send hangs as it is not
killable)
- That notebook runs Manjaro with "Linux asus 4.14.67-1-MANJARO #1 SMP
PREEMPT Fri Aug 24 16:33:26 UTC 2018 x86_64 GNU/Linux"
Same results. btrfs-send freezes.
Am Fr., 7. Sep. 2018 um 17:44 Uhr schrieb Chris Murphy
<lists@colorremedies.com>:
>
> On Fri, Sep 7, 2018 at 6:47 AM, Stefan Loewen <stefan.loewen@gmail.com> wrote:
> > Well... It seems it's not the hardware.
> > I ran a long SMART check which ran through without errors and
> > reallocation count is still 0.
>
> That only checks the drive, it's an internal test. It doesn't check
> anything else, including connections.
>
> Also you do have a log with a read error and a sector LBA reported. So
> there is a hardware issue, it could just be transient.
>
>
> > So I used clonezilla (partclone.btrfs) to mirror the drive to another
> > drive (same model).
> > Everything copied over just fine. No I/O error im dmesg.
> >
> > The new disk shows the same behavior.
>
> So now I'm suspicious of USB behavior. Like I said earlier, when I've
> got USB enclosed drives connect to my NUC, regardless of file system,
> I routinely get hangs and USB resets. I have to connect all of my USB
> enclosed drives to a good USB hub, or I have problems.
>
>
>
> > So I created another subvolume, reflinked stuff over and found that it
> > is enough to reflink one file, create a read-only snapshot and try to
> > btrfs-send that. It's not happening with every file, but there are
> > definitely multiple different files. The one I tested with is a 3.8GB
> > ISO file.
> > Even better:
> > 'btrfs send --no-data snap-one > /dev/null'
> > (snap-one containing just one iso file) hangs as well.
>
> Do you have a list of steps to make this clear? It sounds like first
> you copy a 3.8G ISO file to one subvolume, then reflink copy it into
> another subvolume, then snapshot that 2nd subvolume, and try to send
> the snapshot? But I want to be clear.
>
> I've got piles of reflinked files in snapshots and they send OK,
> although like I said I do get sometimes a 15-30 second hang during
> sends.
>
> > Still dmesg shows no IO errors, only "INFO: task btrfs-transacti:541
> > blocked for more than 120 seconds." with associated call trace.
> > btrfs-send reads some MB in the beginning, writes a few bytes and then
> > hangs without further IO.
> >
> > copying the same file without --reflink, snapshotting and sending
> > works without problems.
> >
> > I guess that pretty much eleminates bad sectors and points towards
> > some problem with reflinks / btrfs metadata.
>
> That's pretty weird. I'll keep trying and see if I hit this. What
> happens if you downgrade to an older kernel? Either 4.14 or 4.17 or
> both. The send code is mainly in the kernel, where the receive code is
> mainly in user space tools, for this testing you don't need to
> downgrade user space tools. If there's a bug here, I expect it's
> kernel.
>
>
>
>
> --
> Chris Murphy
^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: btrfs send hung in pipe_wait
2018-09-07 17:07 ` Stefan Loewen
@ 2018-09-07 19:17 ` Chris Murphy
[not found] ` <CAHTTHimT7m+S4bm1OgZOfmFkk69fc1SPGEvidxwFCHniKL-w6A@mail.gmail.com>
0 siblings, 1 reply; 17+ messages in thread
From: Chris Murphy @ 2018-09-07 19:17 UTC (permalink / raw)
To: Stefan Loewen; +Cc: Chris Murphy, Btrfs BTRFS
On Fri, Sep 7, 2018 at 11:07 AM, Stefan Loewen <stefan.loewen@gmail.com> wrote:
> List of steps:
> - 3.8G iso lays in read-only subvol A
> - I create subvol B and reflink-copy the iso into it.
> - I create a read-only snapshot C of B
> - I "btrfs send --no-data C > /somefile"
> So you got that right, yes.
OK I can't reproduce it. Sending A and C complete instantly with
--no-data, and complete in the same time with a full send/receive. In
my case I used a 4.9G ISO.
I can't think of what local difference accounts for what you're
seeing. There is really nothing special about --reflinks. The extent
and csum data are identical to the original file, and that's the bulk
of the metadata for a given file.
What I can tell you is usually the developers want to see sysrq+w
whenever there are blocked tasks.
https://fedoraproject.org/wiki/QA/Sysrq
You'll want to enable all sysrq functions. And next you'll want three
ssh shells:
1. sudo journalctl -fk
2. sudo -i to become root, and then echo w > /proc/sysrq-trigger but
do not hit return yet
3. sudo btrfs send... to reproduce the problem.
Basically the thing is gonna hang soon after you reproduce the
problem, so you want to get to shell #2 and just hit return rather
than dealing with long delays typing that echo command out. And then
the journal command is so your local terminal captures the sysrq
output because you're gonna kill the VM instead of waiting it out. I
have no idea how to read these things but someone might pick up this
thread and have some idea why these tasks are hanging.
>
> Unfortunately I don't have any way to connect the drive to a SATA port
> directly but I tried to switch out as much of the used setup as
> possible (all changes active at the same time):
> - I got the original (not the clone) HDD out of the enclosure and used
> this adapter to connect it:
> https://www.amazon.de/DIGITUS-Adapterkabel-40pol-480Mbps-schwarz/dp/B007X86VZK
> - I used a different Notebook
> - I ran the test natively on that notebook (instead of from
> VirtualBox. I used VirtualBox for most of the tests as I have to
> force-poweroff the PC everytime the btrfs-send hangs as it is not
> killable)
This problem only happens in VirtualBox? Or it happens on baremetal
also? And we've established it happens with two different source
(send) devices, which means two different Btrfs volumes.
All I can say is you need to keep changing things up, process of
elimination. Rather tedious. Maybe you could try downloading a Fedora
28 ISO, make a boot stick out of it, and try to reproduce with the
same drives. At least that's an easy way to isolate the OS from the
equation.
--
Chris Murphy
^ permalink raw reply [flat|nested] 17+ messages in thread
* Fwd: btrfs send hung in pipe_wait
[not found] ` <CAHTTHimT7m+S4bm1OgZOfmFkk69fc1SPGEvidxwFCHniKL-w6A@mail.gmail.com>
@ 2018-09-08 9:45 ` Stefan Loewen
2018-09-09 2:31 ` Chris Murphy
[not found] ` <CAJCQCtQBwvvbYR3u=EGbRR=rsnBaZK5F=mso3SE_kPwtcXyvHg@mail.gmail.com>
1 sibling, 1 reply; 17+ messages in thread
From: Stefan Loewen @ 2018-09-08 9:45 UTC (permalink / raw)
To: Btrfs BTRFS
[-- Attachment #1: Type: text/plain, Size: 4770 bytes --]
Oops. Forgot CCing the mailinglist
---------- Forwarded message ---------
From: Stefan Loewen <stefan.loewen@gmail.com>
Date: Fr., 7. Sep. 2018 um 23:19 Uhr
Subject: Re: btrfs send hung in pipe_wait
To: Chris Murphy <lists@colorremedies.com>
No it does not only happen in VirtualBox. I already tested the following:
- Manjaro baremetal (btrfs-progs v4.17.1; linux v4.18.5 and v4.14.67)
- Ubuntu 18.04 in VirtualBox (btrfs-progs v4.15.1; linux v4.15.0-33-generic)
- ArchLinux in VirtualBox (btrfs-progs v4.17.1; linux v4.18.5-arch1-1-ARCH)
The logs I posted until now were mostly (iirc all of them) from the VM
with Arch.
Now I also tested with Fedora 28 (linux 4.16) from live-usb (so baremetal).
Same result.
Thanks for the pointer towards sys requests. sysrq-w is empty, but I
sent a bunch of other sysrqs to get stacktraces etc. from the kernel.
Logs are attached.
To recap:
I copied (reflink) a 3.8G iso file from a read-only snapshot (A) into
a new subvol (B) just to keep things small and managable.
There's nothing special about this file other than that it happens to
be one of the files to trigger the later btrfs-send to hang.
Not all files from A do this, but there are definitely multiple and
the problem only occurs when the files are reflinked.
I then create a snapshot (C) of B to be able to btrfs-send it.
Then I run "btrfs send snap-C > /somewhere", (--no-data leads to the
same) that process reads some MB from the source disk and writes a few
bytes to /somewhere and then just hangs without any further IO.
This is where I issued some sysrqs. The output is attached.
Then I tried killing the btrfs-send with ctrl-c and issued the sysrqs
again. I have no idea if that changed anything, but it didn't hurt, so
why not.
I'll try to minimize the dataset and maybe get a small fs-image
without too much personal information that I can upload so the issue
is reproducible by others.
Am Fr., 7. Sep. 2018 um 21:17 Uhr schrieb Chris Murphy
<lists@colorremedies.com>:
>
> On Fri, Sep 7, 2018 at 11:07 AM, Stefan Loewen <stefan.loewen@gmail.com> wrote:
> > List of steps:
> > - 3.8G iso lays in read-only subvol A
> > - I create subvol B and reflink-copy the iso into it.
> > - I create a read-only snapshot C of B
> > - I "btrfs send --no-data C > /somefile"
> > So you got that right, yes.
>
> OK I can't reproduce it. Sending A and C complete instantly with
> --no-data, and complete in the same time with a full send/receive. In
> my case I used a 4.9G ISO.
>
> I can't think of what local difference accounts for what you're
> seeing. There is really nothing special about --reflinks. The extent
> and csum data are identical to the original file, and that's the bulk
> of the metadata for a given file.
>
> What I can tell you is usually the developers want to see sysrq+w
> whenever there are blocked tasks.
> https://fedoraproject.org/wiki/QA/Sysrq
>
> You'll want to enable all sysrq functions. And next you'll want three
> ssh shells:
>
> 1. sudo journalctl -fk
> 2. sudo -i to become root, and then echo w > /proc/sysrq-trigger but
> do not hit return yet
> 3. sudo btrfs send... to reproduce the problem.
>
> Basically the thing is gonna hang soon after you reproduce the
> problem, so you want to get to shell #2 and just hit return rather
> than dealing with long delays typing that echo command out. And then
> the journal command is so your local terminal captures the sysrq
> output because you're gonna kill the VM instead of waiting it out. I
> have no idea how to read these things but someone might pick up this
> thread and have some idea why these tasks are hanging.
>
>
>
>
> >
> > Unfortunately I don't have any way to connect the drive to a SATA port
> > directly but I tried to switch out as much of the used setup as
> > possible (all changes active at the same time):
> > - I got the original (not the clone) HDD out of the enclosure and used
> > this adapter to connect it:
> > https://www.amazon.de/DIGITUS-Adapterkabel-40pol-480Mbps-schwarz/dp/B007X86VZK
> > - I used a different Notebook
> > - I ran the test natively on that notebook (instead of from
> > VirtualBox. I used VirtualBox for most of the tests as I have to
> > force-poweroff the PC everytime the btrfs-send hangs as it is not
> > killable)
>
>
> This problem only happens in VirtualBox? Or it happens on baremetal
> also? And we've established it happens with two different source
> (send) devices, which means two different Btrfs volumes.
>
> All I can say is you need to keep changing things up, process of
> elimination. Rather tedious. Maybe you could try downloading a Fedora
> 28 ISO, make a boot stick out of it, and try to reproduce with the
> same drives. At least that's an easy way to isolate the OS from the
> equation.
>
>
> --
> Chris Murphy
[-- Attachment #2: fedora-kernelmsgs.log.gz --]
[-- Type: application/gzip, Size: 34612 bytes --]
^ permalink raw reply [flat|nested] 17+ messages in thread
* Fwd: btrfs send hung in pipe_wait
[not found] ` <CAJCQCtQBwvvbYR3u=EGbRR=rsnBaZK5F=mso3SE_kPwtcXyvHg@mail.gmail.com>
@ 2018-09-08 9:47 ` Stefan Loewen
0 siblings, 0 replies; 17+ messages in thread
From: Stefan Loewen @ 2018-09-08 9:47 UTC (permalink / raw)
To: Btrfs BTRFS
And this one as well.
---------- Forwarded message ---------
From: Chris Murphy <lists@colorremedies.com>
Date: Fr., 7. Sep. 2018 um 23:53 Uhr
Subject: Re: btrfs send hung in pipe_wait
To: Stefan Loewen <stefan.loewen@gmail.com>
Cc: Chris Murphy <lists@colorremedies.com>
On Fri, Sep 7, 2018 at 3:19 PM, Stefan Loewen <stefan.loewen@gmail.com> wrote:
> Now I also tested with Fedora 28 (linux 4.16) from live-usb (so baremetal).
> Same result.
> Thanks for the pointer towards sys requests. sysrq-w is empty, but I
> sent a bunch of other sysrqs to get stacktraces etc. from the kernel.
> Logs are attached.
Needs a dev to take a look at this, or someone with usb or block
device knowledge to see if something unrelated to btrfs is hung up. I
can't parse it.
Using btrfs-progs 4.17.1, what do you get for 'btrfs check
--mode=lowmem <dev>' ?
--
Chris Murphy
^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: btrfs send hung in pipe_wait
2018-09-08 9:45 ` Fwd: " Stefan Loewen
@ 2018-09-09 2:31 ` Chris Murphy
[not found] ` <CAHTTHinSJy6c7jV1pApeQgnGwMHjd9DEutqxc-T5XjKVbeh1SA@mail.gmail.com>
0 siblings, 1 reply; 17+ messages in thread
From: Chris Murphy @ 2018-09-09 2:31 UTC (permalink / raw)
To: Stefan Loewen; +Cc: Btrfs BTRFS
I don't see any blocked tasks. I wonder if you were too fast with
sysrq w? Maybe it takes a little bit for the block task to actually
develop?
I suggest also 'btrfs check --mode=lowmem' because that is a separate
implementation of btrfs check that tends to catch different things
than the original. It is slow, however.
--
Chris Murphy
^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: btrfs send hung in pipe_wait
[not found] ` <CAHTTHinSJy6c7jV1pApeQgnGwMHjd9DEutqxc-T5XjKVbeh1SA@mail.gmail.com>
@ 2018-09-09 23:29 ` Chris Murphy
0 siblings, 0 replies; 17+ messages in thread
From: Chris Murphy @ 2018-09-09 23:29 UTC (permalink / raw)
To: Stefan Loewen; +Cc: Chris Murphy, Btrfs BTRFS
On Sun, Sep 9, 2018 at 2:16 PM, Stefan Loewen <stefan.loewen@gmail.com> wrote:
> I'm not sure about the exact definition of "blocked" here, but I was
> also surprised that there were no blocked tasks listed since I'm
> definitely unable to kill (SIGKILL) that process.
> On the other hand it wakes up hourly to transfer a few bytes.
> The problem is definitely not, that I issued the sysrq too early. I
> think it was after about 45min of no IO.
Another one the devs have asked for in cases where things get slow or
hang, but without explicit blocked task messages, is sysrq + t. But
I'm throwing spaghetti at a wall at this point, none of it will fix
the problem, and I haven't learned how to read these outputs.
> So there is some problem with this "original" subvol. Maybe I should
> describe how that came into existence.
> Initially I had my data on a NTFS formatted drive. I then created a
> btrfs partition on my second drive and rsynced all my stuff over into
> the root subvol.
> Then I noticed that having all my data in the root subvol was a bad
> idea and created a "data" subvol and reflinked everything into it.
> I deleted the data from the root subvol, made a snapshot of the "data"
> subvol, tried sending that and ran into the problem we're discussing
> here.
That is interesting and useful information. I see nothing invalid
about it at all. However, just for future reference it is possible to
snapshot the top level (default) subvolume.
By default, the top level subvolume (sometimes referred to as
subvolid=5 or subvolid=0) is what is mounted if you haven't used
'btrfs sub set-default' to change it. You can snapshot that subvolume
by snapshotting the mount point. e.g.
mount /dev/sda1 /mnt
btrfs sub snap /mnt/subvolume1
So now you have a readwrite subvolume called "subvolume1" which
contains everything that was in the top level, which you can now
delete if you're trying to keep things tidy and just have subvolumes
and snapshots in the top level.
Anyway, what you did is possibly relevant to the problem. But if it
turns out it's the cause of the problem, it's definitely a bug.
>
> btrfs check in lowmem mode did not find any errors either:
>
> $ sudo btrfs check --mode=lowmem --progress /dev/sdb1
> Opening filesystem to check...
> Checking filesystem on /dev/sdb1
> UUID: cd786597-3816-40e7-bf6c-d585265ad372
> [1/7] checking root items (0:00:30 elapsed,
> 1047408 items checked)
> [2/7] checking extents (0:03:55 elapsed,
> 309170 items checked)
> cache and super generation don't match, space cache will be invalidated
> [3/7] checking free space cache (0:00:00 elapsed)
> [4/7] checking fs roots (0:04:07 elapsed, 85373
> items checked)
> [5/7] checking csums (without verifying data) (0:00:00 elapsed,
> 253106 items checked)
> [6/7] checking root refs done with fs roots in lowmem mode, skipping
> [7/7] checking quota groups skipped (not enabled on this FS)
> found 708354711552 bytes used, no error found
> total csum bytes: 689206904
> total tree bytes: 2423865344
> total fs tree bytes: 1542914048
> total extent tree bytes: 129843200
> btree space waste bytes: 299191292
> file data blocks allocated: 31709967417344
> referenced 928531877888
OK good to know.
--
Chris Murphy
^ permalink raw reply [flat|nested] 17+ messages in thread
end of thread, other threads:[~2018-09-10 7:23 UTC | newest]
Thread overview: 17+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2018-09-06 9:22 btrfs send hung in pipe_wait Stefan Löwen
2018-09-06 15:04 ` Stefan Loewen
2018-09-06 15:48 ` Chris Murphy
2018-09-06 16:03 ` Stefan Löwen
2018-09-06 18:16 ` Chris Murphy
2018-09-06 18:36 ` Stefan Loewen
2018-09-06 19:58 ` Chris Murphy
2018-09-06 20:16 ` Stefan Loewen
2018-09-07 3:29 ` Chris Murphy
2018-09-07 12:47 ` Stefan Loewen
2018-09-07 15:44 ` Chris Murphy
2018-09-07 17:07 ` Stefan Loewen
2018-09-07 19:17 ` Chris Murphy
[not found] ` <CAHTTHimT7m+S4bm1OgZOfmFkk69fc1SPGEvidxwFCHniKL-w6A@mail.gmail.com>
2018-09-08 9:45 ` Fwd: " Stefan Loewen
2018-09-09 2:31 ` Chris Murphy
[not found] ` <CAHTTHinSJy6c7jV1pApeQgnGwMHjd9DEutqxc-T5XjKVbeh1SA@mail.gmail.com>
2018-09-09 23:29 ` Chris Murphy
[not found] ` <CAJCQCtQBwvvbYR3u=EGbRR=rsnBaZK5F=mso3SE_kPwtcXyvHg@mail.gmail.com>
2018-09-08 9:47 ` Fwd: " Stefan Loewen
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.