7

After 30 minutes of uptime using Ubuntu 14.04 with a hybrid SSD I see many processes blocking IO using iotop. This is during disk writes, for example if I open and close an empty file in gedit it can take 2 seconds to close down due to dconf writing settings, this effects other apps in a similar way; slowing the whole system down quite severely.

Using strace I managed to trace this back to an fsync call and from there managed to reproduce it using the sync command.

So to recap, simply running sync from the terminal repeatedly can take on the order of 1 - 2 seconds but ONLY after 30 minutes uptime.

To prove this I made a script that outputs uptime in seconds against time taken to execute sync, and ran it every second :

while true;
do
cat /proc/uptime | awk '{printf "%f ",$1}'; /usr/bin/time -f '%e' sync;
sleep 1;
done;

I ran the above script, waited around an hour (system was left idle) and then plotted the results in gnuplot (y = time in seconds to execute sync, x = uptime in seconds):

sync time plotted against uptime

The point in time where the graph spikes is around 1780 (1780/60 = roughly 30 minutes).

Nothing should be writing to the disk at this time apart from the script, so there should be next to nothing in the page cache after the first sync each subsequent sync will be writing exactly what's being written to the script which will be roughly 100 bytes or so.

This issue persists after reboots; for example - if I wait 30 minutes for the slowdown then reboot, the slowdown will still be there. If I powerdown then reboot the issue disappears until 30 minutes later.

Another curiosity is that when I examined the above graph and zoomed in on an area where the slowdown is occurring I got this:

sync time plotted against uptime, zoomed in

The peaks and troughs repeat - this occurs almost exactly every 10 seconds from trough to trough and also the peak kinks as it comes down.

I've also ran hdparm tests (hdparm -t /dev/sda and hdparm -T /dev/sda) before the slowdown :

/dev/sda:
Timing cached reads:   23778 MB in  2.00 seconds = 11900.64 MB/sec
/dev/sda:
Timing buffered disk reads: 318 MB in  3.01 seconds = 105.63 MB/sec

and during the slowdown:

/dev/sda:
 Timing cached reads:     2 MB in  2.24 seconds = 915.50 kB/sec
/dev/sda:
Timing buffered disk reads: 300 MB in  3.01 seconds =  99.54 MB/sec

Showing that actual disk reads aren't being effected but cached reads are, could that mean that this is to do with the system bus and not the HD after all?

Here's the solutions I've tried :

  • Change the spindown settings of the HD maybe the HD was going into power savings mode:

    hdparm /dev/sda -S252 #(set it to 5 hours before spindown)
    
  • Change the filesystem's journalling type to writeback rather than ordered so that we get performance improvements - this isn't solving the problem though as it doesn't explain the 30 minutes slowdown-free uptime.

  • Disabled CRON as it seems to be occuring after a round 30 minutes.

  • CPU usage is fine and is completely idle so no processes can be blamed however I've tried shutting down every service including the session manager (lightdm) this does nothing as I believe the issue is lower level.

  • Analysing any new processes coming in at 30 minutes indicates no changes - I've diffed the output of PS before and after and there's no difference.

This only started occuring about 2 weeks ago, nothing was installed and no updates were done around that time. I'm thinking this issue is much lower level so would really appreciate some help here as I'm clueless, even pointing me in the right direction would be helpful - for example is there a way to examine what's being flushed out the page cache?

Write caching is enabled on the disk in question, I've also tried disabling write barriers. SMART data on the HD indicates no problems with the HD itself however I have my suspicions it's the HD doing something mysterious as it persists after reboots.

EDIT:

I've done :

watch -n 1 cat /proc/meminfo

... to see how the memory changes particularly looking at the dirty row and the writeback row which I believe is the HDs disk buffer. They all stay at zero for the most part highest being probably 300kb. Calling sync flushes these as expected back to 0 but during the slowdown calling sync when there is zero dirty pages and zero kb in the disk buffer still locks IO. What else could sync be doing if there's nothing to flush out the page cache and write cache?

  • What file systems are you using? – peterph Nov 1 '14 at 22:48
  • ext4, entry in fstab: /dev/mapper/ubuntu-root / ext4 errors=remount-ro 0 1 – alex.p Nov 1 '14 at 22:51
  • You can try a warm boot after 15 minutes uptime. Or keep the system at the boot screen for 15 minutes, or paused mid-boot, the disk spinning, before completing the boot. If the next spike is after another 15 minutes, it's the hard disk. If it's after 30 full minutes from boot completion, it's something in the OS (barring some strange on-boot magic disk timer reset on the OS part). – LSerni Nov 1 '14 at 22:56
  • Thanks for the suggestions, the drive is encrypted and I've booted to the point where the drive is mounted as an encrypted device and left it at the password prompt, then booted after 15 minutes. I'm thinking this would have the same effect as you've suggested and it only requires 15 minutes to have the same effect after mounting so I'd agree with you on it being a possible HD issue although I suppose some part of the kernel is alive at that point as well. – alex.p Nov 1 '14 at 23:33
  • 2
    @KjetilJorgensen you've solved it! Or at least directed me to the answer. The problem appeared to be because of SMART data being enabled for the HD, switching this off with sudo smartctl --smart=off /dev/sda made the issue go away. Interestingly I've switched SMART data back on and the issue does not persist so I can only presume the SMART data was in some kind of inconsistent state and switching it off and on again reset it. If you add it as an answer I'll accept your answer. Thanks for the help very much appreciated. – alex.p Nov 5 '14 at 12:32
3
+50

The symptoms are very consistent with a mostly saturated IO system, however having for the most part ruled out IO load from the OS/userspace side, another possibility is the drive running self-tests on itself, which may include reading from all the sectors. This should be queryable/tunable from smartctl (At least one place being smartctl -c for querying).

As for why it's coming and going and started suddenly now:

  • The drive has passed a certain stage in it's life (number of sectors written, time spun up, etc.) and the firmware on the drive have triggered one of these scans
  • I believe this also can be triggered via smartctl, so it's possible some automated process triggered it
  • Having one of these scans triggered and flagged as either in progress or started, when the drive has spent a certain amount of time powered on, it's re-triggered either from the beginning or to resume where it left off

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.