Arch Linux

gregfrankenstein

Member

Registered: 2015-09-12

Posts: 26

[SOLVED] CPU spike and freezing, apparently from a borked journal

I've seen a few other threads recently about random, inexplicable freezes and CPU spikes.  Maybe this is related?  Ever since about Wednesday, for seemingly no reason, my CPU usage will spike to 100% in i3status and lxtask despite no process in top, lxtask, or any other task manager showing a process above the single digits.  The system slows to a crawl and often locks up entirely with no pattern to what I'm doing at the time, then a couple minutes later, it's suddenly fine again, unless I spend so much time fumbling trying to diagnose the issue and launch applications that I froze it to the point of needing a manual reboot.

I initially thought based on the timing that it was the result of a systemd update, but I tried downgrading that to no avail.  Then I looked in journalctl and noticed that each time it's happened, it logged this.  This example was when I was running rsync but it's happened at all sorts of different times:

Dec 02 13:45:32 ComputerPad kernel: INFO: task md0_raid1:184 blocked for more than 120 seconds.
Dec 02 13:46:45 ComputerPad kernel:       Tainted: G          I       4.19.6.a-1-hardened #1
Dec 02 13:46:45 ComputerPad kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Dec 02 13:46:45 ComputerPad kernel: md0_raid1       D    0   184      2 0x80000000
Dec 02 13:46:45 ComputerPad kernel: Call Trace:
Dec 02 13:46:45 ComputerPad kernel:  ? __schedule+0x29b/0x8b0
Dec 02 13:46:45 ComputerPad kernel:  ? _raw_spin_unlock_irqrestore+0x20/0x40
Dec 02 13:46:45 ComputerPad kernel:  schedule+0x32/0x90
Dec 02 13:46:45 ComputerPad kernel:  md_super_wait+0x69/0xa0 [md_mod]
Dec 02 13:46:45 ComputerPad kernel:  ? wait_woken+0x80/0x80
Dec 02 13:46:45 ComputerPad kernel:  write_page+0x193/0x330 [md_mod]
Dec 02 13:46:45 ComputerPad kernel:  ? preempt_count_add+0x79/0xb0
Dec 02 13:46:45 ComputerPad kernel:  md_update_sb.part.39+0x371/0x8d0 [md_mod]
Dec 02 13:46:45 ComputerPad kernel:  ? md_register_thread+0xd0/0xd0 [md_mod]
Dec 02 13:46:45 ComputerPad kernel:  md_check_recovery+0x148/0x540 [md_mod]
Dec 02 13:46:45 ComputerPad kernel:  raid1d+0x5c/0xf10 [raid1]
Dec 02 13:46:45 ComputerPad kernel:  ? _raw_spin_lock_irqsave+0x25/0x50
Dec 02 13:46:45 ComputerPad kernel:  ? lock_timer_base+0x67/0x80
Dec 02 13:46:45 ComputerPad kernel:  ? _raw_spin_unlock_irqrestore+0x20/0x40
Dec 02 13:46:45 ComputerPad kernel:  ? try_to_del_timer_sync+0x4d/0x80
Dec 02 13:46:45 ComputerPad kernel:  ? del_timer_sync+0x35/0x40
Dec 02 13:46:45 ComputerPad kernel:  ? schedule_timeout+0x1d9/0x4a0
Dec 02 13:46:45 ComputerPad kernel:  ? preempt_count_add+0x79/0xb0
Dec 02 13:46:45 ComputerPad kernel:  ? _raw_spin_lock_irqsave+0x25/0x50
Dec 02 13:46:45 ComputerPad kernel:  ? md_register_thread+0xd0/0xd0 [md_mod]
Dec 02 13:46:45 ComputerPad kernel:  ? md_thread+0xf9/0x160 [md_mod]
Dec 02 13:46:45 ComputerPad kernel:  ? fix_read_error+0x3d0/0x3d0 [raid1]
Dec 02 13:46:45 ComputerPad kernel:  md_thread+0xf9/0x160 [md_mod]
Dec 02 13:46:45 ComputerPad kernel:  ? wait_woken+0x80/0x80
Dec 02 13:46:45 ComputerPad kernel:  kthread+0x112/0x130
Dec 02 13:46:45 ComputerPad kernel:  ? kthread_park+0x80/0x80
Dec 02 13:46:45 ComputerPad kernel:  ret_from_fork+0x35/0x40
Dec 02 13:46:45 ComputerPad kernel: INFO: task dmcrypt_write:235 blocked for more than 120 seconds.
Dec 02 13:46:45 ComputerPad kernel:       Tainted: G          I       4.19.6.a-1-hardened #1
Dec 02 13:46:45 ComputerPad kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Dec 02 13:46:45 ComputerPad kernel: dmcrypt_write   D    0   235      2 0x80000000
Dec 02 13:46:45 ComputerPad kernel: Call Trace:
Dec 02 13:46:45 ComputerPad kernel:  ? __schedule+0x29b/0x8b0
Dec 02 13:46:45 ComputerPad kernel:  ? _raw_spin_unlock_irqrestore+0x20/0x40
Dec 02 13:46:45 ComputerPad kernel:  schedule+0x32/0x90
Dec 02 13:46:45 ComputerPad kernel:  md_write_start+0xf1/0x2b0 [md_mod]
Dec 02 13:46:45 ComputerPad kernel:  ? wait_woken+0x80/0x80
Dec 02 13:46:45 ComputerPad kernel:  raid1_make_request+0x99/0xb30 [raid1]
Dec 02 13:46:45 ComputerPad kernel:  ? __switch_to_asm+0x40/0x70
Dec 02 13:46:45 ComputerPad kernel:  ? __switch_to_asm+0x34/0x70
Dec 02 13:46:45 ComputerPad kernel:  ? __switch_to_asm+0x40/0x70
Dec 02 13:46:45 ComputerPad kernel:  ? __switch_to_asm+0x34/0x70
Dec 02 13:46:45 ComputerPad kernel:  ? __switch_to_asm+0x40/0x70
Dec 02 13:46:45 ComputerPad kernel:  ? __switch_to_asm+0x34/0x70
Dec 02 13:46:45 ComputerPad kernel:  ? __switch_to_asm+0x40/0x70
Dec 02 13:46:45 ComputerPad kernel:  ? __switch_to_asm+0x34/0x70
Dec 02 13:46:45 ComputerPad kernel:  ? __switch_to_asm+0x40/0x70
Dec 02 13:46:45 ComputerPad kernel:  ? __switch_to_asm+0x34/0x70
Dec 02 13:46:45 ComputerPad kernel:  ? __switch_to_asm+0x40/0x70
Dec 02 13:46:45 ComputerPad kernel:  ? __switch_to_asm+0x34/0x70
Dec 02 13:46:45 ComputerPad kernel:  ? __switch_to_asm+0x40/0x70
Dec 02 13:46:45 ComputerPad kernel:  ? wait_woken+0x80/0x80
Dec 02 13:46:45 ComputerPad kernel:  md_handle_request+0x131/0x1a0 [md_mod]
Dec 02 13:46:45 ComputerPad kernel:  ? crypt_iv_essiv_dtr+0x60/0x60 [dm_crypt]
Dec 02 13:46:45 ComputerPad kernel:  md_make_request+0x78/0x190 [md_mod]
Dec 02 13:46:45 ComputerPad kernel:  generic_make_request+0x1b9/0x3d0
Dec 02 13:46:45 ComputerPad kernel:  dmcrypt_write+0x12b/0x150 [dm_crypt]
Dec 02 13:46:45 ComputerPad kernel:  ? _raw_spin_lock_irqsave+0x25/0x50
Dec 02 13:46:45 ComputerPad kernel:  ? _raw_spin_unlock_irqrestore+0x20/0x40
Dec 02 13:46:45 ComputerPad kernel:  kthread+0x112/0x130
Dec 02 13:46:45 ComputerPad kernel:  ? kthread_park+0x80/0x80
Dec 02 13:46:45 ComputerPad kernel:  ret_from_fork+0x35/0x40
Dec 02 13:46:45 ComputerPad kernel: INFO: task jbd2/dm-3-8:785 blocked for more than 120 seconds.
Dec 02 13:46:45 ComputerPad kernel:       Tainted: G          I       4.19.6.a-1-hardened #1
Dec 02 13:46:45 ComputerPad kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Dec 02 13:46:45 ComputerPad kernel: jbd2/dm-3-8     D    0   785      2 0x80000080
Dec 02 13:46:45 ComputerPad kernel: Call Trace:
Dec 02 13:46:45 ComputerPad kernel:  ? __schedule+0x29b/0x8b0
Dec 02 13:46:45 ComputerPad kernel:  ? __dm_make_request.isra.18+0x4c/0xa0 [dm_mod]
Dec 02 13:46:45 ComputerPad kernel:  ? preempt_count_add+0x79/0xb0
Dec 02 13:46:45 ComputerPad kernel:  ? bit_wait+0x50/0x50
Dec 02 13:46:45 ComputerPad kernel:  schedule+0x32/0x90
Dec 02 13:46:45 ComputerPad kernel:  io_schedule+0x12/0x40
Dec 02 13:46:45 ComputerPad kernel:  bit_wait_io+0xd/0x50
Dec 02 13:46:45 ComputerPad kernel:  __wait_on_bit+0x6c/0x80
Dec 02 13:46:45 ComputerPad kernel:  out_of_line_wait_on_bit+0x91/0xb0
Dec 02 13:46:45 ComputerPad kernel:  ? init_wait_var_entry+0x40/0x40
Dec 02 13:46:45 ComputerPad kernel:  jbd2_journal_commit_transaction+0x105f/0x1950 [jbd2]
Dec 02 13:46:45 ComputerPad kernel:  ? __switch_to_asm+0x40/0x70
Dec 02 13:46:45 ComputerPad kernel:  ? preempt_count_add+0x79/0xb0
Dec 02 13:46:45 ComputerPad kernel:  ? _raw_spin_unlock_irqrestore+0x20/0x40
Dec 02 13:46:45 ComputerPad kernel:  kjournald2+0xc0/0x270 [jbd2]
Dec 02 13:46:45 ComputerPad kernel:  ? wait_woken+0x80/0x80
Dec 02 13:46:45 ComputerPad kernel:  ? commit_timeout+0x10/0x10 [jbd2]
Dec 02 13:46:45 ComputerPad kernel:  kthread+0x112/0x130
Dec 02 13:46:45 ComputerPad kernel:  ? kthread_park+0x80/0x80
Dec 02 13:46:45 ComputerPad kernel:  ret_from_fork+0x35/0x40
Dec 02 13:46:45 ComputerPad kernel: INFO: task rsync:5927 blocked for more than 120 seconds.
Dec 02 13:46:45 ComputerPad kernel:       Tainted: G          I       4.19.6.a-1-hardened #1
Dec 02 13:46:45 ComputerPad kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Dec 02 13:46:45 ComputerPad kernel: rsync           D    0  5927   5686 0x00000080
Dec 02 13:46:45 ComputerPad kernel: Call Trace:
Dec 02 13:46:45 ComputerPad kernel:  ? __schedule+0x29b/0x8b0
Dec 02 13:46:45 ComputerPad kernel:  ? preempt_count_add+0x79/0xb0
Dec 02 13:46:45 ComputerPad kernel:  ? bit_wait+0x50/0x50
Dec 02 13:46:45 ComputerPad kernel:  schedule+0x32/0x90
Dec 02 13:46:45 ComputerPad kernel:  io_schedule+0x12/0x40
Dec 02 13:46:45 ComputerPad kernel:  bit_wait_io+0xd/0x50
Dec 02 13:46:45 ComputerPad kernel:  __wait_on_bit+0x6c/0x80
Dec 02 13:46:45 ComputerPad kernel:  out_of_line_wait_on_bit+0x91/0xb0
Dec 02 13:46:45 ComputerPad kernel:  ? init_wait_var_entry+0x40/0x40
Dec 02 13:46:45 ComputerPad kernel:  do_get_write_access+0x352/0x530 [jbd2]
Dec 02 13:46:45 ComputerPad kernel:  ? ext4_dirty_inode+0x46/0x60 [ext4]
Dec 02 13:46:45 ComputerPad kernel:  jbd2_journal_get_write_access+0x2c/0x50 [jbd2]
Dec 02 13:46:45 ComputerPad kernel:  __ext4_journal_get_write_access+0x2c/0x70 [ext4]
Dec 02 13:46:45 ComputerPad kernel:  ext4_reserve_inode_write+0x96/0xc0 [ext4]
Dec 02 13:46:45 ComputerPad kernel:  ext4_mark_inode_dirty+0x4e/0x1d0 [ext4]
Dec 02 13:46:45 ComputerPad kernel:  ext4_dirty_inode+0x46/0x60 [ext4]
Dec 02 13:46:45 ComputerPad kernel:  __mark_inode_dirty+0x41/0x3e0
Dec 02 13:46:45 ComputerPad kernel:  generic_update_time+0xb6/0xd0
Dec 02 13:46:45 ComputerPad kernel:  touch_atime+0xbe/0xe0
Dec 02 13:46:45 ComputerPad kernel:  generic_file_read_iter+0x689/0x9b0
Dec 02 13:46:45 ComputerPad kernel:  __vfs_read+0x133/0x190
Dec 02 13:46:45 ComputerPad kernel:  vfs_read+0x8a/0x150
Dec 02 13:46:45 ComputerPad kernel:  ksys_read+0x4f/0xb0
Dec 02 13:46:45 ComputerPad kernel:  do_syscall_64+0x5b/0x150
Dec 02 13:46:45 ComputerPad kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xa9
Dec 02 13:46:45 ComputerPad kernel: RIP: 0033:0x68782fc8e775
Dec 02 13:46:45 ComputerPad kernel: Code: Bad RIP value.
Dec 02 13:46:45 ComputerPad kernel: RSP: 002b:0000705db17f5188 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
Dec 02 13:46:45 ComputerPad kernel: RAX: ffffffffffffffda RBX: 0000063ec79cc560 RCX: 000068782fc8e775
Dec 02 13:46:45 ComputerPad kernel: RDX: 0000000000002dac RSI: 0000063ec79fe850 RDI: 0000000000000003
Dec 02 13:46:45 ComputerPad kernel: RBP: 0000000000002dac R08: 0000063ec79fe840 R09: 000068782fd61250
Dec 02 13:46:45 ComputerPad kernel: R10: 0000063ec712d100 R11: 0000000000000246 R12: 0000000000000000
Dec 02 13:46:45 ComputerPad kernel: R13: 0000000000002dac R14: 0000000000000000 R15: 0000000000000000

My kernel is-- tainted apparently?  Despite having no strange modules loaded, nor could I really load anything interesting with linux-hardened.  I also tried the vanilla Arch kernel and LTS and they both had the same issue.  It gives a code of G, meaning whatever it is, it's nothing proprietary, and running "cat /proc/sys/kernel/tainted" returns "2048", meaning "the system is working around a severe firmware bug".  Maybe a quirk due to running Libreboot?

I have no idea whether the "tainted" bit is related, but either way, the reason the spike and freeze happens out of nowhere seems to be because it's attempting to journal the disks and hitting some sort of death spiral, but I'm not an expert at this low of a level so I have no idea.  I was about to give up and reinstall the entire OS, as nothing seemed to indicate why this is happening, but then I saw threads like this and thought maybe there's something to it, though I wasn't sure if it's related enough to put it as a reply.

EDIT: Marking as solved, not because I figured out what was wrong, but because I'm using this as an opportunity to clean install the system and drastically reconfigure some things I've been itching to change.

Last edited by gregfrankenstein (2018-12-03 19:15:42)