Slow boot due to repetitive file system scanning since Sept 9th

[doctordruidphd]

Problem: Booting has slowed down due to file system scanning on bootup.

This problem began after an update last week, apparently on Sept. 8. What happens is that when the bootup process reaches the drive mounting stage, the whole thing slows down. It actually runs the file system check on at least one file system every boot, even though the threshold has been set with tune2fs into the 30's. Nothing has been changed in fstab.

What I have discovered:

I tried dismounting one fo the file systems, running and e2fsck -f, (these are all ext4 systems) then remounting. If I do that, using dumpe2fs I find that the last mount date/time and count are correct. I can dismount and remount, and the mount count advances as expected. If I then shut down and reboot, it runs a scan on that system at bootup, and when I check with dumpe2fs, I find the last mount time has been reset to Thu Sep 8th, and the mount count set to 1. Something, therefore, is seriously messed up.

Looking at the dpkg logs, starting with Sept. 7th, for what might have been updated, I see the following, none of which jump out at me as being related to file system mounting:


greenman@Crynfyd16.04 /var/log$ grep "2016-09-07" dpkg.log | grep upgrade
2016-09-07 06:27:07 upgrade chromium-browser-l10n:all 51.0.2704.79-0ubuntu0.16.04.1.1242 52.0.2743.116-0ubuntu0.16.04.1.1250
2016-09-07 06:27:09 upgrade chromium-browser:amd64 51.0.2704.79-0ubuntu0.16.04.1.1242 52.0.2743.116-0ubuntu0.16.04.1.1250
2016-09-07 06:27:18 upgrade chromium-codecs-ffmpeg-extra:amd64 51.0.2704.79-0ubuntu0.16.04.1.1242 52.0.2743.116-0ubuntu0.16.04.1.1250
2016-09-07 06:27:19 upgrade p11-kit-modules:i386 0.23.2-3 0.23.2-5~ubuntu16.04.1
2016-09-07 06:27:20 upgrade p11-kit-modules:amd64 0.23.2-3 0.23.2-5~ubuntu16.04.1
2016-09-07 06:27:21 upgrade libp11-kit-dev:amd64 0.23.2-3 0.23.2-5~ubuntu16.04.1
2016-09-07 06:27:22 upgrade libp11-kit0:amd64 0.23.2-3 0.23.2-5~ubuntu16.04.1
2016-09-07 06:27:23 upgrade libp11-kit0:i386 0.23.2-3 0.23.2-5~ubuntu16.04.1
2016-09-07 06:27:24 upgrade libegl1-mesa-dev:amd64 11.2.0-1ubuntu2.1 11.2.0-1ubuntu2.2
2016-09-07 06:27:25 upgrade libwayland-egl1-mesa:amd64 11.2.0-1ubuntu2.1 11.2.0-1ubuntu2.2
2016-09-07 06:27:26 upgrade libgbm1:amd64 11.2.0-1ubuntu2.1 11.2.0-1ubuntu2.2
2016-09-07 06:27:26 upgrade libegl1-mesa:amd64 11.2.0-1ubuntu2.1 11.2.0-1ubuntu2.2
2016-09-07 06:27:27 upgrade libgl1-mesa-dri:amd64 11.2.0-1ubuntu2.1 11.2.0-1ubuntu2.2
2016-09-07 06:27:29 upgrade libgl1-mesa-dri:i386 11.2.0-1ubuntu2.1 11.2.0-1ubuntu2.2
2016-09-07 06:27:31 upgrade libegl1-mesa-drivers:amd64 11.2.0-1ubuntu2.1 11.2.0-1ubuntu2.2
2016-09-07 06:27:32 upgrade libgl1-mesa-dev:amd64 11.2.0-1ubuntu2.1 11.2.0-1ubuntu2.2
2016-09-07 06:27:33 upgrade mesa-common-dev:amd64 11.2.0-1ubuntu2.1 11.2.0-1ubuntu2.2
2016-09-07 06:27:35 upgrade libosmesa6:i386 11.2.0-1ubuntu2.1 11.2.0-1ubuntu2.2
2016-09-07 06:27:36 upgrade libosmesa6:amd64 11.2.0-1ubuntu2.1 11.2.0-1ubuntu2.2
2016-09-07 06:27:37 upgrade libgles2-mesa-dev:amd64 11.2.0-1ubuntu2.1 11.2.0-1ubuntu2.2
2016-09-07 06:27:37 upgrade libgles2-mesa:amd64 11.2.0-1ubuntu2.1 11.2.0-1ubuntu2.2
2016-09-07 06:27:39 upgrade libgl1-mesa-glx:i386 11.2.0-1ubuntu2.1 11.2.0-1ubuntu2.2
2016-09-07 06:27:41 upgrade libgl1-mesa-glx:amd64 11.2.0-1ubuntu2.1 11.2.0-1ubuntu2.2
2016-09-07 06:27:42 upgrade libgles1-mesa:amd64 11.2.0-1ubuntu2.1 11.2.0-1ubuntu2.2
2016-09-07 06:27:43 upgrade libglapi-mesa:amd64 11.2.0-1ubuntu2.1 11.2.0-1ubuntu2.2
2016-09-07 06:27:44 upgrade libglapi-mesa:i386 11.2.0-1ubuntu2.1 11.2.0-1ubuntu2.2
2016-09-07 06:27:44 upgrade metacity:amd64 1:3.18.5-0ubuntu0.1 1:3.18.7-0ubuntu0.1
2016-09-07 06:27:45 upgrade libmetacity-private3a:amd64 1:3.18.5-0ubuntu0.1 1:3.18.7-0ubuntu0.1
2016-09-07 06:27:46 upgrade metacity-common:all 1:3.18.5-0ubuntu0.1 1:3.18.7-0ubuntu0.1
2016-09-07 06:27:50 upgrade libnm-gtk0:amd64 1.2.0-0ubuntu0.16.04.3 1.2.0-0ubuntu0.16.04.4
2016-09-07 06:27:50 upgrade libnm-gtk-common:all 1.2.0-0ubuntu0.16.04.3 1.2.0-0ubuntu0.16.04.4
2016-09-07 06:27:51 upgrade libxatracker2:amd64 11.2.0-1ubuntu2.1 11.2.0-1ubuntu2.2
2016-09-07 06:27:52 upgrade mesa-vdpau-drivers:amd64 11.2.0-1ubuntu2.1 11.2.0-1ubuntu2.2
2016-09-07 06:27:53 upgrade p11-kit:amd64 0.23.2-3 0.23.2-5~ubuntu16.04.1

