Startup delay

[Menard]

Hello

I noticed an increased startup timing, strictly between the grub and the login screen, from 45" to 60" now in a few time (1 month) and the logs show that the timing is shorter as 20" for the whole process

Code: Select all

$ systemd-analyze critical-chain
The time when unit became active or started is printed after the "@" character.
The time the unit took to start is printed after the "+" character.

graphical.target @29.951s
└─multi-user.target @29.951s
  └─networkd-dispatcher.service @17.251s +12.699s
    └─basic.target @17.061s
      └─sockets.target @17.061s
        └─uuidd.socket @17.061s
          └─sysinit.target @16.915s
            └─systemd-timesyncd.service @16.755s +159ms
              └─systemd-tmpfiles-setup.service @16.595s +140ms
                └─systemd-journal-flush.service @5.333s +11.259s
                  └─systemd-journald.service @4.899s +429ms
                    └─systemd-journald.socket @4.890s
                      └─system.slice @4.882s
                        └─-.slice @4.882s

Code: Select all

System:    Kernel: 5.15.0-41-generic x86_64 bits: 64 compiler: N/A Desktop: Cinnamon 5.2.7 
           wm: muffin dm: LightDM Distro: Linux Mint 20.3 Una base: Ubuntu 20.04 focal 
Machine:   Type: Desktop Mobo: MSI model: A88XM-E35 V2 (MS-7721) v: 6.0 serial: <filter> 
           UEFI [Legacy]: American Megatrends v: 6.5 date: 08/10/2016 
CPU:       Topology: Quad Core model: AMD A8-7600 Radeon R7 10 Compute Cores 4C+6G bits: 64 
           type: MCP arch: Steamroller rev: 1 L2 cache: 2048 KiB 
           flags: avx lm nx pae sse sse2 sse3 sse4_1 sse4_2 sse4a ssse3 svm bogomips: 24799 
           Speed: 1557 MHz min/max: 1400/3100 MHz Core speeds (MHz): 1: 1896 2: 1899 3: 3100 
           4: 3100 
Graphics:  Device-1: AMD Kaveri [Radeon R7 Graphics] vendor: Micro-Star MSI driver: radeon 
           v: kernel bus ID: 00:01.0 chip ID: 1002:1313 
           Display: x11 server: X.Org 1.20.13 driver: ati,radeon unloaded: fbdev,modesetting,vesa 
           resolution: 1920x1080~60Hz 
           OpenGL: renderer: AMD KAVERI (DRM 2.50.0 5.15.0-41-generic LLVM 12.0.0) 
           v: 4.5 Mesa 21.2.6 direct render: Yes 
Audio:     Device-1: AMD Kaveri HDMI/DP Audio vendor: Micro-Star MSI driver: snd_hda_intel 
           v: kernel bus ID: 00:01.1 chip ID: 1002:1308 
           Device-2: AMD FCH Azalia vendor: Micro-Star MSI driver: snd_hda_intel v: kernel 
           bus ID: 00:14.2 chip ID: 1022:780d 
           Sound Server: ALSA v: k5.15.0-41-generic 
Network:   Device-1: Realtek RTL8111/8168/8411 PCI Express Gigabit Ethernet vendor: Micro-Star MSI 
           driver: r8169 v: kernel port: e000 bus ID: 01:00.0 chip ID: 10ec:8168 
           IF: enp1s0 state: up speed: 1000 Mbps duplex: full mac: <filter> 
Drives:    Local Storage: total: 931.52 GiB used: 568.01 GiB (61.0%) 
           ID-1: /dev/sda vendor: Seagate model: ST3500630A size: 465.76 GiB speed: 1.5 Gb/s 
           serial: <filter> 
           ID-2: /dev/sdb type: USB vendor: Seagate model: BUP Slim BK size: 465.76 GiB 
           serial: <filter> 
Partition: ID-1: / size: 29.36 GiB used: 16.19 GiB (55.1%) fs: ext4 dev: /dev/sdb1 
           ID-2: /home size: 29.36 GiB used: 13.96 GiB (47.6%) fs: ext4 dev: /dev/sda2 
Sensors:   System Temperatures: cpu: 12.4 C mobo: N/A gpu: radeon temp: 17 C 
           Fan Speeds (RPM): N/A 
Info:      Processes: 242 Uptime: 1h 09m Memory: 6.74 GiB used: 2.13 GiB (31.5%) Init: systemd 
           v: 245 runlevel: 5 Compilers: gcc: 9.4.0 alt: 9 Client: Unknown python3.8 client 
           inxi: 3.0.38 

According the logs, the startup time is even shorter ... 20"
in sudo dmesg -T between 7:43:31 and 7:43:51

Code: Select all

