Bug 110031

Summary: Large files writes and reads to/from disk slowed down to a crawl
Product: IO/Storage Reporter: reserv0
Component: OtherAssignee: io_other
Status: NEW ---    
Severity: blocking CC: alkisg, fernando.filgueira, gurselm, hydrapolic, szg00000
Priority: P1    
Hardware: Intel   
OS: Linux   
Kernel Version: All versions after and including v4.2.0 Subsystem:
Regression: Yes Bisected commit-id:
Attachments: system info

Description reserv0 2015-12-27 10:54:44 UTC
I noticed this problem immediately after I tried to upgrade my system to the (vanilla) v4.2 kernel, and could reproduce the issue with each and every version of v4.2 and 4.3 I since tried (last version tested: v4.3.3).

Most often, when I tar (with or without compression) or, sometimes, untar (usually seen when using compressed tarballs) large archives, the file I/O to the disks (on a RAID5, 3 disks array, ext4 file system) is immensely slower (30 to 50 times (!) slower) when compared to the v4.1 (or older) kernel.

I noticed this first on a "persistent" ramdisk which is automatically saved and restored on system (re)boots, the contents being tared (without compression) to the disk on saving and untared on restoration to the ramdisk. A 800Mb ramdisk typically takes a dozen of seconds to be (un)tared with kernel v4.1, and, sometimes (not always), up to 7 minutes (!!!) to be tared by the linux v4.2/3 kernels !
I also noticed the same issue (almost everytime) when untaring large (100Mb or so) bziped archives, but also got the feeling any archive or large file operation was slower anyway with v4.2+ kernels.

To get some numbers, I added a logging feature to the ramdisk sysvinit script, so that the saving and restoration times would be logged. Here is what I got today, after several reboots with the v4.3.3 and v4.1.15 kernels (on the same system/partition and same ramdisk contents):
00:33:21 - Linux v4.1.15: Ramdisk stopped
08:51:31 - Linux v4.1.15: Starting ramdisk
08:51:44 - Linux v4.1.15: Ramdisk started
10:11:24 - Linux v4.1.15: Stopping ramdisk
10:11:31 - Linux v4.1.15: Ramdisk stopped
10:33:58 - Linux v4.1.15: Starting ramdisk
10:34:11 - Linux v4.1.15: Ramdisk started
10:35:53 - Linux v4.1.15: Stopping ramdisk
10:36:00 - Linux v4.1.15: Ramdisk stopped
10:36:53 - Linux v4.3.3: Starting ramdisk
10:37:05 - Linux v4.3.3: Ramdisk started
10:37:20 - Linux v4.3.3: Stopping ramdisk
10:37:28 - Linux v4.3.3: Ramdisk stopped
10:42:20 - Linux v4.3.3: Starting ramdisk
10:42:33 - Linux v4.3.3: Ramdisk started
10:42:43 - Linux v4.3.3: Stopping ramdisk
10:42:50 - Linux v4.3.3: Ramdisk stopped
10:53:22 - Linux v4.3.3: Starting ramdisk
10:53:34 - Linux v4.3.3: Ramdisk started
10:58:35 - Linux v4.3.3: Stopping ramdisk
10:58:48 - Linux v4.3.3: Ramdisk stopped
10:59:44 - Linux v4.3.3: Starting ramdisk
10:59:56 - Linux v4.3.3: Ramdisk started
11:03:54 - Linux v4.3.3: Stopping ramdisk
11:11:01 - Linux v4.3.3: Ramdisk stopped
11:11:52 - Linux v4.1.15: Starting ramdisk
11:12:04 - Linux v4.1.15: Ramdisk started
11:14:27 - Linux v4.1.15: Stopping ramdisk
11:14:34 - Linux v4.1.15: Ramdisk stopped
11:15:15 - Linux v4.1.15: Starting ramdisk
11:15:28 - Linux v4.1.15: Ramdisk started

I'm attaching to this report a tar archive containing various info bits about my system (kernel config files and System.map for both 4.1 and v4.3, kernels messages for today's reboots, filesystem parameters). Let me know if you need more info...

As far as I am concerned, this bug is a plain show stopper and the Linux kernels v4.2 and 4.3 are totally unusable. I'm for now stuck with v4.1 (a good thing it was made a long-lived branch...).
Comment 1 reserv0 2015-12-27 10:55:40 UTC
Created attachment 198341 [details]
system info
Comment 2 reserv0 2016-01-11 13:16:01 UTC
Kernel v4.4.0 is also affected by this show-stopper bug...

Here is a log of the 900 Mb RAM-disk saving and restoring for today's reboots (as I compiled v4.4 and rebooted several times to test it); look at the last RAM-disk stopping for v4.4.0: almost 8 minutes instead of a dozen of seconds (of course, the RAM-disk contents was the same, all along) !!!

2016-01-11 11:35:46 - Linux v4.1.15: Stopping ramdisk
2016-01-11 11:35:53 - Linux v4.1.15: Ramdisk stopped
2016-01-11 11:39:25 - Linux v4.4.0: Starting ramdisk
2016-01-11 11:39:38 - Linux v4.4.0: Ramdisk started
2016-01-11 11:51:25 - Linux v4.4.0: Stopping ramdisk
2016-01-11 11:51:39 - Linux v4.4.0: Ramdisk stopped
2016-01-11 11:52:20 - Linux v4.1.15: Starting ramdisk
2016-01-11 11:52:32 - Linux v4.1.15: Ramdisk started
2016-01-11 12:58:01 - Linux v4.1.15: Stopping ramdisk
2016-01-11 12:58:08 - Linux v4.1.15: Ramdisk stopped
2016-01-11 12:58:51 - Linux v4.4.0: Starting ramdisk
2016-01-11 12:59:03 - Linux v4.4.0: Ramdisk started
2016-01-11 13:00:25 - Linux v4.4.0: Stopping ramdisk
2016-01-11 13:00:38 - Linux v4.4.0: Ramdisk stopped
2016-01-11 13:01:20 - Linux v4.4.0: Starting ramdisk
2016-01-11 13:01:32 - Linux v4.4.0: Ramdisk started
2016-01-11 13:37:23 - Linux v4.4.0: Stopping ramdisk
2016-01-11 13:37:31 - Linux v4.4.0: Ramdisk stopped
2016-01-11 13:38:15 - Linux v4.4.0: Starting ramdisk
2016-01-11 13:38:27 - Linux v4.4.0: Ramdisk started
2016-01-11 13:46:49 - Linux v4.4.0: Stopping ramdisk
2016-01-11 13:54:55 - Linux v4.4.0: Ramdisk stopped
2016-01-11 13:55:46 - Linux v4.1.15: Starting ramdisk
2016-01-11 13:55:58 - Linux v4.1.15: Ramdisk started
Comment 3 reserv0 2016-03-01 09:27:12 UTC
First, a question, if someone reads me here: is anyone reading the bug reports ?
I am *amazed* that I seem to be the only person in the world to care about such an issue that should have jumped in the face of anyone running Linux... o.o