greenman@Crynfyd16.04 /var/log$ grep "2016-09-08" dpkg.log | grep upgrade
2016-09-08 09:37:00 upgrade libgtkspell3-3-dev:amd64 3.0.8-1~xenialppa1 3.0.9-1~xenialppa2
2016-09-08 09:37:01 upgrade libgtkspell3-3-0:amd64 3.0.8-1~xenialppa1 3.0.9-1~xenialppa2
2016-09-08 09:37:02 upgrade gir1.2-gtkspell3-3.0:amd64 3.0.8-1~xenialppa1 3.0.9-1~xenialppa2

greenman@Crynfyd16.04 /var/log$ grep "2016-09-09" dpkg.log | grep upgrade
2016-09-09 06:24:22 upgrade libgtkspellmm-3.0-dev:amd64 3.0.4-1~xenialppa1 3.0.5-1~xenialppa2
2016-09-09 06:24:23 upgrade accountsservice:amd64 0.6.40-2ubuntu11.1 0.6.40-2ubuntu11.2
2016-09-09 06:24:24 upgrade libaccountsservice0:amd64 0.6.40-2ubuntu11.1 0.6.40-2ubuntu11.2
2016-09-09 06:24:25 upgrade libimlib2:amd64 1.4.7-1build1 1.4.7-1ubuntu0.1
2016-09-09 06:24:26 upgrade libqtspell-qt5-dev:amd64 0.8.1-1~xenialppa2 0.8.2-1~xenialppa1
2016-09-09 06:24:27 upgrade libqtspell-qt5-0:amd64 0.8.1-1~xenialppa2 0.8.2-1~xenialppa1

