Page 1 of 1

HD replaced, long delay in boot? [CLOSED]

Posted: 09 Sep 2019 22:31
by Cory
Hi all,

Recently I performed a fresh install: / on SSD, swap and /home on traditional harddrive (640 GB SATA, 7200 rpm). Swap and /home were to move to a 2 TB drive, but first I had to move stuff out of the way to free this drive.
Three old harddrives of various sizes in between, while waiting during the copy process from various sources on the web I gained some insight -or so I thought- on how optimize lifetime of a precious SSD. Simply said "avoid writing to SSD as much as possible by placing often-written locations to traditional but fast magnetic disks".

The original harddrive is gone now; swap, /home, and /var are located on the 2 TB harddrive and mounted from /etc/fstab using their UUID.

However, with the new harddrive in place now there is a fairly long delay in booting that wasn't there before. The kernel messages consistently show two "jumps" of some 15+ and 10+ seconds of no activity - or so it seems.
The system seems to look for something... something is initializing - Btrfs, raid (I have no RAID active, not enabled in BIOS that I know of)?

Code: Select all

...(device initialization etc)...
[    3.186811]  sdb: sdb1 sdb2 sdb3 sdb4 sdb5
[    3.187428] sd 4:0:0:0: [sdb] Attached SCSI disk
[    3.900031] raid6: sse2x1   gen()  3637 MB/s
[    3.968020] raid6: sse2x1   xor()  3086 MB/s
[    4.036020] raid6: sse2x2   gen()  4799 MB/s
[    4.104020] raid6: sse2x2   xor()  3481 MB/s
[    4.172029] raid6: sse2x4   gen()  5061 MB/s
[    4.240024] raid6: sse2x4   xor()  2430 MB/s
[    4.240025] raid6: using algorithm sse2x4 gen() 5061 MB/s
[    4.240026] raid6: .... xor() 2430 MB/s, rmw enabled
[    4.240027] raid6: using intx1 recovery algorithm
[    4.240316] xor: measuring software checksum speed
[    4.280018]    prefetch64-sse:  7537.000 MB/sec
[    4.320019]    generic_sse:  7510.000 MB/sec
[    4.320020] xor: using function: prefetch64-sse (7537.000 MB/sec)
[    4.369378] Btrfs loaded, crc32c=crc32c-generic
[   22.413916] random: crng init done
[   22.413919] random: 7 urandom warning(s) missed due to ratelimiting
[   34.998350] EXT4-fs (sda3): mounted filesystem with ordered data mode. Opts: 
[   35.154095] ip_tables: (C) 2000-2006 Netfilter Core Team
[   35.162356] systemd[1]: systemd 232 running in system mode. (+PAM +AUDIT +SEL
...(further systemd etc)...
Could anyone share thoughts about and insight in what and why is causing the delay, and if there is some way to speed things up?
Many thanks in advance!

Further info on (hard) drives, partitions and mount points:

Code: Select all

me@box:~$ sudo dmesg | grep ANSI: | more
[    2.164200] scsi 0:0:1:0: CD-ROM            LITE-ON  DVD SOHD-16P9S   FS09 PQ
: 0 ANSI: 5
[    2.456734] scsi 2:0:0:0: Direct-Access     ATA      Corsair Force LS 02.0 PQ
: 0 ANSI: 5
[    2.488676] scsi 4:0:0:0: Direct-Access     ATA      WDC WD20EZRX-00D 0A80 PQ
: 0 ANSI: 5

Code: Select all

me@box:~$ lsblk -o name,size,fstype,label,mountpoint
sda    55.9G                        
├─sda1  579M ntfs   System Reserved 
├─sda2 35.3G ntfs                   
└─sda3   20G ext4   SolydX-AMD64    /
sdb     1.8T                        
├─sdb1 29.8G swap   SWAP            [SWAP]
├─sdb2 18.6G ext4   HOME            /home
├─sdb3  9.3G ext4   VAR             /var
├─sdb4  4.7G ext4   TMP             
└─sdb5  1.8T ext4   DATA            /media/data
sr0    1024M
(sda1 and sda2 being Windows 10)

Code: Select all

me@box:~$ cat /etc/fstab
# <file system>	<mount point>	<type>	<options>	<dump>	<pass>
UUID=8b2db248-98ff-40d8-a187-0c106ce55678	/	ext4	rw,errors=remount-ro	0	1
#UUID=aa2af99a-28dd-4f82-81f9-5cc021b531ff	/home	ext4	rw,errors=remount-ro	0	2
UUID=67c2087d-a68a-4291-9c88-2ae0874ca54f	/home	ext4	rw,errors=remount-ro	0	2
#UUID=2bdbf662-7eef-4a3e-a1e3-163ef570b547	swap	swap	sw	0	0
UUID=06917b3c-3197-43a2-bb7f-35862131a1c8	swap	swap	sw	0	0

UUID=778e439a-ec94-4f12-a72f-a2b92375ea18	/var	ext4	auto,rw,relatime,noexec,nosuid	0	2

UUID=6ac0ad7f-4d32-4cec-8227-2282b548d132	/media/data	ext4	auto,rw,relatime	0	2

# RAM disks
tmpfs   /tmp                    tmpfs   defaults,noatime,mode=1777              0       0
#tmpfs   /var/cache/apt/archives tmpfs   defaults,noexec,nosuid,nodev,mode=0755 0       0
tmpfs   /var/tmp                tmpfs   defaults,noatime                        0       0
tmpfs   /var/backups            tmpfs   defaults,noatime                        0       0
# Disable /var/log/* tmpfs dirs when enabling tmpfs on /var/log
#tmpfs   /var/log                tmpfs   defaults,noatime                        0       0
#tmpfs   /var/log/apt            tmpfs   defaults,noatime,mode=0755              0       0
#tmpfs   /var/log/lightdm        tmpfs   defaults,noatime,mode=0755              0       0
#tmpfs   /var/log/samba          tmpfs   defaults,noatime,mode=0755              0       0
tmpfs   /var/log/cups           tmpfs   defaults,noatime,mode=0755               0       0
tmpfs   /var/log/ConsoleKit     tmpfs   defaults,noatime,mode=0755               0       0
tmpfs   /var/log/clamav         tmpfs   defaults,noatime,mode=0755,uid=clamav,gid=clamav 0       0
(I have left the original UUIDs in, just in case things wouldn't work out as expected)
Partition TMP is never used (yet), as /tmp is mounted as a RAM disk I do not need to worry about writes to the SSD; the same applies to part of /var.

Code: Select all

me@box:~$ mount | grep /tmp
tmpfs on /tmp type tmpfs (rw,noatime)
tmpfs on /var/tmp type tmpfs (rw,noatime)

BTW "RAM disks" was there from the fresh installation, I never changed anything - should I?

Re: HD replaced, long delay in boot?

Posted: 09 Sep 2019 23:14
by kurotsugi
we can start analyzing by using

Code: Select all

systemd-analyze blame 
systemd-analyze critical-chain

Re: HD replaced, long delay in boot?

Posted: 10 Sep 2019 18:57
by Cory
Apparently there is so much I do not know (yet, and I wonder if I ever will)...

Here you go:

Code: Select all

me@box:~$ systemd-analyze blame 
          6.925s solydxk-system-adjust.service
          5.213s NetworkManager-wait-online.service
          1.280s loadcpufreq.service
          1.169s ModemManager.service
          1.099s accounts-daemon.service
           944ms ufw.service
           828ms networking.service
           782ms upower.service
           735ms dev-sda3.device
           515ms NetworkManager.service
           481ms nmbd.service
           402ms systemd-fsck@dev-disk-by\x2duuid-778e439a\x2dec94\x2d4f12\x2da7
           402ms apt-daily.service
           401ms rtkit-daemon.service
           395ms smbd.service
           375ms systemd-logind.service
           357ms rsyslog.service
           344ms lm-sensors.service
           333ms lpd.service
           322ms systemd-fsck@dev-disk-by\x2duuid-67c2087d\x2da68a\x2d4291\x2d9c
           320ms alsa-restore.service
           316ms keyboard-setup.service
           284ms pppd-dns.service
           269ms systemd-fsck@dev-disk-by\x2duuid-6ac0ad7f\x2d4d32\x2d4cec\x2d82
           253ms apt-daily-upgrade.service
           252ms console-kit-log-system-start.service
           250ms lightdm.service
           227ms systemd-journald.service
           207ms exim4.service
           173ms systemd-udev-trigger.service
           164ms cpufrequtils.service
           157ms colord.service
           155ms decnet.service
           153ms media-data.mount
           131ms packagekit.service
           130ms polkit.service
           123ms hddtemp.service
           120ms systemd-timesyncd.service
           114ms user@1000.service
           103ms systemd-udevd.service
            93ms udisks2.service
            82ms avahi-daemon.service
            71ms systemd-modules-load.service
            61ms run-rpc_pipefs.mount
            61ms binfmt-support.service
            60ms systemd-user-sessions.service
            59ms systemd-journal-flush.service
            57ms rc-local.service
            57ms dev-disk-by\x2duuid-06917b3c\x2d3197\x2d43a2\x2dbb7f\x2d3586213
            52ms systemd-tmpfiles-setup-dev.service
            52ms systemd-random-seed.service
            51ms plymouth-start.service
            49ms plymouth-quit-wait.service
            47ms minissdpd.service
            41ms var.mount
            41ms systemd-remount-fs.service
            40ms home.mount
            40ms plymouth-quit.service
            36ms var-backups.mount
            33ms openvpn.service
            32ms kmod-static-nodes.service
            32ms sys-kernel-debug.mount
            31ms var-log-cups.mount
            30ms var-tmp.mount
            30ms console-kit-daemon.service
            30ms dev-hugepages.mount
            30ms systemd-tmpfiles-setup.service
            29ms plymouth-read-write.service
            27ms var-log-clamav.mount
            26ms systemd-update-utmp.service
            25ms nfs-config.service
            23ms systemd-sysctl.service
            23ms var-log-ConsoleKit.mount
            21ms rpcbind.service
            20ms proc-sys-fs-binfmt_misc.mount
            16ms dev-mqueue.mount
            15ms systemd-update-utmp-runlevel.service
            11ms console-setup.service
             8ms tmp.mount

Code: Select all

me@box:~$ systemd-analyze critical-chain
The time after the unit is active or started is printed after the "@" character.
The time the unit takes to start is printed after the "+" character. @9.665s
└─ @9.665s
  └─ @8.183s
    └─getty@tty1.service @8.182s
      └─rc-local.service @7.965s +57ms
        └─ @7.941s
          └─NetworkManager-wait-online.service @2.726s +5.213s
            └─NetworkManager.service @2.208s +515ms
              └─dbus.service @1.718s
                └─ @1.655s
                  └─ @1.655s
                    └─avahi-daemon.socket @1.655s
                      └─ @1.647s
                        └─systemd-timesyncd.service @1.526s +120ms
                          └─var-tmp.mount @1.406s +30ms
                            └─var.mount @1.329s +41ms
                              └─systemd-fsck@dev-disk-by\x2duuid-778e439a\x2dec94\x2d4f12\x2da72f\x2da2b92375ea18.service @923ms +402ms
                                └─dev-disk-by\x2duuid-778e439a\x2dec94\x2d4f12\x2da72f\x2da2b92375ea18.device @843ms
Meanwhile I'm trying to do some research on what message this is trying to convey.
I think I understand what it is about, but the deeper meaning is yet beyond my grasp :-\

Re: HD replaced, long delay in boot?

Posted: 10 Sep 2019 20:54
by kurotsugi
your system reach graphic target in less than 10 secs. that's fast. did I missed something here? the only delaying factor is network stack which completely normal if you have samba. everything seems normal for me

Re: HD replaced, long delay in boot?

Posted: 10 Sep 2019 22:26
by Cory
Thank you for you evaluation - very much appreciated!

Maybe you are right and I shouldn't bother (I do not complain, don't want it to look like I am complaining anyway).
The thing is, when spoiled with fast boot times, any delay where "nothing seems to happen" for even a short period of some seconds, and I cannot explain what is going on, is perceived as long.
Add to that the swap of disks, not knowing exactly if what I had done is optimally correct, and you have this situation where I "talked myself into potentially having a problem".

Seeing -and slowly learning to interpret- the output of these tools, I don't think I should spend more precious time on this...

Re: HD replaced, long delay in boot?

Posted: 10 Sep 2019 23:27
by kurotsugi
I think it's an IO bottleneck. try to disable swap and see whether if improve the speed. a hybrid system won't perform as fast a SSD. though, compared to old techs that's still blazing fast. my system normally needs ~3 minutes to complete the boot. there's also a lag after login when the bottleneck is quite severe

btw, it's easy to read the data. take a look into items with (+) symbol. in our case there are 3 items. there's only one above 1 secs. that should be the main culprit. the other stuff is fsck and systemd clock sync, but both of them are under 1 secs so you can ignore it

Re: HD replaced, long delay in boot?

Posted: 13 Sep 2019 13:42
by Cory
Thank you for your help in the analysis and explanation, master kurotsugi - very much appreciated!

An I/O bottleneck would not surprise me. Indeed this system is old - it dates back to August 2008 when I put it together.
(The components I selected for low power consumption, in it's original config it draws under 100 W with one conventional 3,5" "green" harddrive active. It is still good enough for me as I am no gamer, developer or graphics designer. The only compute-intensive work is editing audio recordings, the somewhat long time it takes to write those files is not bothering me too much - not enough to replace this box for something marginally faster, though. And, tbh, I rather spend my hard-earned money for something more relevant to life than a computer. Add to that the waste it generates -even when properly recycled- to dump this box.)
I have now disabled swap, and have yet to see if I get away with this during audio editing with ocenaudio (which, btw, I find a very nice and clearly designed utility for simple cutting and pasting of audio).

Hardware details of the subject:

Code: Select all

me@box:~$ inxi -SMCmGN
System:    Host: box Kernel: 4.9.0-9-amd64 x86_64 (64 bit) Desktop: Xfce 4.12.3 Distro: SolydX 9 64-bit
Machine:   Device: desktop Mobo: MICRO-STAR model: K9A2VM (MS-7501) v: 1.0 BIOS: American Megatrends v: V1.12 date: 08/24/2010
CPU:       Dual core AMD Athlon 64 X2 5200+ (-MCP-) cache: 1024 KB 
           clock speeds: max: 2700 MHz 1: 1000 MHz 2: 1000 MHz
Memory:    Used/Total: 1092.6/5719.4MB
           Array-1 capacity: 8 GB devices: 4 EC: None
           Device-1: DIMM0 size: 2 GB speed: 400 MHz type: DDR2
           Device-2: DIMM1 size: 2 GB speed: 400 MHz type: DDR2
           Device-3: DIMM2 size: 1 GB speed: 400 MHz type: DDR2
           Device-4: DIMM3 size: 1 GB speed: 400 MHz type: DDR2
Graphics:  Card: Advanced Micro Devices [AMD/ATI] RS780 [Radeon HD 3200]
           Display Server: X.Org 1.19.2 drivers: ati,radeon (unloaded: modesetting,fbdev,vesa)
           Resolution: 1680x1050@59.95hz
           GLX Renderer: Gallium 0.4 on AMD RS780 (DRM 2.49.0 / 4.9.0-9-amd64, LLVM 3.9.1)
           GLX Version: 3.0 Mesa 13.0.6
Network:   Card: 3Com 3c905C-TX/TX-M [Tornado] driver: 3c59x
The onboard NIC seemed broken sometime. Back then I had little time to put much effort in it, just added this 3Com card I had laying around - still works well.

With the complete bootup time to userspace well under 1 minute (around 50 seconds) and shutdown under 5 seconds, I think there is little to no need to optimize further - unless someone (kurotsugi?) knows of something very obvious and easy (that is, within my grasp of limited low-level knowledge). Add to that my limited spare time that I can dedicate to this.

To cut a long story short: I better accept the good that I have and not break things...

edit: corrections and additions

Re: HD replaced, long delay in boot? [closed]

Posted: 13 Sep 2019 14:24
by Cory
Remember I wrote "...and not break the good that I have"?
Somehow I did break things: /var/lib/dpkg is gone altogether, I have no way to update / install new.
Yet another subject I'll need help on - please stand by while I do some research!

edit: Something along the way went seriously wrong without showing as such... until now.
According to FHS and some other sources, /var contains among others important administrative data. Not only is /var/lib/dpkg missing from my installation, compared to another machine running SolydX 9 there should be a whole list of directories - one for (just about) every installed package. And there's more: /var itself is missing some directories too. And "of course": no backups of these files - "should the need arise, I can always perform a clean install".
As I cannot update nor install new packages, I'm not gambling and will be performing a clean install.

Case closed.

Re: HD replaced, long delay in boot? [CLOSED]

Posted: 17 Sep 2019 00:07
by Cory
Just to update y'all on the progress: clean install of SolydX 9 x64 2019-2 finished without issues.

The results are now

Code: Select all

me@box:~$ systemd-analyze blame
          7.713s NetworkManager-wait-online.service
          7.270s solydxk-system-adjust.service
          1.011s ufw.service
           850ms networking.service
           822ms upower.service
           781ms packagekit.service
           760ms dev-sda3.device
           485ms loadcpufreq.service
           431ms systemd-fsck@dev-disk-by\x2duuid-6ac0ad7f\x2d4d32\x2d4cec\x2d82
           428ms plymouth-read-write.service
           350ms ModemManager.service
           349ms keyboard-setup.service
           268ms systemd-journald.service
           221ms nmbd.service
           215ms systemd-fsck@dev-disk-by\x2duuid-778e439a\x2dec94\x2d4f12\x2da7
           213ms lightdm.service
           212ms systemd-fsck@dev-disk-by\x2duuid-6560e52d\x2ddf2c\x2d4a3c\x2d82
           185ms NetworkManager.service
           175ms rsyslog.service
           174ms accounts-daemon.service
           173ms systemd-logind.service
           161ms systemd-udev-trigger.service
           159ms exim4.service

Code: Select all

me@box:~$ systemd-analyze critical-chain
The time after the unit is active or started is printed after the "@" character.
The time the unit takes to start is printed after the "+" character. @10.615s
└─ @10.615s
  └─decnet.service @10.261s +110ms
    └─ @10.219s
      └─NetworkManager-wait-online.service @2.504s +7.713s
        └─NetworkManager.service @2.317s +185ms
          └─dbus.service @2.149s
            └─ @2.134s
              └─ @2.134s
                └─acpid.path @2.134s
                  └─ @2.132s
                    └─sys-fs-fuse-connections.mount @5.458s +16ms
                      └─systemd-modules-load.service @174ms +55ms
                        └─system.slice @171ms
                          └─-.slice @150ms
... which is not bad, considering this is dated hardware.
Getting the network ready is quite slow, I feel I should investigate this further - but lack time to do so.

In the process of reinstallation I tried to enable the on-board Realtek NIC, and to my surprise it is not broken.
Although, looking at the timing, I think is it a bit less efficient than the 3C590 PCI card I used before. Doesn't bother me, I leave it as-is for now.

Code: Select all

me@box:~$ inxi -SCMNx
System:    Host: box Kernel: 4.9.0-11-amd64 x86_64 (64 bit gcc: 6.3.0)
           Desktop: Xfce 4.12.3 (Gtk 2.24.30) Distro: SolydX 9 64-bit
Machine:   Device: desktop Mobo: MICRO-STAR model: K9A2VM (MS-7501) v: 1.0
           BIOS: American Megatrends v: V1.12 date: 08/24/2010
CPU:       Dual core AMD Athlon 64 X2 5200+ (-MCP-) cache: 1024 KB
           flags: (lm nx sse sse2 sse3 svm) bmips: 7200
           clock speeds: max: 2700 MHz 1: 1800 MHz 2: 1800 MHz
Network:   Card: Realtek RTL8111/8168/8411 PCI Express Gigabit Ethernet Controller
           driver: r8169 v: 2.3LK-NAPI port: e800 bus-ID: 03:00.0
As for the storage:

Code: Select all

me@box:~$ lsblk -o name,type,rm,size,mountpoint
sda    disk  0 55.9G 
├─sda1 part  0  579M 
├─sda2 part  0 35.3G 
└─sda3 part  0   20G /
sdb    disk  0  1.8T 
├─sdb1 part  0 29.8G 
├─sdb2 part  0 18.6G /home
├─sdb3 part  0  9.3G /var
├─sdb4 part  0  4.7G 
└─sdb5 part  0  1.8T /media/data
sr0    rom   1 1024M 
sr1    rom   1 1024M 

Code: Select all

me@box:~$ mount | grep /sd
/dev/sda3 on / type ext4 (rw,relatime,errors=remount-ro,data=ordered)
/dev/sdb2 on /home type ext4 (rw,relatime,errors=remount-ro,data=ordered)
/dev/sdb3 on /var type ext4 (rw,nosuid,noexec,relatime,data=ordered)
/dev/sdb5 on /media/data type ext4 (rw,relatime,errors=remount-ro,data=ordered)
As you can see I have /var mounted in a separate partition. That caused some inconsistency at first, as per the default installation var is normally under / - except some subdirectories that are mounted as tmpfs (the live installer automatically recognized the SSD where / resides, and took care of this? I have to browse through the installer script yet... dunno if I'm getting to this anytime soon)
Anyway, I manually synced /var with partition var and then mounted (in fstab) partition var as /var - seems to work OK now.