[ven. juil. 22 07:43:51 2022] audit: type=1400 audit(1658468631.233:11): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/connman/scripts/dhclient-script" pid=690 comm="apparmor_parser"
[ven. juil. 22 07:44:03 2022] kauditd_printk_skb: 13 callbacks suppressed
[ven. juil. 22 07:44:03 2022] audit: type=1400 audit(1658468643.457:25): apparmor="DENIED" operation="capable" profile="/usr/sbin/cups-browsed" pid=872 comm="cups-browsed" capability=23  capname="sys_nice"
[ven. juil. 22 07:44:05 2022] Generic FE-GE Realtek PHY r8169-0-100:00: attached PHY driver (mii_bus:phy_addr=r8169-0-100:00, irq=MAC)
[ven. juil. 22 07:44:06 2022] r8169 0000:01:00.0 enp1s0: Link is Down
[ven. juil. 22 08:15:25 2022] r8169 0000:01:00.0 enp1s0: Link is Up - 1Gbps/Full - flow control rx/tx
[ven. juil. 22 08:15:25 2022] IPv6: ADDRCONF(NETDEV_CHANGE): enp1s0: link becomes ready

[all41]

I think the 5.4 series kernel is more appopriate for your hardware.
Try reverting back to a 5.4 series kernel at grub.

[antikythera]

please follow the instructions posted by LanceM and post the outputs back in this thread:

viewtopic.php?p=2007220#p2007220

but also the main culprit service wise seems to be networkd-dispatcher, so check your network settings haven't got messed up somehow

[spamegg]

Another one that looks interesting is this:

Code: Select all

                └─systemd-journal-flush.service @5.333s +11.259s

As your logs get larger and larger, this time can increase and slow the boot even more.

I recommend following Pjotr's tutorial on how to limit log size and clean out old logs. https://easylinuxtipsproject.blogspot.c ... .html#ID10

[antikythera]

root is on a mechanical USB drive, might be why the log takes a while to flush

[Menard]

root is on a mechanical USB drive, might be why the log takes a while to flush

What I did is :

1 - restoring this system from an old backup (may 5) on another USB external hard drive that is faster and I updated it, so the timings were restored as their value before (45")
nb : with clonezilla Live USB in image device mode
2 - reverse-copying this secondary system on the former disk and great deception, I found the 60" timing back

So for me it is evidence that it cannot come from some growing or corruption phenomenon ... (including network settings)
it can still come from the updates or hardware modifications, degradations
I could have made a test before the updates to check for the first item

I am with unbound local DNS server and I spent a lot of time to have it perfectly work, but no recent changes

XXX >>> The main time lost is between the end of the startup and the display of the login screen ... it is clear when using F11 to show the log in real time ... it is black screen with nothing to read for a long time, and then appears the login screen

[Menard]

I think the 5.4 series kernel is more appopriate for your hardware.
Try reverting back to a 5.4 series kernel at grub.

I ve re-installed the 5.4 and I rebooted and I had to re-installe grub, and then I rebooted and started with the 5.4 option but then I measured 55" in the delay so my first conclusion is that the 5.15 kernel is not the main cause of this 33% startup delay increase (can you confirm to me that I can write it like this ? )

but I have to check this result other times and check the 5.15 startup, so after this I have to check if that comes from other updates, Timeshift snapshots will help me

[Menard]

Boot time is even worse this morning with 5.4 kernel : 62"

I am not sure to understand well the result of systemd-analyze critical-chain but when I ask the system to display the startup journal by F11 it is clear that the startup is not the problem but it is after the end of the display, something "in black" takes time until the desktop appears

[Menard]

This post to recall that I am still searching for why I had this important increased delay after the startup itself and between displaying the login screen
it is for the science more than for the time lost or earned
I had no time for this, lastly
I only know it is not because of the kernel, and probably not because of the system disk (it is checked more twice a week or more when some hard shutdown happens)
Coming back soon

[n4m3]

Maybe it's not software related. You're using a Seagate Barracuda Hdd right? and maybe it's getting just old? I had like 3 of them years ago and had strange problems with them too.(my first ssd from 2014 is still working and i don't have any broken ssd yet but none of my hdds still exist).

The worst thing to find with a Barracuda, that was not even related to the Hdd itself, was a broken sata cable that delayed the start for many seconds or it would even crash.

If you hear the arm "clicking" save your data asap. I lost that way my 2 css maps i was building in 2006 and never started one again.

[Menard]

It is an external hard disk (Seagate back up plus slim) inside is a ST500LT012 not known for issues
Issues are known with my ST1000LM035 and my ST2000LM007 external USB for the moment, but they are fine for the moment
I know about the Rosewood series and I won't use them as back up

USB cables are also sensible but in this case I shoud have some #C7 (199) errors on SMART

[Menard]

What appears now is that the startup delay in unconstant, it varies from 47" to 55" since the upgrade from kernel 5.4 to kernel 5.15 with allways the fact that it is the last part that increases, not the part that is logged in the system ...

But anyway all my concern is the second part of the boot process, after the moment when the on screen display has stopped, all is black for 15" ... I guess that before, this time lasted around 2 or 3 seconds

Can you tell me what this means ? During some seconds, nothing happens in the system ?

[deepakdeshp]

If you hit ESC key as the system is booting it shows whats happening and where is the delay.