2

Note: I had posted this on Ask Ubuntu, but was told that forum is for questions related to real Ubuntu, only. I was advised to post here, so I'm moving the question over here.

I have installed Zorin-OS Education Lite 32bit on my aged Thinkpad T43p. This distro is based on Ubuntu, with xfce and lightdm for the graphical interface.

Initially the separate partitions for /, swap, /var, /var/log, and /home were on the HDD. Then I decided to add a small (32G) SSD besides the HDD (the T43p supports two storage devices) to hopefully speed up the system. I move the root partition to the SSD and left all other on the HDD. Only things changed on the HDD: old root partiton deleted, and swap partition deleted/created (was too small). Basically, a great success. It is fun how much faster the system is working now.

At one point, however, a naughty problem arose (I can't tell exactly when this started):

  • When I shut down the system, and later power it on again, the boot process is excessively slow. After about 4-5 minutes, the system is up and works as expected. No grub menu is shown in this process, which is expected bevahiour.

  • When I force a power off (holding down the power button) while the excessively long startup, an then restart the system, it quickly comes up and presents the grub menu. Selecting the normal "Zorin OS" from the boot menu brings the system up and running in less than a minute. (The grub mennu is show, I suspect, because the system was not cleanly shutdown, right?)

I have compared the boot log (dmesg) from both boots, and have found a few differences. Interpreting those is beyond my knowledge of the boot process; hopefully one or the other difference will ring a bell with some knowledgable soul out there.

To find the differences, I have stipped the timestamp at the start of the message, sorted them lexically, and fed them into a comarison tool. The result is as follows (lines marked with "delayed ->" are from delayed boot, those marked with "normal ->" are from speedy boot after forced power off)

delayed ->        .data : 0xdd9b5c60 - 0xdde8eb40   (4963 kB)
                  .init : 0xddea6000 - 0xddfc8000   (1160 kB)
                  .text : 0xdd000000 - 0xdd9b5c60   (9943 kB)
normal  ->        .data : 0xd49b5c60 - 0xd4e8eb40   (4963 kB)
                  .init : 0xd4ea6000 - 0xd4fc8000   (1160 kB)
                  .text : 0xd4000000 - 0xd49b5c60   (9943 kB)
---------------------------------------------------------------------
delayed ->  Console: colour dummy device 80x25
normal  ->  Console: colour VGA+ 80x25
            Console: switching to colour dummy device 80x25
            Console: switching to colour frame buffer device 175x65
---------------------------------------------------------------------
delayed ->  Kernel command line: BOOT_IMAGE=/boot/vmlinuz-5.4.0-54-generic root=UUID=d50a32c6-34b0-11eb-a9eb-7111d485222b ro initrd=/casper/initrd.lz4 quiet splash vt.handoff=1
normal  ->  Kernel command line: BOOT_IMAGE=/boot/vmlinuz-5.4.0-54-generic root=UUID=d50a32c6-34b0-11eb-a9eb-7111d485222b ro initrd=/casper/initrd.lz4 quiet splash
---------------------------------------------------------------------
delayed ->  Memory: 1995804K/2095608K available (9943K kernel code, 938K rwdata, 3992K rodata, 1160K init, 836K bss, 99804K reserved, 0K cma-reserved, 1188744K highmem)
normal  ->  Memory: 1996092K/2095608K available (9943K kernel code, 938K rwdata, 3992K rodata, 1160K init, 836K bss, 99516K reserved, 0K cma-reserved, 1188744K highmem)
---------------------------------------------------------------------
delayed ->  [TTM] Zone  kernel: Available graphics memory: 434278 KiB
            [TTM] Zone highmem: Available graphics memory: 1028650 KiB
normal  ->  [TTM] Zone  kernel: Available graphics memory: 434422 KiB
            [TTM] Zone highmem: Available graphics memory: 1028794 KiB
---------------------------------------------------------------------
delayed ->  checking generic (c0000000 5a0000) vs hw (c0000000 8000000)
---------------------------------------------------------------------
delayed ->  clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x1eae0a205f2, max_idle_ns: 440795277977 ns
normal  ->  clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x1ead52fe7de, max_idle_ns: 440795275707 ns
---------------------------------------------------------------------
delayed ->  fb0: VESA VGA frame buffer device
            fb0: switching to radeondrmfb from VESA VGA
            fbcon: Deferring console take-over
            fbcon: Deferring console take-over
---------------------------------------------------------------------
delayed ->  initial memory mapped: [mem 0x00000000-0x1e5fffff]
normal  ->  initial memory mapped: [mem 0x00000000-0x155fffff]
---------------------------------------------------------------------
delayed ->  rtc_cmos 00:02: setting system clock to 2020-12-04T13:04:12 UTC (1607087052)
normal  ->  rtc_cmos 00:02: setting system clock to 2020-12-04T13:22:52 UTC (1607088172)
---------------------------------------------------------------------
delayed ->  smpboot: Total of 1 processors activated (4256.82 BogoMIPS)
normal  ->  smpboot: Total of 1 processors activated (4256.44 BogoMIPS)
---------------------------------------------------------------------
delayed ->  systemd-journald[299]: Received request to flush runtime journal from PID 1
normal  ->  systemd-journald[298]: File /var/log/journal/bd8e491d3fd246aba6861a6970e39e0d/system.journal corrupted or uncleanly shut down, renaming and replacing.
            systemd-journald[298]: Received request to flush runtime journal from PID 1
---------------------------------------------------------------------
normal  ->  systemd[1]: Created slice system-postfix.slice.
---------------------------------------------------------------------
delayed ->  systemd[1]: Listening on Journal Socket.
            systemd[1]: Mounting Huge Pages File System...
            systemd[1]: Reached target User and Group Name Lookups.
normal  ->  systemd[1]: Listening on Journal Audit Socket.
            systemd[1]: Listening on Syslog Socket.
---------------------------------------------------------------------
delayed ->  tsc: Detected 2128.414 MHz processor
            tsc: Fast TSC calibration using PIT
normal  ->  tsc: Detected 2128.220 MHz processor
            tsc: Fast TSC calibration failed
---------------------------------------------------------------------
normal  ->  tsc: PIT calibration matches PMTIMER. 1 loops
---------------------------------------------------------------------
delayed ->  vesafb: Truecolor: size=0:8:8:8, shift=0:16:8:0
            vesafb: framebuffer at 0xc0000000, mapped to 0x(ptrval), using 5760k, total 5760k
            vesafb: mode is 1400x1050x32, linelength=5600, pages=0
            vesafb: scrolling: redraw
---------------------------------------------------------------------
delayed ->  vt handoff: transparent VT on vt#1
------------------------------------------------------------------------

The final part of the boot log for the delayed boot looks as follows:

[   15.216737] audit: type=1400 audit(1607087065.208:11): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/bin/evince-previewer//sanitized_helper" pid=676 comm="apparmor_parser"
[  174.735613] thinkpad_ec: loading out-of-tree module taints kernel.
[  174.735783] thinkpad_ec: module verification failed: signature and/or required key missing - tainting kernel
[  174.740215] thinkpad_ec: thinkpad_ec 0.42 loaded.
[  174.741379] tp_smapi 0.42 loading...
[  174.743033] tp_smapi successfully loaded (smapi_port=0xb2).
[  174.767561] thinkpad_acpi: acpi_evalf(BCTG, dd, ...) failed: AE_NOT_FOUND
[  174.767572] ACPI: \_SB_.PCI0.LPC_.EC__.HKEY: BCTG: evaluate failed
[  174.812330] thinkpad_acpi: acpi_evalf(BCTG, dd, ...) failed: AE_NOT_FOUND
[  174.812341] ACPI: \_SB_.PCI0.LPC_.EC__.HKEY: BCTG: evaluate failed
[  195.615652] lib80211_crypt: registered algorithm 'CCMP'
[  195.673147] lib80211_crypt: registered algorithm 'TKIP'
[  195.689827] IPv6: ADDRCONF(NETDEV_CHANGE): wlp11s2: link becomes ready
[  211.880332] ipw2200: Firmware error detected.  Restarting.

and those for the normal speed boot are:

[   14.430665] audit: type=1400 audit(1607088184.628:11): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/bin/evince-previewer//sanitized_helper" pid=693 comm="apparmor_parser"
[   25.976615] thinkpad_ec: loading out-of-tree module taints kernel.
[   25.976668] thinkpad_ec: module verification failed: signature and/or required key missing - tainting kernel
[   25.981152] thinkpad_ec: thinkpad_ec 0.42 loaded.
[   25.981993] tp_smapi 0.42 loading...
[   25.983999] tp_smapi successfully loaded (smapi_port=0xb2).
[   26.011674] thinkpad_acpi: acpi_evalf(BCTG, dd, ...) failed: AE_NOT_FOUND
[   26.011683] ACPI: \_SB_.PCI0.LPC_.EC__.HKEY: BCTG: evaluate failed
[   26.054491] thinkpad_acpi: acpi_evalf(BCTG, dd, ...) failed: AE_NOT_FOUND
[   26.054503] ACPI: \_SB_.PCI0.LPC_.EC__.HKEY: BCTG: evaluate failed
[  121.255499] ipw2200: Firmware error detected.  Restarting.
[  137.612515] lib80211_crypt: registered algorithm 'CCMP'
[  137.738593] lib80211_crypt: registered algorithm 'TKIP'
[  137.784727] IPv6: ADDRCONF(NETDEV_CHANGE): wlp11s2: link becomes ready

Some of the delay before the ipw2200 message is due to me having to press enter when the grub menu is shown.

I noticed that the kernel is started with an additional parm: vt.handoff=1 when the boot process is delayed. Also there are some differences related to the video, syslogd, and some others.

Any hint what to look at next? TIA

Update 10.12.2020 I have deciced to start all over again, and will not follow this problem in this thread any longer.

I had installed the system twice before starting this question, and each time, I think, did the problem appear some time after the installation. Currently, I fear that some software update -- as usual after installing from DVD, there are plenty -- is causing the problem. So, I decided to do a fresh install, but will not do a general update right away. Hoping to find the cause by step by step updating. Nevermind, and thanks for your time.

Improve this question
5
  • systemd-analyze blame and systemd-analyze critical-chain or systemd-analyze critical-chain followed by a service name can sometimes give more information than dmesg
    – mchid
    Commented Dec 6, 2020 at 14:14
  • Thanks for that. Running the blame command showed plymount-read-write.service to be the culprit; it takes 2.5 minutes to be ready. I googled this and found only entries talking about plymouth-quit-wait.service. So, what the heck might plymouth-read-write.service be waiting for? I did the same analysis for the "normal" boot, and that service was ready after 50ms.
    – phunsoft
    Commented Dec 6, 2020 at 15:44
  • In the meantime, I have found a circumvention to the problem: Removing the splash parameter from the kernel parameter list in the grub entry. No splash, no delay. However, I do want that splash screen (the machine is not for me), so the problem is not solved: What is different in relation to plymouth between a system cleanly shut down and one that was killed by forcing power-off?
    – phunsoft
    Commented Dec 8, 2020 at 8:36
  • This is just a guess but you might want to look into framebuffer issues with radeon and long boot times. I'm sure there's probably a bug and a workaround or fix somewhere. It would probably be a good idea to update (edit) your question to include the processer and GPU specs and also which drivers are in use.
    – mchid
    Commented Dec 9, 2020 at 12:09
  • Thanks for the pointers; will update late. However, a boot from power-off after normal shutdown does show the problem, but a boot from power-off after killing the system (forcing power-off) does not show any problem. Would that be explainable with framebuffer or driver problems? I would think the state of the machine with regards to hardware and drivers is the same at boot time in both cases. But, thanks a lot.I'll do some research regarding framebuffer and radeon.
    – phunsoft
    Commented Dec 9, 2020 at 12:27

1 Answer 1

Reset to default
1

After reinstalling, I did not upgrade any packages except from the ones for Firefox (seemed to be riskless ones). Next I installed the tlp package, version 1.3 from the linrunner repository, and one more package (tp-smapi-dkms) which was recommende by tlp. And voila, after two reboots the boot process showed the excessive delay. I uninstalled V1.3 and installed the official Ubuntu version 1.1, but same behaviour. I also uninstalled tp-smapi-dkms, only, but this didn't help either.

On my Thinkpad T43p running Zoin-OS Education Lite 32bit, tlp is definitely causing a problem.

To bad, as I was hoping tlp would be helpful in power management on this machine. I don't know how good the power management of the kernel, and Zorin-OS, is out of the box. Will try to find some information about this.

Anyway, the problem is solved.

Improve this answer

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .