Calls to sync/fsync slow down after 30 minutes uptime

Question

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):

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:

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?

Answer 1

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