Second, Linux v4.4.3 is still affected by this bug, despite many fixes that went in it dealing with locking issues; I mention those, because I believe the problem stems from a deadlock somewhere in the I/O subsystem: I made another experience by performing a (parallel, with 'make -j6' on a quad-core) compilation of a large software and half down the road (I won't be surprise if the bug would be happening only after 4 Gb or so of data has been read or written to the disks), the compilation speed slows down tremendously the cores getting "stuck" one after the other (the Gnome system monitor reports them in "I/O latency", till only 25% of the processor full power gets stuck idling in I/O and almost 0% is left for "user" code execution).

I also made the same test with the same kernel, compiled for 64 bits and running on a 64 bits distro, with the exact same result.
Comment 4 Szőgyényi Gábor 2016-03-01 19:36:43 UTC
"First, a question, if someone reads me here: is anyone reading the bug reports ?"
***Yes.

But your question is relevant. I tried the "Assigned To" e-mail address of this bug, and this comes back:
*******************************************************************************
I'm sorry to have to inform you that your message could not
be delivered to one or more recipients. It's attached below.

For further assistance, please send mail to postmaster.

If you do so, please include this problem report. You can
delete your own text from the attached returned message.

The mail system

<io_other@kernel-bugs.osdl.org>: unable to look up host kernel-bugs.osdl.org:
hostname nor servname provided, or not known

*******************************************************************************
Comment 5 reserv0 2016-03-07 10:26:59 UTC
Kernel v4.4.4 is still affected by this bug.

I however tried on a second machine (since it is a show stopper bug and I have little free time for such an experimentation, I didn't bother before): the bug is not triggered on that other computer (Q6600 CPU, running the same distro): it might therefore be a hardware-dependent bug (CPU ? Motherboard ?).
Comment 6 reserv0 2016-03-16 20:38:38 UTC
Kernel v4.4.6 is still affected by this bug
Comment 7 reserv0 2016-03-24 09:34:58 UTC
Kernel v4.5 is also affected by this bug; I'm starting to desperate to see it fixed...

If only I could get a comprehensive log of the changes that went on between v4.1 and v4.2 (i.e. when that nasty bug was introduced), I could investigate, spot the potentially problematic commits and revert them one by one till I get a working kernel... Alas, unlike what happens for micro releases (e.g. ChangeLog-4.2.1), there doesn't seem to be a change log for minor releases updates (which is quite surprising and a major flaw in the Linux kernel changes traceability)...

I did have a look to the commits stats between v4.1 and v4.2 (https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/diff/?id=v4.2&id2=v4.1&context=3&ignorews=1&dt=2), but that's quite a long list of changes, which are not grouped by commit and thus quite unpractical.

If any one could kindly point me to what kind of change between v4.1 and v4.2 could induce such a bug, I'd be grateful and could probably help narrowing the issue, if not solve it...
Comment 8 reserv0 2016-04-12 22:40:19 UTC
Kernel v4.5.1 is still affected by this bug; v4.1.21 is the last working kernel for me...
Comment 9 reserv0 2016-04-20 15:39:49 UTC
v4.5.2 is still affected by this bug. :-(
Comment 10 reserv0 2016-05-05 23:23:24 UTC
v4.5.3 is still affected by this bug.

Anyone working on this, or willing to try and give me clues about what, in v4.2 changes, could have broken I/O so badly ?...
Comment 11 reserv0 2016-05-13 07:58:38 UTC
With v4.5.4, looking at the change log and noticing "writeback: Fix performance regression in wb_over_bg_thresh()", which looks really similar to what I'm experiencing here, I had the hope that the bug would have finally been solved...

Alas, v4.5.4 is still affected.
Comment 12 reserv0 2016-05-17 07:17:29 UTC
v4.6.0 is affected as well...
Comment 13 reserv0 2016-09-13 12:48:23 UTC
This issue still happens with Linux kernel v4.7.3.

Note however that I since installed another, newer Linux distribution (same lineage, same compiler version, but newer glibc: v2.20 instead of v2.13) on the affected computer, with pretty much the exact same configuration (in particular, same kernel (vanilla) and kernel config options). Under this new distro, I don't encounter the bug any more.
That bug might therefore get triggered only on a particular combination of hardware and glibc version. Probably some deadlock issue somewhere in the semaphores...

If only there were a comprehensive list of kernel changes (between v4.1 and v4.2), a commit per commit reversal would allow to pinpoints the culprit change...
Comment 14 reserv0 2016-10-28 13:13:31 UTC
Interesting news about this bug: Linux v4.8.4 fixed the issue for 64 bits kernels... But *not* for 32 bits (+PAE) ones (same system -Rosa 2012 32 and 64 bits- and kernel configuration in both cases).

If anyone knows what patch that went into v4.8.4 may affect 32 and 64 bits kernels differently, please let me know, and I'll revert the said pcath on the 64 bits system to confirm what fixed the issue (and what is left to be done for 32 bits).
Comment 15 reserv0 2017-01-09 13:16:31 UTC
Bug still present, for 32 bits kernels only, in v4.9.2.

In case it would be a lock contention in the I/O scheduler I also tried changing it from cfq to deadline, noop and even bfq, to no avail.
Comment 16 Szőgyényi Gábor 2017-03-06 20:42:26 UTC
Please try to reproduce this bug with latest kernel image.
Comment 17 reserv0 2017-03-15 23:56:55 UTC
Bug still present for 32 bits kernel in v4.10.3.

I noticed that, when I do a large software compilation, at some point (after several gigabytes of disk writes), the "I/O latency" (as reported by the Gnome system monitor applet) skyrockets, eating up all the CPU core power. If I pause the compilation (CTRL S in the terminal), then the disk writes slowly proceed and the I/O CPU consumption goes down. If I wait for all writes to finish, I can un-pause the compilation process (which will slow down again to a crawl a minute later, but will be OKeyish till then)...

Perhaps something to do with changes in disk writes caching code ?  The affected system got 32Gb of RAM (and a 32 bits kernel with PAE).
Comment 18 reserv0 2017-05-20 18:35:12 UTC
Bug still present for 32 bits kernel in v4.11.2...

We are getting closer to the EOL of the last working kernel version for me: v4.1...

Someone, please, look at this show stopper bug...
Comment 19 Alkis Georgopoulos 2017-06-22 06:15:29 UTC
reserv0, I think the bug you're describing is the same with the one I filed against Ubuntu's kernel a few weeks ago:
https://bugs.launchpad.net/ubuntu/+source/linux-hwe/+bug/1698118

I.e. that disk writes start fast but end up to 800 times slower, in all kernels 4.x, on i386 systems, with 16 GB RAM or more.
3.x kernels don't have that issue, on the same systems. And all 64bit installations on the same systems are unaffected too.

I have a very easily reproducible test case there, i.e. a script that copies /lib around 100 times. The first copy happens in 5 seconds and the 30th in 800+ seconds when the pagecache gets full.

echo 3 > /proc/sys/vm/drop_caches clears the performance issue for a few minutes.

Is this the same bug that you're experiencing? Can you reproduce my test case in your systems?

I think that the component "IO Storage" might be wrong though, it might be more related to pagecaching.
Comment 20 reserv0 2017-06-22 17:47:43 UTC
Greetings Alkis. Glad to see I'm not alone in the whole world to encounter this show stopper bug on his system...

I can indeed confirm that limiting the available RAM to 12Gb (via 'mem=12G' in the kernel command line) does prevent the problem from occurring.

However, 'echo 3 >/proc/sys/vm/drop_caches' does not achieve anything on my system and the disk writes are still dead slow after that.

It definitely looks like an issue related with free RAM usage for caching purpose...

Now to find what broke it in the gazillion of commits applied between 4.1 (last working kernel version) and 4.2.0 (first broken version)...
Comment 21 reserv0 2017-07-12 16:02:08 UTC
Bug still present for 32 bits kernel in v4.12...
Comment 22 reserv0 2017-09-19 22:33:27 UTC
Bug still present for 32 bits kernel in v4.13.2
Comment 23 reserv0 2017-11-24 18:02:12 UTC
Bug still present for 32 bits kernel in v4.14.2.
Comment 24 reserv0 2018-03-22 22:30:47 UTC
Bug still present for 32 bits kernel in v4.15.12.
Comment 25 reserv0 2018-04-19 14:23:23 UTC
Bug still present for 32 bits kernel in v4.16.3, and with the "end of life" of v4.1 getting close, I'm worried I will be left without any option to run a maintained Linux kernel on 32 bits machines with 16 Gb of memory or more...
Comment 26 reserv0 2018-06-04 14:12:48 UTC
Bug still present for 32 bits kernel in v4.17.0, and with the "end of life" of v4.1, I will be left without any upgrade path...

Pretty please, consider keeping v4.1 live till this *showstopper* bug gets solved !
Comment 27 reserv0 2018-08-17 08:59:08 UTC
Bug still present for 32 bits kernel in v4.18.1, and now, v4.1 (last working Linux kernel for 32 bits machines with 16Gb or more RAM) has gone unmaintained...
Comment 28 fernando 2020-02-03 21:11:34 UTC
Had similar problem (mine is amd64), tried every kernel shipped with ubuntu and debian and had the problem, then I dowloaded and compiled any kernel (4.16 5.1 and 5.4) from:

https://cdn.kernel.org/pub/linux/kernel/

and the problem went away.
Comment 29 reserv0 2020-02-20 12:43:03 UTC
(In reply to fernando from comment #28)
> Had similar problem (mine is amd64), tried every kernel shipped with ubuntu
> and debian and had the problem, then I dowloaded and compiled any kernel
> (4.16 5.1 and 5.4) from:
> 
> https://cdn.kernel.org/pub/linux/kernel/
> 
> and the problem went away.

I'm afraid the problem is NOT solved. The last kernel version I tried (v5.4.4) did see an improvement (i.e. the problem surfaces later, after a larger amount of data writes have occurred; e.g. in my test case compilation, it appears at 50% instead at 25% of the total compilation), but the problem is still there, and only kernels v4.1.x and older are exempt of it.

Note that the amount of RAM you are using does also impact how fast the problem arises (or whether it will arise at all). I'm using 32 Gb here.