dietpi-boot.service taking 40+ seconds on rpi3B and pinea64 Topic is solved

[kamilmirza]

@Joulinar
well I tried setting NTP as Gateway but that failed earlier because my router was not responding to NTP requests when enabled
reconfigured NTP server on my router and changed dietpi NTP mode to Gateway, now its responding to NTP requests

boot time drastically reduced to 2-8 seconds

though DHCP is taking more time versus STATIC IP

with DHCP IP

Code: Select all

root@pihole:~# systemd-analyze blame
          8.380s dietpi-boot.service

with STATIC IP

Code: Select all

root@pihole:~# systemd-analyze blame
          2.358s dietpi-boot.service
          
root@pihole:~# journalctl -u systemd-timesyncd
-- Logs begin at Tue 2020-01-21 02:42:09 PKT, end at Tue 2020-01-21 02:50:02 PKT. --
Jan 21 02:42:11 pihole systemd[1]: Starting Network Time Synchronization...
Jan 21 02:42:12 pihole systemd[1]: Started Network Time Synchronization.
Jan 21 02:42:21 pihole systemd-timesyncd[532]: Synchronized to time server for the first time 192.168.0.1:123 (192.168.0.1).      Jan 21 02:42:21 pihole systemd[1]: Stopping Network Time Synchronization...
Jan 21 02:42:21 pihole systemd[1]: systemd-timesyncd.service: Succeeded.
Jan 21 02:42:21 pihole systemd[1]: Stopped Network Time Synchronization.

[Joulinar]

ahh cool. so your system is now booting much faster and still have time sync activated. correct?

[kamilmirza]

ahh cool. so your system is now booting much faster and still have time sync activated. correct?

yes

dietpi-config > Advanced Options > Time Sync Mode > 2 : Boot + Daily
dietpi-config > Network Options: Misc > NTP Mirror > Gateway

[MichaIng]

I wonder why Type=forking changed anything... Currently it is Type=oneshot which should have exactly the same result: In both cases follow-up units can only start ofter the main process exited.
What I wonder as well is that the time sync is done as background job, hence it should not delay dietpi-boot finish. Looks like I need to do some testing to verify this.

However yeah it is generally recommended to set the NTP mirror to local gateway (router), which in 99% servers as NTP server with cache and is hence the way fastest solution. It must stay enabled, otherwise you will earlier or later run into issues when connecting to SSL/TLS resources and certificate timestamps do not match anymore.

Not sure if I got everything correct, does the router not serve as NTP server, if you disabled DHCP (enabled static IP)? There might be few routers which have some strict rules about this, but usually:
- Simply assign the same IP + gateway + DNS that you got via DHCP as static IP/values, e.g. dietpi-config adapter menu has this "copy" option.
- If the router has trouble with this, it might be possible to assign a static IP that is outside the DHCP range but within the same subnet. E.g. DHCP server assigns IPs 192.168.178.2 - 192.168.178.200, then assign 192.168.178.201 as static IP.
- Bad if a router has problems with both of the above, and even blocks NTP requests for clients then .

[Joulinar]

@MichaIng
The whole topic is quite strange. I discovered it some weeks ago as I noticed that my Demo VM's takes quite some time to reboot. I checked my RPi3B+ and RPi4B as well and found the same behavior. NTP time sync takes up to 40 sec to complete. However I'm sure this was not the case in the past. Even more strange, the behavior seems to disappear after a while. I tried a lot of thinks in meantime but could not figure out what triggers NTP to take that long during boot. All my systems are using my Internet Router as NTP server (Gateway) now. However they are behaving different.

Demo VM1

Code: Select all

Jan 22 23:06:01 DietPiVM1 systemd[1]: Starting Network Time Synchronization...
Jan 22 23:06:01 DietPiVM1 systemd[1]: Started Network Time Synchronization.
Jan 22 23:06:09 DietPiVM1 systemd-timesyncd[550]: Synchronized to time server for the first time 192.168.0.1:123 (192.168.0.1).
Jan 22 23:06:09 DietPiVM1 systemd[1]: Stopping Network Time Synchronization...
Jan 22 23:06:09 DietPiVM1 systemd[1]: systemd-timesyncd.service: Succeeded.
Jan 22 23:06:09 DietPiVM1 systemd[1]: Stopped Network Time Synchronization.

root@DietPiVM1:~# systemd-analyze blame
          2.691s dev-sda1.device
          1.419s keyboard-setup.service
          1.333s dietpi-preboot.service
          1.231s mariadb.service

RPi3B+

Code: Select all

Jan 22 23:06:03 DietPi3 systemd[1]: Starting Network Time Synchronization...
Jan 22 23:06:04 DietPi3 systemd[1]: Started Network Time Synchronization.
Jan 22 23:06:44 DietPi3 systemd-timesyncd[448]: Synchronized to time server for the first time 192.168.0.1:123 (192.168.0.1).
Jan 22 23:06:45 DietPi3 systemd[1]: Stopping Network Time Synchronization...
Jan 22 23:06:45 DietPi3 systemd[1]: systemd-timesyncd.service: Succeeded.
Jan 22 23:06:45 DietPi3 systemd[1]: Stopped Network Time Synchronization.

root@DietPi3:~# systemd-analyze blame
         34.163s dietpi-boot.service
          2.019s mariadb.service
          1.279s php7.3-fpm.service
          1.266s dietpi-preboot.service
          1.058s dev-mmcblk0p2.device

RPi4B

Code: Select all

Jan 22 23:04:51 DietPi4 systemd[1]: Starting Network Time Synchronization...
Jan 22 23:04:51 DietPi4 systemd[1]: Started Network Time Synchronization.
Jan 22 23:05:01 DietPi4 systemd-timesyncd[617]: Timed out waiting for reply from 192.168.0.1:123 (192.168.0.1).
Jan 22 23:05:43 DietPi4 systemd-timesyncd[617]: Synchronized to time server for the first time 192.168.0.1:123 (192.168.0.1).
Jan 22 23:05:43 DietPi4 systemd[1]: Stopping Network Time Synchronization...
Jan 22 23:05:43 DietPi4 systemd[1]: systemd-timesyncd.service: Succeeded.
Jan 22 23:05:43 DietPi4 systemd[1]: Stopped Network Time Synchronization.

root@DietPi4:~# systemd-analyze blame
         43.091s dietpi-boot.service
          1.214s dietpi-preboot.service
          1.072s rpi-eeprom-update.service
           872ms dev-mmcblk0p2.device
           864ms wg-quick@wg0.service

[MichaIng]

@Joulinar
Did you actually watch it taking that long? Because the timestamps of course change after time sync, usually into the future when last timestamp from last shutdown is restored via fake-hwclock. So it makes sense to boot with display and see DietPi-Run_NTPD do its job, which does an info print for every second it waits for systemd-timesyncd.

[Joulinar]

@MichaIng
I did a fresh reboot of all 3 devices before posting.

Attached a screen print from the RPi3B+

[MichaIng]

Indeed that is long. It is with internal Ethernet adapter, static IP (DHCP disabled) and Gateway as NTP server?

Could you check journalctl about related kernel and systemd messages during boot?

[Joulinar]

this is quite a strange topic. I was playing a little bit with STATIC and DHCP and honestly it doesn't matter. Sometimes it's pritty fast on STATIC

Code: Select all

root@DietPi3:~# systemd-analyze blame
          2.963s dietpi-boot.service
          1.235s dietpi-preboot.service
          1.098s dev-mmcblk0p2.device

and next time it hangs again

Code: Select all

root@DietPi3:~# systemd-analyze blame
         43.698s dietpi-boot.service
          1.295s dev-mmcblk0p2.device
          1.226s dietpi-preboot.service

Interesting point, I have some timeout connecting to my local NTP server running on my Internet Router.

Code: Select all

Jan 24 11:28:36 DietPi3 systemd[1]: Started DietPi-RAMlog.
Jan 24 11:28:36 DietPi3 systemd[1]: Started DietPi-RAMdisk.
Jan 24 11:28:36 DietPi3 systemd[1]: Starting DietPi-PreBoot...
Jan 24 11:28:38 DietPi3 systemd[1]: Started DietPi-PreBoot.
Jan 24 11:28:38 DietPi3 systemd[1]: Reached target Network (Pre).
Jan 24 11:28:38 DietPi3 systemd[1]: Starting Raise network interfaces...
Jan 24 11:28:38 DietPi3 systemd[1]: Started ifup for eth0.
Jan 24 11:28:38 DietPi3 systemd[1]: Started Raise network interfaces.
Jan 24 11:28:38 DietPi3 systemd[1]: Reached target Network.
Jan 24 11:28:38 DietPi3 systemd[1]: Starting DietPi-Boot...
Jan 24 11:28:38 DietPi3 systemd[1]: Starting Permit User Sessions...
Jan 24 11:28:38 DietPi3 systemd[1]: Started Permit User Sessions.
Jan 24 11:28:38 DietPi3 sh[328]: eth0=eth0
Jan 24 11:28:38 DietPi3 systemd[1]: Starting Network Time Synchronization...
Jan 24 11:28:39 DietPi3 systemd[1]: Started Network Time Synchronization.
Jan 24 11:28:39 DietPi3 systemd[1]: Reached target System Time Synchronized.
Jan 24 11:28:49 DietPi3 systemd-timesyncd[486]: Timed out waiting for reply from 192.168.0.1:123 (192.168.0.1).
Jan 24 11:29:06 DietPi3 systemd[1]: systemd-fsckd.service: Succeeded.
Jan 24 11:29:29 DietPi3 systemd-timesyncd[486]: Synchronized to time server for the first time 192.168.0.1:123 (192.168.0.1).
Jan 24 11:29:29 DietPi3 systemd[1]: Stopping Network Time Synchronization...
Jan 24 11:29:29 DietPi3 systemd[1]: systemd-timesyncd.service: Succeeded.
Jan 24 11:29:29 DietPi3 systemd[1]: Stopped Network Time Synchronization.
Jan 24 11:29:29 DietPi3 systemd[1]: Started DietPi-Boot.
Jan 24 11:29:29 DietPi3 systemd[1]: Started DietPi-PostBoot.
Jan 24 11:29:29 DietPi3 systemd[1]: Started Getty on tty1.

[MichaIng]

Does the router serve logs about the NTP requests and/or newly connected devices? The question is how fast it "accept" requests for both, NTP requests and internet connections from newly connected devices.

The prior done network connecting check within dietpi-boot only checks for an applied default gateway, which in case of static IP should be done very quickly when the interfaces are brought up. The eth0=eth0 print comes from ifup@eth0.service, indicating that this has fully finished. But that does not mean that router internally the device requests are handled immediately.