System freezes a lot - btrfs trace in dmesg - symptom or cause?

System freezes a lot - btrfs trace in dmesg - symptom or cause?

[Richard Schwab]

[-- Attachment #1: Type: text/plain, Size: 1288 bytes --]

Hi there,

I'm currently having some issues with my system freezing a lot, from a
few seconds up to a few minutes. I haven't figured out yet what might be
causing this, however, coincidentally some btrfs notices appeared in my
dmesg after I had a freeze for about 5 minutes. I'm wondering whether
this is just another symptom of my system having some weird issues or
whether this might actually be the cause of the freezes I've been
experiencing.

$ uname -a
Linux mypc 4.15.14-1-ARCH #1 SMP PREEMPT Wed Mar 28 17:34:29 UTC 2018
x86_64 GNU/Linux

$ btrfs --version
btrfs-progs v4.15.1

$ btrfs fi show
Label: none  uuid: uuid1
    Total devices 1 FS bytes used 226.60GiB
    devid    1 size 237.37GiB used 237.31GiB path /dev/mapper/cryptroot256g

Label: none  uuid: uuid2
    Total devices 1 FS bytes used 116.61MiB
    devid    1 size 1.00GiB used 460.00MiB path /dev/sdb2

$ btrfs fi df /
Data, single: total=231.28GiB, used=223.66GiB
System, single: total=32.00MiB, used=48.00KiB
Metadata, single: total=6.00GiB, used=2.93GiB
GlobalReserve, single: total=512.00MiB, used=0.00B

Partial dmesg is attached as file. Please tell me if you need more than
this, however, before these lines it only contained the startup process
(up until 87s).

Sincerely
Richard Schwab

[-- Attachment #2: btrfs.dmesg.txt --]
[-- Type: text/plain, Size: 18510 bytes --]

[ 6995.028268] perf: interrupt took too long (2513 > 2500), lowering kernel.perf_event_max_sample_rate to 79000
[10513.344255] Chrome_~dThread[6211]: segfault at 0 ip 00007f0cf13d6aed sp 00007f0ceb37eb00 error 6 in libxul.so[7f0cf0fe2000+4c14000]
[10513.344553] Chrome_~dThread[3242]: segfault at 0 ip 00007f8bcb0d6aed sp 00007f8bc507eb00 error 6
[10513.344557] Chrome_~dThread[3110]: segfault at 0 ip 00007f13a50d6aed sp 00007f139f07eb00 error 6 in libxul.so[7f13a4ce2000+4c14000]
[10513.344562]  in libxul.so[7f8bcace2000+4c14000]
[10513.344704] Chrome_~dThread[3202]: segfault at 0 ip 00007f089e7d6aed sp 00007f089877eb00 error 6 in libxul.so[7f089e3e2000+4c14000]
[10691.693188] INFO: task btrfs-transacti:447 blocked for more than 120 seconds.
[10691.693196]       Tainted: P           O     4.15.14-1-ARCH #1
[10691.693199] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[10691.693202] btrfs-transacti D    0   447      2 0x80000000
[10691.693207] Call Trace:
[10691.693221]  ? __schedule+0x24b/0x8c0
[10691.693229]  ? enqueue_entity+0x59b/0xc70
[10691.693234]  schedule+0x32/0x90
[10691.693239]  io_schedule+0x12/0x40
[10691.693247]  __lock_page+0xf8/0x130
[10691.693252]  ? add_to_page_cache_lru+0xe0/0xe0
[10691.693309]  read_extent_buffer_pages+0xf0/0x2f0 [btrfs]
[10691.693337]  ? btrfs_alloc_root+0x30/0x30 [btrfs]
[10691.693365]  btree_read_extent_buffer_pages+0x94/0xf0 [btrfs]
[10691.693389]  read_block_for_search.isra.14+0x15a/0x2f0 [btrfs]
[10691.693413]  btrfs_search_slot+0x3cd/0xa00 [btrfs]
[10691.693437]  ? block_group_cache_tree_search+0xba/0xd0 [btrfs]
[10691.693460]  btrfs_insert_empty_items+0x66/0xb0 [btrfs]
[10691.693484]  alloc_reserved_file_extent+0x96/0x320 [btrfs]
[10691.693511]  __btrfs_run_delayed_refs+0x908/0x1180 [btrfs]
[10691.693539]  btrfs_run_delayed_refs+0xe5/0x1b0 [btrfs]
[10691.693566]  btrfs_start_dirty_block_groups+0x2cb/0x470 [btrfs]
[10691.693596]  btrfs_commit_transaction+0x117/0x930 [btrfs]
[10691.693626]  ? start_transaction+0x9e/0x420 [btrfs]
[10691.693654]  transaction_kthread+0x17b/0x1a0 [btrfs]
[10691.693684]  ? btrfs_cleanup_transaction+0x570/0x570 [btrfs]
[10691.693687]  kthread+0x113/0x130
[10691.693691]  ? kthread_create_on_node+0x70/0x70
[10691.693695]  ret_from_fork+0x35/0x40
[10691.693703] INFO: task journal-offline:7151 blocked for more than 120 seconds.
[10691.693707]       Tainted: P           O     4.15.14-1-ARCH #1
[10691.693709] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[10691.693712] journal-offline D    0  7151      1 0x00000104
[10691.693715] Call Trace:
[10691.693721]  ? __schedule+0x24b/0x8c0
[10691.693726]  ? preempt_count_add+0x68/0xa0
[10691.693730]  schedule+0x32/0x90
[10691.693759]  wait_current_trans+0xc3/0xf0 [btrfs]
[10691.693763]  ? wait_woken+0x80/0x80
[10691.693792]  start_transaction+0x332/0x420 [btrfs]
[10691.693824]  btrfs_sync_file+0x2b6/0x440 [btrfs]
[10691.693832]  do_fsync+0x38/0x60
[10691.693836]  SyS_fsync+0xc/0x10
[10691.693840]  do_syscall_64+0x74/0x190
[10691.693845]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[10691.693848] RIP: 0033:0x7f7147b5a0ec
[10691.693850] RSP: 002b:00007f714191cd30 EFLAGS: 00000293 ORIG_RAX: 000000000000004a
[10691.693854] RAX: ffffffffffffffda RBX: 000055d002846410 RCX: 00007f7147b5a0ec
[10691.693856] RDX: 0000000000000000 RSI: 00007f71474b6811 RDI: 0000000000000015
[10691.693857] RBP: 00007f71474b7c60 R08: 00007f714191d700 R09: 00007f714191d700
[10691.693859] R10: 0000000000000011 R11: 0000000000000293 R12: 0000000000000002
[10691.693861] R13: 00007fff8456870f R14: 00007fff84568710 R15: 0000000000000016
[10691.693866] INFO: task journal-offline:7152 blocked for more than 120 seconds.
[10691.693869]       Tainted: P           O     4.15.14-1-ARCH #1
[10691.693871] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[10691.693874] journal-offline D    0  7152      1 0x00000104
[10691.693877] Call Trace:
[10691.693883]  ? __schedule+0x24b/0x8c0
[10691.693887]  ? preempt_count_add+0x68/0xa0
[10691.693891]  schedule+0x32/0x90
[10691.693920]  wait_current_trans+0xc3/0xf0 [btrfs]
[10691.693923]  ? wait_woken+0x80/0x80
[10691.693952]  start_transaction+0x332/0x420 [btrfs]
[10691.693984]  btrfs_sync_file+0x2b6/0x440 [btrfs]
[10691.693990]  do_fsync+0x38/0x60
[10691.693994]  SyS_fsync+0xc/0x10
[10691.693998]  do_syscall_64+0x74/0x190
[10691.694001]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[10691.694004] RIP: 0033:0x7f7147b5a0ec
[10691.694005] RSP: 002b:00007f714011bd30 EFLAGS: 00000293 ORIG_RAX: 000000000000004a
[10691.694009] RAX: ffffffffffffffda RBX: 000055d00284b810 RCX: 00007f7147b5a0ec
[10691.694010] RDX: 0000000000000000 RSI: 00007f71474b6811 RDI: 0000000000000016
[10691.694012] RBP: 00007f71474b7c60 R08: 00007f714011c700 R09: 00007f714011c700
[10691.694014] R10: 0000000000000011 R11: 0000000000000293 R12: 0000000000000002
[10691.694016] R13: 00007fff8456870f R14: 00007fff84568710 R15: 0000000000000016
[10691.694043] INFO: task gnome-shell:1116 blocked for more than 120 seconds.
[10691.694047]       Tainted: P           O     4.15.14-1-ARCH #1
[10691.694049] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[10691.694052] gnome-shell     D    0  1116   1061 0x00000000
[10691.694055] Call Trace:
[10691.694061]  ? __schedule+0x24b/0x8c0
[10691.694065]  ? preempt_count_add+0x68/0xa0
[10691.694069]  schedule+0x32/0x90
[10691.694098]  wait_current_trans+0xc3/0xf0 [btrfs]
[10691.694102]  ? wait_woken+0x80/0x80
[10691.694131]  start_transaction+0x332/0x420 [btrfs]
[10691.694177]  btrfs_create+0x57/0x200 [btrfs]
[10691.694183]  path_openat+0xbf7/0x1320
[10691.694189]  ? sock_getsockopt+0x356/0x8e0
[10691.694194]  do_filp_open+0x9b/0x110
[10691.694201]  ? __check_object_size+0x9b/0x1a0
[10691.694206]  ? __alloc_fd+0xaf/0x160
[10691.694211]  ? do_sys_open+0x1bd/0x250
[10691.694214]  do_sys_open+0x1bd/0x250
[10691.694219]  do_syscall_64+0x74/0x190
[10691.694224]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[10691.694226] RIP: 0033:0x7f8e1a7d6390
[10691.694228] RSP: 002b:00007ffc4d6b83c0 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
[10691.694231] RAX: ffffffffffffffda RBX: 000056312af47d00 RCX: 00007f8e1a7d6390
[10691.694233] RDX: 00000000000000c1 RSI: 000056312af47d00 RDI: ffffffffffffff9c
[10691.694235] RBP: 00007f8e196e3420 R08: 0000000000000000 R09: 0000000000000023
[10691.694236] R10: 00000000000001b6 R11: 0000000000000293 R12: 000056312af47d36
[10691.694238] R13: 000000005ace689e R14: 0e38e38e38e38e39 R15: 00007f8e197472e0
[10691.694296] INFO: task baloo_file_extr:1653 blocked for more than 120 seconds.
[10691.694299]       Tainted: P           O     4.15.14-1-ARCH #1
[10691.694301] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[10691.694304] baloo_file_extr D    0  1653   1652 0x00000000
[10691.694308] Call Trace:
[10691.694313]  ? __schedule+0x24b/0x8c0
[10691.694318]  schedule+0x32/0x90
[10691.694323]  io_schedule+0x12/0x40
[10691.694328]  wait_on_page_bit+0xea/0x130
[10691.694333]  ? add_to_page_cache_lru+0xe0/0xe0
[10691.694369]  read_extent_buffer_pages+0x25a/0x2f0 [btrfs]
[10691.694396]  ? btrfs_alloc_root+0x30/0x30 [btrfs]
[10691.694423]  btree_read_extent_buffer_pages+0x94/0xf0 [btrfs]
[10691.694452]  read_tree_block+0x31/0x60 [btrfs]
[10691.694475]  read_block_for_search.isra.14+0x110/0x2f0 [btrfs]
[10691.694499]  btrfs_search_slot+0x3cd/0xa00 [btrfs]
[10691.694523]  ? block_group_cache_tree_search+0xba/0xd0 [btrfs]
[10691.694546]  btrfs_insert_empty_items+0x66/0xb0 [btrfs]
[10691.694569]  alloc_reserved_file_extent+0x96/0x320 [btrfs]
[10691.694685]  __btrfs_run_delayed_refs+0x908/0x1180 [btrfs]
[10691.694713]  btrfs_run_delayed_refs+0xe5/0x1b0 [btrfs]
[10691.694743]  btrfs_commit_transaction+0x46/0x930 [btrfs]
[10691.694777]  ? btrfs_wait_ordered_range+0x92/0x100 [btrfs]
[10691.694808]  btrfs_sync_file+0x363/0x440 [btrfs]
[10691.694842]  btrfs_file_write_iter+0x4c9/0x650 [btrfs]
[10691.694849]  __vfs_write+0xf8/0x180
[10691.694855]  vfs_write+0xb1/0x1a0
[10691.694860]  SyS_pwrite64+0x90/0xb0
[10691.694865]  do_syscall_64+0x74/0x190
[10691.694870]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[10691.694872] RIP: 0033:0x7f87c380caf3
[10691.694874] RSP: 002b:00007ffd2d3022b0 EFLAGS: 00000293 ORIG_RAX: 0000000000000012
[10691.694877] RAX: ffffffffffffffda RBX: 000055e0967b7450 RCX: 00007f87c380caf3
[10691.694879] RDX: 0000000000000078 RSI: 00007ffd2d302340 RDI: 0000000000000013
[10691.694881] RBP: 00007ffd2d302330 R08: 0000000031004000 R09: 00000000000001fd
[10691.694883] R10: 0000000000000020 R11: 0000000000000293 R12: 0000000000000013
[10691.694885] R13: 00000000003a7b61 R14: 0000000000000000 R15: 000055e09679f660
[10691.694891] INFO: task quiterss:1672 blocked for more than 120 seconds.
[10691.694895]       Tainted: P           O     4.15.14-1-ARCH #1
[10691.694897] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[10691.694900] quiterss        D    0  1672   1116 0x00000000
[10691.694904] Call Trace:
[10691.694910]  ? __schedule+0x24b/0x8c0
[10691.694914]  ? preempt_count_add+0x68/0xa0
[10691.694919]  schedule+0x32/0x90
[10691.694947]  wait_current_trans+0xc3/0xf0 [btrfs]
[10691.694951]  ? wait_woken+0x80/0x80
[10691.694980]  start_transaction+0x332/0x420 [btrfs]
[10691.695012]  btrfs_create+0x57/0x200 [btrfs]
[10691.695017]  path_openat+0xbf7/0x1320
[10691.695023]  do_filp_open+0x9b/0x110
[10691.695029]  ? preempt_count_add+0x49/0xa0
[10691.695032]  ? __check_object_size+0x9b/0x1a0
[10691.695035]  ? preempt_count_add+0x68/0xa0
[10691.695038]  ? __check_object_size+0x9b/0x1a0
[10691.695043]  ? __alloc_fd+0xaf/0x160
[10691.695047]  ? do_sys_open+0x1bd/0x250
[10691.695051]  do_sys_open+0x1bd/0x250
[10691.695056]  do_syscall_64+0x74/0x190
[10691.695060]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[10691.695062] RIP: 0033:0x7faff28d8390
[10691.695064] RSP: 002b:00007ffc2c48ac60 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
[10691.695067] RAX: ffffffffffffffda RBX: 0000000000000064 RCX: 00007faff28d8390
[10691.695069] RDX: 00000000000800c1 RSI: 000055c2f49cf198 RDI: ffffffffffffff9c
[10691.695071] RBP: 000055c2f49cf198 R08: 0000000000000000 R09: 0000000000000049
[10691.695073] R10: 00000000000001b6 R11: 0000000000000293 R12: 00007ffc2c48adb0
[10691.695074] R13: 00007ffc2c48ada8 R14: 00007ffc2c48adc0 R15: 00007ffc2c48ada0
[10691.695121] INFO: task threaded-ml:2517 blocked for more than 120 seconds.
[10691.695125]       Tainted: P           O     4.15.14-1-ARCH #1
[10691.695128] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[10691.695131] threaded-ml     D    0  2517   2489 0x00000000
[10691.695134] Call Trace:
[10691.695141]  ? __schedule+0x24b/0x8c0
[10691.695143]  ? _raw_spin_unlock+0x16/0x30
[10691.695148]  schedule+0x32/0x90
[10691.695153]  io_schedule+0x12/0x40
[10691.695158]  wait_on_page_bit+0xea/0x130
[10691.695163]  ? add_to_page_cache_lru+0xe0/0xe0
[10691.695196]  prepare_pages+0x256/0x270 [btrfs]
[10691.695229]  __btrfs_buffered_write.isra.4+0x257/0x700 [btrfs]
[10691.695263]  btrfs_file_write_iter+0x216/0x650 [btrfs]
[10691.695270]  __vfs_write+0xf8/0x180
[10691.695276]  vfs_write+0xb1/0x1a0
[10691.695281]  SyS_write+0x52/0xc0
[10691.695286]  do_syscall_64+0x74/0x190
[10691.695290]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[10691.695292] RIP: 0033:0x7f174882b47b
[10691.695294] RSP: 002b:00007f16e3ffe360 EFLAGS: 00000293 ORIG_RAX: 0000000000000001
[10691.695297] RAX: ffffffffffffffda RBX: 000000000309b720 RCX: 00007f174882b47b
[10691.695299] RDX: 0000000000000074 RSI: 000000000309b720 RDI: 0000000000000010
[10691.695300] RBP: 0000000000000074 R08: 0000000000000000 R09: 00007f16e3fff700
[10691.695302] R10: 0000000000000004 R11: 0000000000000293 R12: 0000000000000074
[10691.695304] R13: 0000000000000001 R14: 0000000002dec120 R15: 0000000000000074
[10691.695353] INFO: task systemd-coredum:7134 blocked for more than 120 seconds.
[10691.695357]       Tainted: P           O     4.15.14-1-ARCH #1
[10691.695359] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[10691.695362] systemd-coredum D    0  7134      1 0x00000100
[10691.695365] Call Trace:
[10691.695371]  ? __schedule+0x24b/0x8c0
[10691.695375]  ? preempt_count_add+0x68/0xa0
[10691.695379]  schedule+0x32/0x90
[10691.695408]  wait_current_trans+0xc3/0xf0 [btrfs]
[10691.695412]  ? wait_woken+0x80/0x80
[10691.695441]  start_transaction+0x332/0x420 [btrfs]
[10691.695473]  btrfs_sync_file+0x2b6/0x440 [btrfs]
[10691.695479]  do_fsync+0x38/0x60
[10691.695484]  SyS_fsync+0xc/0x10
[10691.695489]  do_syscall_64+0x74/0x190
[10691.695495]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[10691.695499] RIP: 0033:0x7fd1023920c4
[10691.695501] RSP: 002b:00007ffe8b641da8 EFLAGS: 00000246 ORIG_RAX: 000000000000004a
[10691.695506] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fd1023920c4
[10691.695508] RDX: 0000000000090000 RSI: 000055a987f320b0 RDI: 0000000000000008
[10691.695510] RBP: 000055a987f320b0 R08: 000000001fffffff R09: 0000000000000000
[10691.695513] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000008
[10691.695515] R13: 0000000000000007 R14: 0000000000000000 R15: 000055a9876c5eca
[10691.695522] INFO: task systemd-coredum:7135 blocked for more than 120 seconds.
[10691.695527]       Tainted: P           O     4.15.14-1-ARCH #1
[10691.695531] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[10691.695535] systemd-coredum D    0  7135      1 0x00000100
[10691.695539] Call Trace:
[10691.695548]  ? __schedule+0x24b/0x8c0
[10691.695553]  ? preempt_count_add+0x68/0xa0
[10691.695559]  schedule+0x32/0x90
[10691.695593]  wait_current_trans+0xc3/0xf0 [btrfs]
[10691.695597]  ? wait_woken+0x80/0x80
[10691.695624]  start_transaction+0x332/0x420 [btrfs]
[10691.695652]  btrfs_sync_file+0x2b6/0x440 [btrfs]
[10691.695657]  do_fsync+0x38/0x60
[10691.695661]  SyS_fsync+0xc/0x10
[10691.695665]  do_syscall_64+0x74/0x190
[10691.695669]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[10691.695671] RIP: 0033:0x7efc118060c4
[10691.695673] RSP: 002b:00007ffe3d514528 EFLAGS: 00000246 ORIG_RAX: 000000000000004a
[10691.695676] RAX: ffffffffffffffda RBX: 0000000000000050 RCX: 00007efc118060c4
[10691.695678] RDX: 000055d79ae3f29d RSI: 000055d798f1aeca RDI: 0000000000000007
[10691.695680] RBP: 00007ffe3d5147e0 R08: 0000000000000001 R09: 0000000000000001
[10691.695681] R10: 0000000000000018 R11: 0000000000000246 R12: 0000000000000007
[10691.695683] R13: 000055d79911c6c0 R14: 0000000000000000 R15: 000055d798f1aeca
[10777.215907] systemd[1]: systemd-journald.service: State 'stop-sigabrt' timed out. Terminating.
[10813.467012] systemd[1]: systemd-coredump@3-7129-0.service: Service reached runtime time limit. Stopping.
[10813.467321] systemd[1]: systemd-coredump@4-7132-0.service: Service reached runtime time limit. Stopping.
[10813.467530] systemd[1]: systemd-coredump@2-7131-0.service: Service reached runtime time limit. Stopping.
[10813.467714] systemd[1]: systemd-coredump@1-7130-0.service: Service reached runtime time limit. Stopping.
[10814.576937] INFO: task btrfs-transacti:447 blocked for more than 120 seconds.
[10814.576944]       Tainted: P           O     4.15.14-1-ARCH #1
[10814.576947] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[10814.576950] btrfs-transacti D    0   447      2 0x80000000
[10814.576955] Call Trace:
[10814.576969]  ? __schedule+0x24b/0x8c0
[10814.576976]  ? enqueue_entity+0x59b/0xc70
[10814.576982]  schedule+0x32/0x90
[10814.576987]  io_schedule+0x12/0x40
[10814.576995]  __lock_page+0xf8/0x130
[10814.577001]  ? add_to_page_cache_lru+0xe0/0xe0
[10814.577057]  read_extent_buffer_pages+0xf0/0x2f0 [btrfs]
[10814.577085]  ? btrfs_alloc_root+0x30/0x30 [btrfs]
[10814.577113]  btree_read_extent_buffer_pages+0x94/0xf0 [btrfs]
[10814.577137]  read_block_for_search.isra.14+0x15a/0x2f0 [btrfs]
[10814.577162]  btrfs_search_slot+0x3cd/0xa00 [btrfs]
[10814.577185]  ? block_group_cache_tree_search+0xba/0xd0 [btrfs]
[10814.577208]  btrfs_insert_empty_items+0x66/0xb0 [btrfs]
[10814.577232]  alloc_reserved_file_extent+0x96/0x320 [btrfs]
[10814.577258]  __btrfs_run_delayed_refs+0x908/0x1180 [btrfs]
[10814.577286]  btrfs_run_delayed_refs+0xe5/0x1b0 [btrfs]
[10814.577313]  btrfs_start_dirty_block_groups+0x2cb/0x470 [btrfs]
[10814.577344]  btrfs_commit_transaction+0x117/0x930 [btrfs]
[10814.577376]  ? start_transaction+0x9e/0x420 [btrfs]
[10814.577414]  transaction_kthread+0x17b/0x1a0 [btrfs]
[10814.577450]  ? btrfs_cleanup_transaction+0x570/0x570 [btrfs]
[10814.577456]  kthread+0x113/0x130
[10814.577461]  ? kthread_create_on_node+0x70/0x70
[10814.577467]  ret_from_fork+0x35/0x40
[10829.573727] systemd[1]: systemd-coredump@3-7129-0.service: Failed with result 'timeout'.
[10829.598383] systemd[1]: systemd-coredump@4-7132-0.service: Failed with result 'timeout'.
[10867.468634] systemd[1]: systemd-journald.service: State 'stop-sigterm' timed out. Killing.
[10867.468675] systemd[1]: systemd-journald.service: Killing process 483 (systemd-journal) with signal SIGKILL.
[10882.459017] systemd[1]: systemd-coredump@2-7131-0.service: Failed with result 'timeout'.
[10882.543666] systemd[1]: systemd-journald.service: Main process exited, code=killed, status=9/KILL
[10882.543724] systemd[1]: systemd-journald.service: Failed with result 'watchdog'.
[10882.544463] systemd[1]: systemd-journald.service: Service has no hold-off time, scheduling restart.
[10882.544514] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1.
[10882.544973] systemd[1]: Stopped Flush Journal to Persistent Storage.
[10882.544984] systemd[1]: Stopping Flush Journal to Persistent Storage...
[10882.544990] systemd[1]: Stopped Journal Service.
[10882.546122] systemd[1]: Starting Journal Service...
[10882.556116] systemd-coredump[7220]: Failed to get COMM, falling back to the command line: No such process
[10882.556125] systemd-coredump[7220]: Failed to get EXE, ignoring: No such process
[10882.558212] systemd[1]: Started Process Core Dump (PID 7220/UID 0).
[10882.657421] systemd-journald[7221]: File /var/log/journal/3ef0da93b38446888eade5bbbe82faa0/system.journal corrupted or uncleanly shut down, renaming and replacing.
[10882.864559] systemd-journald[7221]: File /var/log/journal/3ef0da93b38446888eade5bbbe82faa0/user-1000.journal corrupted or uncleanly shut down, renaming and replacing.
[11958.641897] perf: interrupt took too long (3150 > 3141), lowering kernel.perf_event_max_sample_rate to 63000

Re: System freezes a lot - btrfs trace in dmesg - symptom or cause?

[Chris Murphy]

FWIW, gmail considers the original post a phishing attempt, and put it
into spam. Also the sending mail server marked the header with a
request that subsequent mail servers fail to forward the email, which
effectively makes it incompatible with mail servers which modify the
email body, making dkim message verification fail. So I suggest either
clearing it up with the mail provider or using a different email for
lists.

This message has a from address in central-intelligence.agency but has
failed central-intelligence.agency's required tests for
authentication.  Learn more

Authentication-Results: mx.google.com;
       dkim=neutral (body hash did not verify)
header.i=@central-intelligence.agency header.s=default
header.b=eqsLMYnQ;
       spf=pass (google.com: best guess record for domain of
linux-btrfs-owner@vger.kernel.org designates 209.132.180.67 as
permitted sender) smtp.mailfrom=linux-btrfs-owner@vger.kernel.org;
       dmarc=fail (p=REJECT sp=REJECT dis=QUARANTINE)
header.from=central-intelligence.agency



On Tue, Apr 3, 2018 at 3:35 PM, Richard Schwab
<kernelorg-djthmw7n9w@central-intelligence.agency> wrote:
> Hi there,
>
> I'm currently having some issues with my system freezing a lot, from a
> few seconds up to a few minutes. I haven't figured out yet what might be
> causing this, however, coincidentally some btrfs notices appeared in my
> dmesg after I had a freeze for about 5 minutes. I'm wondering whether
> this is just another symptom of my system having some weird issues or
> whether this might actually be the cause of the freezes I've been
> experiencing.

>From the attached text file

10691.693188] INFO: task btrfs-transacti:447 blocked for more than 120 seconds.
[10691.693196]       Tainted: P           O     4.15.14-1-ARCH #1
[10691.693199] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[10691.693202] btrfs-transacti D    0   447      2 0x80000000
[10691.693207] Call Trace:
[10691.693221]  ? __schedule+0x24b/0x8c0
[10691.693229]  ? enqueue_entity+0x59b/0xc70
[10691.693234]  schedule+0x32/0x90
[10691.693239]  io_schedule+0x12/0x40
[10691.693247]  __lock_page+0xf8/0x130
[10691.693252]  ? add_to_page_cache_lru+0xe0/0xe0
[10691.693309]  read_extent_buffer_pages+0xf0/0x2f0 [btrfs]
[10691.693337]  ? btrfs_alloc_root+0x30/0x30 [btrfs]
[10691.693365]  btree_read_extent_buffer_pages+0x94/0xf0 [btrfs]
[10691.693389]  read_block_for_search.isra.14+0x15a/0x2f0 [btrfs]
[10691.693413]  btrfs_search_slot+0x3cd/0xa00 [btrfs]
[10691.693437]  ? block_group_cache_tree_search+0xba/0xd0 [btrfs]
[10691.693460]  btrfs_insert_empty_items+0x66/0xb0 [btrfs]
[10691.693484]  alloc_reserved_file_extent+0x96/0x320 [btrfs]
[10691.693511]  __btrfs_run_delayed_refs+0x908/0x1180 [btrfs]
[10691.693539]  btrfs_run_delayed_refs+0xe5/0x1b0 [btrfs]
[10691.693566]  btrfs_start_dirty_block_groups+0x2cb/0x470 [btrfs]
[10691.693596]  btrfs_commit_transaction+0x117/0x930 [btrfs]
[10691.693626]  ? start_transaction+0x9e/0x420 [btrfs]
[10691.693654]  transaction_kthread+0x17b/0x1a0 [btrfs]
[10691.693684]  ? btrfs_cleanup_transaction+0x570/0x570 [btrfs]
[10691.693687]  kthread+0x113/0x130
[10691.693691]  ? kthread_create_on_node+0x70/0x70
[10691.693695]  ret_from_fork+0x35/0x40
[10691.693703] INFO: task journal-offline:7151 blocked for more than
120 seconds.


Off hand it just looks like noise, it's only an info message. But of
course the hung task is super annoying and maybe makes it worse than
if it were to just crash. Anyway, best to reproduce and issue sysrq +
w and hopefully a dev will get around to giving an opinion on what's
going on. In the meantime you can try reverting to 4.14.32 or try
4.16.0. I'm not seeing anything off hand in 4.15.15 that relates, so I
suspect it still happens with that version. Another thing to try is
booting without the proprietary driver you're using that taints the
kernel. It may very well be unrelated to this problem, but ...

https://www.kernel.org/doc/Documentation/admin-guide/sysrq.rst

Translated it means do this:

sudo -i
echo 1 > /proc/sys/kernel/sysrq
echo w > /proc/sysrq-trigger
exit
sudo journalctl -o short-monotonic -k > kernelmsg+sysrqw.log

And then post that log file somewhere like dropbox or whatever, it may
be too big to attach to the list but you can try it.


-- 
Chris Murphy

Re: System freezes a lot - btrfs trace in dmesg - symptom or cause?

[Qu Wenruo]

[-- Attachment #1.1: Type: text/plain, Size: 2527 bytes --]



On 2018年04月04日 05:35, Richard Schwab wrote:
> Hi there,
> 
> I'm currently having some issues with my system freezing a lot, from a
> few seconds up to a few minutes. I haven't figured out yet what might be
> causing this, however, coincidentally some btrfs notices appeared in my
> dmesg after I had a freeze for about 5 minutes. I'm wondering whether
> this is just another symptom of my system having some weird issues or
> whether this might actually be the cause of the freezes I've been
> experiencing.
> 
> $ uname -a
> Linux mypc 4.15.14-1-ARCH #1 SMP PREEMPT Wed Mar 28 17:34:29 UTC 2018
> x86_64 GNU/Linux
> 
> $ btrfs --version
> btrfs-progs v4.15.1
> 
> $ btrfs fi show
> Label: none  uuid: uuid1
>     Total devices 1 FS bytes used 226.60GiB
>     devid    1 size 237.37GiB used 237.31GiB path /dev/mapper/cryptroot256g
> 
> Label: none  uuid: uuid2
>     Total devices 1 FS bytes used 116.61MiB
>     devid    1 size 1.00GiB used 460.00MiB path /dev/sdb2
> 
> $ btrfs fi df /
> Data, single: total=231.28GiB, used=223.66GiB
> System, single: total=32.00MiB, used=48.00KiB
> Metadata, single: total=6.00GiB, used=2.93GiB
> GlobalReserve, single: total=512.00MiB, used=0.00B
> 
> Partial dmesg is attached as file. Please tell me if you need more than
> this, however, before these lines it only contained the startup process
> (up until 87s).

[10691.693202] btrfs-transacti D    0   447      2 0x80000000
[10691.693207] Call Trace:
[10691.693221]  ? __schedule+0x24b/0x8c0
[10691.693229]  ? enqueue_entity+0x59b/0xc70
[10691.693234]  schedule+0x32/0x90
[10691.693239]  io_schedule+0x12/0x40
[10691.693247]  __lock_page+0xf8/0x130
[10691.693252]  ? add_to_page_cache_lru+0xe0/0xe0
[10691.693309]  read_extent_buffer_pages+0xf0/0x2f0 [btrfs]
[10691.693337]  ? btrfs_alloc_root+0x30/0x30 [btrfs]
[10691.693365]  btree_read_extent_buffer_pages+0x94/0xf0 [btrfs]
[10691.693389]  read_block_for_search.isra.14+0x15a/0x2f0 [btrfs]

This means the tree block pages btrfs trying to read is being locked by
other guy.

And considering later operations also waiting on the same page, it looks
like a deadlock.

Not sure if it's something serious or just bad luck.
But looks like there is something wrong with btrfs tree locks.

Is it reproducible and what's the workload?

And if it's just bad luck, reboot the system and run "btrfs check" on
the fs is highly recommended.

Thanks,
Qu

> 
> Sincerely
> Richard Schwab
> 


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 488 bytes --]