perfevents: irq loop stuck!

perfevents: irq loop stuck!

[Vince Weaver]

I've gotten the following warning a few times now with the perf_fuzzer.
In each case it looks like the culprit might be the fixed-counter 0
value being 0000fffffffffffe

I have a somewhat repeatable trace and it looks like the problem event is:

        pe[32].type=PERF_TYPE_HARDWARE;
        pe[32].size=80;
        pe[32].config=PERF_COUNT_HW_INSTRUCTIONS;
        pe[32].sample_period=0xc0000000000000bd;

Should it be possible to open an event with a large negative sample_period 
like that?  I tried tracing through the sample_period setting code and 
there are places that cast from u64 to s64 and other dubious things, but 
as always I find the code very hard to follow.

This is on a Haswell machine.

[  425.815773] ------------[ cut here ]------------
[  425.821212] WARNING: CPU: 0 PID: 0 at arch/x86/kernel/cpu/perf_event_intel.c:1373 intel_pmu_handle_irq+0x2a4/0x3c0()
[  425.833692] perfevents: irq loop stuck!
[  425.839116] Modules linked in: fuse x86_pkg_temp_thermal intel_powerclamp coretemp kvm snd_hda_codec_realtek snd_hda_codec_generic snd_hda_codec_hdmi crct10dif_pclmul crc32_pclmul ghash_clmulni_intel aesni_intel aes_x86_64 lrw gf128mul snd_hda_intel i915 glue_helper snd_hda_controller snd_hda_codec snd_hwdep snd_pcm drm_kms_helper snd_seq snd_timer snd_seq_device ablk_helper snd cryptd ppdev iTCO_wdt iTCO_vendor_support lpc_ich drm soundcore mei_me parport_pc mfd_core evdev i2c_algo_bit i2c_i801 i2c_core button processor video battery wmi mei parport psmouse serio_raw pcspkr tpm_tis tpm sd_mod sr_mod crc_t10dif crct10dif_common cdrom ahci ehci_pci libahci e1000e ehci_hcd xhci_hcd libata ptp crc32c_intel usbcore scsi_mod pps_core usb_common thermal fan thermal_sys
[  425.930947] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 3.15.0-rc1+ #104
[  425.937876] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
[  425.945817]  0000000000000009 ffff88011ea06cb0 ffffffff81649ca0 ffff88011ea06cf8
[  425.953957]  ffff88011ea06ce8 ffffffff810646ad 0000000000000064 ffff88011ea0cbe0
[  425.961986]  ffff8800cd1f4800 0000000000000040 ffff88011ea0cde0 ffff88011ea06d48
[  425.970169] Call Trace:
[  425.972858]  <NMI>  [<ffffffff81649ca0>] dump_stack+0x45/0x56
[  425.979150]  [<ffffffff810646ad>] warn_slowpath_common+0x7d/0xa0
[  425.985617]  [<ffffffff8106471c>] warn_slowpath_fmt+0x4c/0x50
[  425.991770]  [<ffffffff8102ef94>] intel_pmu_handle_irq+0x2a4/0x3c0
[  425.998417]  [<ffffffff8165378b>] perf_event_nmi_handler+0x2b/0x50
[  426.005116]  [<ffffffff81652f58>] nmi_handle.isra.5+0xa8/0x150
[  426.011428]  [<ffffffff81652eb5>] ? nmi_handle.isra.5+0x5/0x150
[  426.017729]  [<ffffffff816530d8>] do_nmi+0xd8/0x340
[  426.022979]  [<ffffffff81652581>] end_repeat_nmi+0x1e/0x2e
[  426.028917]  [<ffffffff8105034a>] ? native_write_msr_safe+0xa/0x10
[  426.035514]  [<ffffffff8105034a>] ? native_write_msr_safe+0xa/0x10
[  426.042139]  [<ffffffff8105034a>] ? native_write_msr_safe+0xa/0x10
[  426.048752]  <<EOE>>  <IRQ>  [<ffffffff8102eb7d>] intel_pmu_enable_event+0x21d/0x240
[  426.057185]  [<ffffffff81027baa>] x86_pmu_start+0x7a/0x100
[  426.063125]  [<ffffffff810283a5>] x86_pmu_enable+0x295/0x310
[  426.069206]  [<ffffffff8113528f>] perf_pmu_enable+0x2f/0x40
[  426.075185]  [<ffffffff8102644a>] x86_pmu_commit_txn+0x7a/0xa0
[  426.081423]  [<ffffffff813ca99b>] ? debug_object_activate+0x17b/0x220
[  426.088298]  [<ffffffff810b0cad>] ? __lock_acquire.isra.29+0x3bd/0xb90
[  426.095245]  [<ffffffff81135fe0>] ? event_sched_in.isra.76+0x150/0x1e0
[  426.102269]  [<ffffffff81136230>] group_sched_in+0x1c0/0x1e0
[  426.108394]  [<ffffffff81136725>] __perf_event_enable+0x255/0x260
[  426.114976]  [<ffffffff811318f0>] remote_function+0x40/0x50
[  426.120916]  [<ffffffff810de20d>] generic_smp_call_function_single_interrupt+0x5d/0x100
[  426.129515]  [<ffffffff810421dd>] smp_trace_call_function_single_interrupt+0x2d/0xb0
[  426.137854]  [<ffffffff8165bc1d>] trace_call_function_single_interrupt+0x6d/0x80
[  426.145827]  <EOI>  [<ffffffff814e1b72>] ? cpuidle_enter_state+0x52/0xc0
[  426.153044]  [<ffffffff814e1b68>] ? cpuidle_enter_state+0x48/0xc0
[  426.159612]  [<ffffffff814e1c17>] cpuidle_enter+0x17/0x20
[  426.165411]  [<ffffffff810aa270>] cpu_startup_entry+0x2c0/0x3d0
[  426.171810]  [<ffffffff81639bc6>] rest_init+0xb6/0xc0
[  426.177259]  [<ffffffff81639b15>] ? rest_init+0x5/0xc0
[  426.182778]  [<ffffffff81d05f75>] start_kernel+0x43d/0x448
[  426.188647]  [<ffffffff81d05941>] ? repair_env_string+0x5c/0x5c
[  426.195040]  [<ffffffff81d05120>] ? early_idt_handlers+0x120/0x120
[  426.201643]  [<ffffffff81d055ee>] x86_64_start_reservations+0x2a/0x2c
[  426.208575]  [<ffffffff81d05733>] x86_64_start_kernel+0x143/0x152
[  426.215176] ---[ end trace 515d2dd21a07f5dd ]---
[  426.220078] 
[  426.221698] CPU#0: ctrl:       0000000000000000
[  426.226591] CPU#0: status:     0000000000000000
[  426.231480] CPU#0: overflow:   0000000000000000
[  426.236361] CPU#0: fixed:      00000000000000b8
[  426.241211] CPU#0: pebs:       0000000000000000
[  426.246076] CPU#0: active:     0000000300000002
[  426.250948] CPU#0:   gen-PMC0 ctrl:  00000000001300c5
[  426.256392] CPU#0:   gen-PMC0 count: 0000000000088ff0
[  426.261838] CPU#0:   gen-PMC0 left:  0000fffffff77328
[  426.267273] CPU#0:   gen-PMC1 ctrl:  0000000000530254
[  426.272727] CPU#0:   gen-PMC1 count: 0000000000000001
[  426.279307] CPU#0:   gen-PMC1 left:  0000ffffffffffff
[  426.285847] CPU#0:   gen-PMC2 ctrl:  000000000013412e
[  426.292354] CPU#0:   gen-PMC2 count: 0000000000010545
[  426.298874] CPU#0:   gen-PMC2 left:  0000fffffffefb07
[  426.305405] CPU#0:   gen-PMC3 ctrl:  00000000001300c0
[  426.311913] CPU#0:   gen-PMC3 count: 0000000001699699
[  426.318311] CPU#0:   gen-PMC3 left:  0000fffffeaa1a64
[  426.324715] CPU#0: fixed-PMC0 count: 0000fffffffffffe
[  426.331093] CPU#0: fixed-PMC1 count: 0000fffe069f640d
[  426.337399] CPU#0: fixed-PMC2 count: 0000000005cd7211
[  426.343626] perf_event_intel: clearing PMU state on CPU#0