Addendum: I tried booting with a 16.04 system that was backed up a couple of weeks ago, and after rescanning, the file systems mount normally, But then when booting the updated Xenial, the problem starts again. So it's got to be something from an update.

[GreyGeek]

How long is your time from bootup to login screen?

[doctordruidphd]

Probably adds two or three minutes; doesn't really matter. It should not be running a full check on every boot, and it should not be resetting the access date to Sept 8th, and it should not be resetting the mount count to 1 each time.

FYI: The "date" and "cal" commands are both showing the correct date and time, so not a problem there.

Additional: The backup Xenial system that works properly was last updated on August 30, so it's definitely something that happened after that. Also Debian Jessie boots as expected; on the first boot after the problematic Xenial, it rescans all of this disks, and after that, boots correctly every time. So something is broken in the updated Xenial.

[Snowhog]

The condition you are describing/experiencing could happen if the file time stamps and CMOS date time are out of sync, specifically, the CMOS date/time is reading earlier than the last file date/time stamp. Is this a desktop PC? They all have CMOS batteries, and they don't last forever.

[doctordruidphd]

The condition you are describing/experiencing could happen if the file time stamps and CMOS date time are out of sync, specifically, the CMOS date/time is reading earlier than the last file date/time stamp. Is this a desktop PC? They all have CMOS batteries, and they don't last forever.

Yes, but if that were true, the other systems would be having the same problems, I would think.

[Snowhog]

Not necessarily. Filesystem checks are very sensitive to such date/time discrepancies. When the CMOS battery 'dies', the PC system date defaults to a much earlier date/time than it actually is. The check as to when to scan the filesystems is based on the date of the 'last scan' and the 'current date'. IF the CMOS date reports a 'default date' -- happens when the battery dies -- then a filesystem scan always happens every boot. I'm not saying that this is what is causing your issue; just that it can be a cause.

[doctordruidphd]

Thanks for your suggestions, Snowhog.

This is TENTATIVELY solved, and I say only tentatively because I have not found the cause of the problem. Could be sidhe, lunar oscillations of Io, or some other accursed thing.

What I did was to copy the old pre-problem Xenial to a new parition, do the dist upgrade, copy over config files, etc., and reboot, several times. Problem gone, it boots normally, incrementing the mount counts and last mount times as expected.

What I did find, thanks to your suggestion, was that systemd-timesyncd.service was not running, and in fact the hardware clock was out of sync. Not defaulted as in dead battery, but still out of whack. For some reason there was an entry for something related to vbox in its config file, which I deleted as I hardly ever use it, and now it starts properly at bootup, syncing the clock as it should.

I tried booting the problematic Xenial system, and it once again hosed the file system mount counts and times. So it's hopelessly borked, though I cannot find where or why. Bloody sidhe, must have forgotten to leave food scraps by the creek last full moon. Unless someone has a better explanation, I'll go with that, and just replace the broken system with the one that now works.

[vinnywright]

Bloody sidhe, must have forgotten to leave food scraps by the creek last full moon. Unless someone has a better explanation, I'll go with that, and just replace the broken system with the one that now works.

I was under the impression that only the lower Fey did that ,,,,,,,, not the Sidhe .

at any rate I am sure they like messing with Druid's

perhaps it's time to re-ward the house ⁜


VINNY

[doctordruidphd]

The Feast of Samhain approaches -- all will be well then. So does 16.10; we shall see.