Re: perfevents: irq loop stuck!

[Vince Weaver]

On Tue, 13 May 2014, Vince Weaver wrote:

>         pe[32].sample_period=0xc0000000000000bd;
> 
> Should it be possible to open an event with a large negative sample_period 
> like that? 

so this seems to be a real bug.

attr->sample_period is a u64 value, but internally it gets cast to
s64 and is added against itself and so all kinds of unexpected things 
happen.

So if you set attr->sample_period to 0xc0000000000000bd in the hopes of 
sampling the RETIRED_INSTRUCTIONS event every 5 years or so, instead
what happens is that in
	x86_perf_event_set_period()
the value is cast to a signed 64-bit value, so we are now negative.

Then "left" is set to period because we are negative.

Then since left is less than 0, we double the period value.
This overflows the 64-bit integer and suddenly we are in undefined
behavior territory and we're lucky the C compiler doesn't decide to
format the hard drive.

Anyway we are still less than 0, so then the

	if (unlikely(left < 2))
		left = 2;

code kicks in and suddenly our hugely positive sample_period has changed
to just being "2".  And so we suddenly get a storm of interrupts instead 
of one every 5 years.

So, not sure how to fix this without a total re-write, unless we want to 
cheat and just say sample_period is capped at 62-bits or something.

Also it's unclear why sometimes this can cause a stuck interrupt leading 
to the "irq loop stuck" message.  I have a reproducible fuzzer test case 
that will cause this to happen, but can't isolate it down to a simple test 
case...

Vince

Re: perfevents: irq loop stuck!

[Peter Zijlstra]

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

On Wed, May 14, 2014 at 10:55:40PM -0400, Vince Weaver wrote:
> On Tue, 13 May 2014, Vince Weaver wrote:
> 
> >         pe[32].sample_period=0xc0000000000000bd;
> > 
> > Should it be possible to open an event with a large negative sample_period 
> > like that? 
> 
> so this seems to be a real bug.
> 
> attr->sample_period is a u64 value, but internally it gets cast to
> s64 and is added against itself and so all kinds of unexpected things 
> happen.
> 
> So if you set attr->sample_period to 0xc0000000000000bd in the hopes of 
> sampling the RETIRED_INSTRUCTIONS event every 5 years or so, instead
> what happens is that in
> 	x86_perf_event_set_period()
> the value is cast to a signed 64-bit value, so we are now negative.
> 
> Then "left" is set to period because we are negative.
> 
> Then since left is less than 0, we double the period value.
> This overflows the 64-bit integer and suddenly we are in undefined
> behavior territory and we're lucky the C compiler doesn't decide to
> format the hard drive.
> 
> Anyway we are still less than 0, so then the
> 
> 	if (unlikely(left < 2))
> 		left = 2;
> 
> code kicks in and suddenly our hugely positive sample_period has changed
> to just being "2".  And so we suddenly get a storm of interrupts instead 
> of one every 5 years.
> 
> So, not sure how to fix this without a total re-write, unless we want to 
> cheat and just say sample_period is capped at 62-bits or something.

63 bits should do I think, but yes, we hit a very similar but a few days
ago in the sched_deadline code.

I'm fine with capping it, allowing the full 64bit would mean we need 65
bits (effectively 96 or 128 bit of course) math to make it all work
which would be tedious and give no real gain.

> Also it's unclear why sometimes this can cause a stuck interrupt leading 
> to the "irq loop stuck" message.  I have a reproducible fuzzer test case 
> that will cause this to happen, but can't isolate it down to a simple test 
> case...

So yes.. in theory we should throttle the event after a number of
interrupts to keep the machine alive, and I think that happens because
I've managed to hit it too while trying to reproduce one of the problems
Sasha reported and the machine was largely usuable.

It might trigger the getting stuck msgs because we can reach the 2
events (2 retired instructions isn't that many) in the NMI return path
after we've re-enabled the PMU I suppose.

We'll then not make progress for a while, print the msg, get throttled,
goto 1. This is possible if we're allowed 100+ interrupts per jiffy, so
if you adjust /proc/sys/kernel/perf_event_max_sample_rate to below that
and it doesn't trigger anymore we know the throttle works.

We've also seen hardware seize up on low period counts like that, which
is why there's a minimum of 2, 1 would guarantee an NMI storm/lockup no
matter what.

[-- Attachment #2: Type: application/pgp-signature, Size: 836 bytes --]

Re: perfevents: irq loop stuck!

[Vince Weaver]

On Thu, 15 May 2014, Peter Zijlstra wrote:

> > So, not sure how to fix this without a total re-write, unless we want to 
> > cheat and just say sample_period is capped at 62-bits or something.
> 
> 63 bits should do I think, but yes, we hit a very similar but a few days
> ago in the sched_deadline code.
> 
> I'm fine with capping it, allowing the full 64bit would mean we need 65
> bits (effectively 96 or 128 bit of course) math to make it all work
> which would be tedious and give no real gain.

Yes, it looks like 63 bits will be fine although I had to think about some 
of the logic there to make sure there's no signed overflow.

> We'll then not make progress for a while, print the msg, get throttled,
> goto 1. This is possible if we're allowed 100+ interrupts per jiffy, so
> if you adjust /proc/sys/kernel/perf_event_max_sample_rate to below that
> and it doesn't trigger anymore we know the throttle works.

The odd thing is that even when I try to write a small reproducer I can 
easily get the overflow of period to 2 to happen, but it doesn't trigger 
the message.  It will on occasion give a throttle message but that is all.

The fuzzer can reliably reproduce the actual IRQ warning, but a replay of 
a gathered trace will not.

Even weirder, the even that triggers it is attached to CPU0 but only 
triggers if the fuzzer itself is running on a different CPU.  Also the 
trigger event has all of exclude_kernel, exclude_user, and exclude_hv set
so I'm not sure how it even counts up to the 2 retired instructions to 
trigger an overflow anyway.  It doesn't help that there are 100+ other 
active events at the time, although suspiciously a few of them are 
apic_irq tracepoints (though attached to CPUs other than the trouble one).

anyway I'm not sure if it's worth tracking this more if it's possible to 
mostly fix the case by fixing the sample_period bounds.

Vince

Re: perfevents: irq loop stuck!

[Peter Zijlstra]

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

On Fri, May 16, 2014 at 12:25:28AM -0400, Vince Weaver wrote:
> anyway I'm not sure if it's worth tracking this more if it's possible to 
> mostly fix the case by fixing the sample_period bounds.

Right, so lets start with that, if it triggers again, we'll have another
look.

FWIW I ran with the below patch over night, and while trinity completely
shat itself going OOM -- so I'm not sure how long it ran, it didn't
trigger the stuck interrupt loop.

Will do more runs now that I'm there to hold its hand once more.

---
Subject: perf: Limit perf_event_attr::sample_period to 63 bits
From: Peter Zijlstra <peterz@infradead.org>
Date: Thu May 15 20:23:48 CEST 2014

Vince reported that using a large sample_period (one with bit 63 set)
results in wreckage since while the sample_period is fundamentally
unsigned (negative periods don't make sense) the way we implement
things very much rely on signed logic.

So limit sample_period to 63 bits to avoid tripping over this.

Reported-by: Vince Weaver <vincent.weaver@maine.edu>
Signed-off-by: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/n/tip-p25fhunibl4y3qi0zuqmyf4b@git.kernel.org
---
 kernel/events/core.c |    3 +++
 1 file changed, 3 insertions(+)

--- a/kernel/events/core.c
+++ b/kernel/events/core.c
@@ -7058,6 +7058,9 @@ SYSCALL_DEFINE5(perf_event_open,
 	if (attr.freq) {
 		if (attr.sample_freq > sysctl_perf_event_sample_rate)
 			return -EINVAL;
+	} else {
+		if (attr.sample_period & (1ULL << 63))
+			return -EINVAL;
 	}
 
 	/*

[-- Attachment #2: Type: application/pgp-signature, Size: 836 bytes --]

Re: perfevents: irq loop stuck!

[Vince Weaver]

On Fri, 16 May 2014, Peter Zijlstra wrote:

> On Fri, May 16, 2014 at 12:25:28AM -0400, Vince Weaver wrote:
> > anyway I'm not sure if it's worth tracking this more if it's possible to 
> > mostly fix the case by fixing the sample_period bounds.
> 
> Right, so lets start with that, if it triggers again, we'll have another
> look.

I applied the patch and can verify it avoids the too-big-period-wrapping 
problem.

I left things fuzzing over the weekend, and eventually the bug triggered 
again.  The problem issue still seems to be caused by 
	"sample_period=2,fixed counter 0"
so maybe there's an erratum out there I should be looking up.

The fuzzing also turned up a few other issues, and in the end after 2 days 
it locked up the machine so hard that it also took out the ethernet switch 
due to some sort of packet trasmit storm, which is a failure mode I 
have to admit I haven't encountered before.

Vince

[69213.252805] ------------[ cut here ]------------
[69213.260637] WARNING: CPU: 4 PID: 11343 at 
arch/x86/kernel/cpu/perf_event_intel.c:1373 intel_pmu_handle_irq+0x2a4/0x3c0()
[69213.276788] perfevents: irq loop stuck!
...
[69213.686561] CPU#4: ctrl:       0000000000000000
[69213.694352] CPU#4: status:     0000000000000000
[69213.701979] CPU#4: overflow:   0000000000000000
[69213.709599] CPU#4: fixed:      00000000000000b8
[69213.717172] CPU#4: pebs:       0000000000000000
[69213.724596] CPU#4: active:     0000000300000000
[69213.731939] CPU#4:   gen-PMC0 ctrl:  000000000013412e
[69213.739877] CPU#4:   gen-PMC0 count: 000000000000002c
[69213.747820] CPU#4:   gen-PMC0 left:  0000ffffffffffd7
[69213.755657] CPU#4:   gen-PMC1 ctrl:  0000000000138b40
[69213.763461] CPU#4:   gen-PMC1 count: 00000000000086b3
[69213.771152] CPU#4:   gen-PMC1 left:  0000ffffffff81c9
[69213.778742] CPU#4:   gen-PMC2 ctrl:  000000000013024e
[69213.786271] CPU#4:   gen-PMC2 count: 0000000000000001
[69213.793784] CPU#4:   gen-PMC2 left:  0000ffffffffffff
[69213.801227] CPU#4:   gen-PMC3 ctrl:  0000000000134f2e
[69213.808720] CPU#4:   gen-PMC3 count: 00000000000009f9
[69213.816192] CPU#4:   gen-PMC3 left:  0000fffffffff6de
[69213.823620] CPU#4: fixed-PMC0 count: 0000fffffffffffe
[69213.831035] CPU#4: fixed-PMC1 count: 0000ffffea2a90b2
[69213.838477] CPU#4: fixed-PMC2 count: 00000000051c5865
[69213.845792] perf_event_intel: clearing PMU state on CPU#4

Re: perfevents: irq loop stuck!

[Vince Weaver]

On Mon, 19 May 2014, Vince Weaver wrote:

> The fuzzing also turned up a few other issues, and in the end after 2 days 
> it locked up the machine so hard that it also took out the ethernet switch 
> due to some sort of packet trasmit storm, which is a failure mode I 
> have to admit I haven't encountered before.

Not only did it take out the ethernet switch, but it corrupted the 
filesystem too :(

Though I guess I should be surprised this doesn't happen more considering 
how often I have to hard-reboot the machines. 

[ 3835.636255] EXT4-fs error (device sda4): ext4_mb_generate_buddy:756: group 1681, 14687 clusters in bitmap, 14680 in gd; block bitmap corrupt.
[ 3835.649921] Aborting journal on device sda4-8.
[ 3835.654895] EXT4-fs (sda4): Remounting filesystem read-only
[ 3835.661053] ------------[ cut here ]------------
[ 3835.666163] WARNING: CPU: 0 PID: 2265 at fs/ext4/ext4_jbd2.c:259 __ext4_handle_dirty_metadata+0x1b2/0x200()
[ 3835.676785] Modules linked in: fuse x86_pkg_temp_thermal intel_powerclamp coretemp snd_hda_codec_hdmi kvm iTCO_wdt snd_hda_codec_realtek snd_hda_codec_generic iTCO_vendor_support i915 crc32_pclmul snd_hda_intel ghash_clmulni_intel snd_hda_controller wmi evdev drm_kms_helper ppdev aesni_intel mei_me mei drm snd_hda_codec aes_x86_64 lrw gf128mul glue_helper snd_hwdep ablk_helper psmouse snd_pcm snd_timer tpm_tis i2c_algo_bit snd tpm pcspkr serio_raw processor battery i2c_i801 i2c_core lpc_ich parport_pc parport cryptd soundcore button video mfd_core sd_mod sr_mod crc_t10dif crct10dif_generic cdrom ehci_pci ahci libahci xhci_hcd e1000e ehci_hcd crct10dif_pclmul libata crct10dif_common ptp crc32c_intel usbcore scsi_mod pps_core usb_common thermal fan thermal_sys
[ 3835.751220] CPU: 0 PID: 2265 Comm: git Not tainted 3.15.0-rc5+ #108
[ 3835.757911] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
[ 3835.765842]  0000000000000009 ffff8801179fb908 ffffffff8164a8f0 0000000000000000
[ 3835.773882]  ffff8801179fb940 ffffffff810646ad ffff880036aa7888 0000000000000000
[ 3835.781927]  ffff880036bf1cc8 ffffffff81830e20 00000000000012f3 ffff8801179fb950
[ 3835.789913] Call Trace:
[ 3835.792537]  [<ffffffff8164a8f0>] dump_stack+0x45/0x56
[ 3835.798028]  [<ffffffff810646ad>] warn_slowpath_common+0x7d/0xa0
[ 3835.804381]  [<ffffffff8106478a>] warn_slowpath_null+0x1a/0x20
[ 3835.810577]  [<ffffffff81269662>] __ext4_handle_dirty_metadata+0x1b2/0x200
[ 3835.817882]  [<ffffffff81652017>] ? _raw_spin_unlock+0x27/0x30
[ 3835.824080]  [<ffffffff81271ef6>] ext4_free_blocks+0x646/0xbf0
[ 3835.830334]  [<ffffffff81264be9>] ext4_ext_remove_space+0x7d9/0x1050
[ 3835.837054]  [<ffffffff81267580>] ext4_ext_truncate+0xb0/0xe0
[ 3835.843223]  [<ffffffff81240589>] ext4_truncate+0x379/0x3c0
[ 3835.849076]  [<ffffffff81152be9>] ? truncate_pagecache+0x59/0x60
[ 3835.855547]  [<ffffffff81241d1f>] ext4_setattr+0x2ef/0x730
[ 3835.861437]  [<ffffffff811d2961>] notify_change+0x241/0x390
[ 3835.867342]  [<ffffffff811b315f>] do_truncate+0x6f/0xa0
[ 3835.873046]  [<ffffffff811b2bab>] ? do_dentry_open+0x22b/0x2c0
[ 3835.879284]  [<ffffffff811c4edf>] do_last+0xa7f/0x12f0
[ 3835.884863]  [<ffffffff811c1241>] ? link_path_walk+0x71/0x880
[ 3835.891080]  [<ffffffff811c57c8>] ? path_openat+0x78/0x670
[ 3835.897030]  [<ffffffff811c580b>] path_openat+0xbb/0x670
[ 3835.902656]  [<ffffffff810b0d4d>] ? __lock_acquire.isra.29+0x3bd/0xb90
[ 3835.909714]  [<ffffffff811c65da>] do_filp_open+0x3a/0x90
[ 3835.915433]  [<ffffffff81652017>] ? _raw_spin_unlock+0x27/0x30
[ 3835.921711]  [<ffffffff811d3c97>] ? __alloc_fd+0xa7/0x130
[ 3835.927522]  [<ffffffff811b4698>] do_sys_open+0x128/0x220
[ 3835.933351]  [<ffffffff811b47ae>] SyS_open+0x1e/0x20
[ 3835.938695]  [<ffffffff8165b5ed>] system_call_fastpath+0x1a/0x1f
[ 3835.945196] ---[ end trace abc274a1f233508e ]---
[ 3835.950155] EXT4: jbd2_journal_dirty_metadata failed: handle type 5 started at line 3740, credits 16/16, errcode -30
[ 3835.961325] EXT4: jbd2_journal_dirty_metadata failed: handle type 5 started at line 3740, credits 16/16, errcode -30<2>[ 3835.972625] EXT4-fs error (device sda4) in ext4_free_blocks:4867: Journal has aborted
[ 3835.981224] EXT4-fs error (device sda4) in ext4_reserve_inode_write:4877: Journal has aborted
[ 3836.011139] EXT4-fs error (device sda4) in ext4_reserve_inode_write:4877: Journal has aborted
[ 3836.020512] EXT4-fs error (device sda4) in ext4_ext_remove_space:3018: Journal has aborted
[ 3836.036079] EXT4-fs error (device sda4) in ext4_ext_truncate:4666: Journal has aborted
[ 3836.044701] EXT4-fs error (device sda4) in ext4_reserve_inode_write:4877: Journal has aborted
[ 3836.053985] EXT4-fs error (device sda4) in ext4_orphan_del:2684: Journal has aborted
[ 3836.069403] EXT4-fs error (device sda4) in ext4_reserve_inode_write:4877: Journal has aborted