This is an early dual core, but it seems as though it has gotten slower reaching the login screen since the upgrade from 14.0.13, here, more than four minutes from beginning of journal until TDM paints:
# inxi -CIS System: Host: gx620 Kernel: 6.2.12-1-default arch: x86_64 bits: 64 Desktop: Trinity Distro: openSUSE Tumbleweed 20230603 CPU: Info: dual core model: Intel Pentium D bits: 64 type: MCP cache: L2: 4 MiB Speed (MHz): avg: 2993 min/max: N/A cores: 1: 2993 2: 2993 Info: Processes: 139 Uptime: 0h 11m Memory: 3.38 GiB used: 417.9 MiB (12.1%) Shell: Bash inxi: 3.3.26 # pinxi -Gaz --vs --zl --hostname pinxi 3.3.27-04 (2023-05-31) Graphics: Device-1: Intel 82945G/GZ Integrated Graphics vendor: Dell driver: i915 v: kernel arch: Gen-3.5 process: Intel 90nm built: 2005-06 ports: active: VGA-1 empty: none bus-ID: 00:02.0 chip-ID: 8086:2772 class-ID: 0300 Display: x11 server: X.Org v: 21.1.8 driver: X: loaded: intel unloaded: fbdev,modesetting,vesa dri: i915 gpu: i915 display-ID: :0 screens: 1 Screen-1: 0 s-res: 1680x1050 s-dpi: 108 s-size: 395x246mm (15.55x9.69") s-diag: 465mm (18.32") Monitor-1: VGA-1 mapped: VGA1 model: Dell P2213 serial: <filter> built: 2012 res: 1680x1050 hz: 60 dpi: 91 gamma: 1.2 size: 470x300mm (18.5x11.81") diag: 558mm (22") ratio: 16:10 modes: max: 1680x1050 min: 720x400 API: OpenGL v: 2.1 Mesa 23.0.3 renderer: i915 (: 945G) direct-render: Yes # journalctl -b --no-host | grep -E 'l: Command l|tdm|rinit' Jun 04 16:44:37 kernel: Command line: root=... noresume preempt=full mitigations=none Jun 04 16:46:09 display-manager[717]: Starting service tdm Jun 04 16:48:45 dbus-daemon[616]: [system] Activating service name='org.trinitydesktop.hardwarecontrol' requested by ':1.10' (uid=0 pid=838 comm="/opt/trinity/bin/tdm_greet") (using servicehelper) Jun 04 16:48:45 org.trinitydesktop.hardwarecontrol[855]: [tde_dbus_hardwarecontrol] Listening... Jun 04 16:48:45 dbus-daemon[616]: [system] Successfully activated service 'org.trinitydesktop.hardwarecontrol' Jun 04 16:48:46 org.trinitydesktop.hardwarecontrol[855]: [tde_dbus_hardwarecontrol] Name acquired: :1.11 Jun 04 16:48:47 org.trinitydesktop.hardwarecontrol[855]: [tde_dbus_hardwarecontrol] Name acquired: org.trinitydesktop.hardwarecontrol # systemd-analyze Startup finished in 3.519s (kernel) + 15.292s (initrd) + 1min 46.790s (userspace) = 2min 5.602s graphical.target reached after 1min 19.996s in userspace. # systemd-analyze critical-chain ... graphical.target @1min 19.996s └─display-manager.service @1min 7.367s +10.192s └─systemd-logind.service @1min 6.614s +734ms └─nss-user-lookup.target @1min 5.849s └─nscd.service @1min 2.656s +3.189s └─basic.target @1min 2.241s └─sockets.target @1min 2.240s └─telnet.socket @1min 2.240s └─sysinit.target @1min 1.976s └─systemd-update-utmp.service @1min 1.760s +215ms └─systemd-tmpfiles-setup.service @1min 536ms +1.195s └─local-fs.target @1min 403ms └─run-credentials-systemd\x2dtmpfiles\x2dsetup.service.mount @1min 552ms └─local-fs-pre.target @11.668s └─lvm2-monitor.service @5.147s +6.519s └─dm-event.socket @5.092s └─system.slice └─-.slice # systemd-analyze blame | head -11 42.795s systemd-journal-flush.service 37.680s dev-disk-by\x2did-scsi\x2d0ATA_ST1000DL002\x2d9TT1_W1V0G6JD\x2dpart6.device 37.680s dev-sda6.device 37.680s dev-disk-by\x2did-scsi\x2dSATA_ST1000DL002\x2d9TT1_W1V0G6JD\x2dpart6.device 37.680s dev-disk-by\x2did-scsi\x2d1ATA_ST1000DL002\x2d9TT153_W1V0G6JD\x2dpart6.device 37.680s dev-disk-by\x2ddiskseq-10\x2dpart6.device 37.680s sys-devices-pci0000:00-0000:00:1f.2-ata3-host2-target2:0:0-2:0:0:0-block-sda-sda6.device 37.680s dev-disk-by\x2duuid-6C9066139065E3D4.device 37.680s dev-disk-by\x2dpath-pci\x2d0000:00:1f.2\x2data\x2d1.0\x2dpart6.device 37.680s dev-disk-by\x2did-scsi\x2d35000c500390ca681\x2dpart6.device 37.680s dev-disk-by\x2dpath-pci\x2d0000:00:1f.2\x2data\x2d1\x2dpart6.device #
On Sun, 4 Jun 2023 17:12:08 -0400 Felix Miata via tde-users users@trinitydesktop.org wrote:
This is an early dual core, but it seems as though it has gotten slower reaching the login screen since the upgrade from 14.0.13, here, more than four minutes from beginning of journal until TDM paints:
└─run-credentials-systemd\x2dtmpfiles\x2dsetup.service.mount
@1min 552ms └─local-fs-pre.target @11.668s └─lvm2-monitor.service @5.147s +6.519s └─dm-event.socket @5.092s └─system.slice └─-.slice # systemd-analyze blame | head -11 42.795s systemd-journal-flush.service 37.680s dev-disk-by\x2did-scsi\x2d0ATA_ST1000DL002\x2d9TT1_W1V0G6JD\x2dpart6.device 37.680s dev-sda6.device 37.680s dev-disk-by\x2did-scsi\x2dSATA_ST1000DL002\x2d9TT1_W1V0G6JD\x2dpart6.device 37.680s dev-disk-by\x2did-scsi\x2d1ATA_ST1000DL002\x2d9TT153_W1V0G6JD\x2dpart6.device 37.680s dev-disk-by\x2ddiskseq-10\x2dpart6.device 37.680s sys-devices-pci0000:00-0000:00:1f.2-ata3-host2-target2:0:0-2:0:0:0-block-sda-sda6.device 37.680s dev-disk-by\x2duuid-6C9066139065E3D4.device 37.680s dev-disk-by\x2dpath-pci\x2d0000:00:1f.2\x2data\x2d1.0\x2dpart6.device 37.680s dev-disk-by\x2did-scsi\x2d35000c500390ca681\x2dpart6.device 37.680s dev-disk-by\x2dpath-pci\x2d0000:00:1f.2\x2data\x2d1\x2dpart6.device # --
This has nothing to do with TDE. systemd waits/timeouts on mounting something
Nick Koretsky via tde-users composed on 2023-06-05 08:52 (UTC+0300):
This has nothing to do with TDE. systemd waits/timeouts on mounting something
Those mounts aren't related to whatever's delaying TDM painting the screen: # journalctl -b --no-host | grep -E 'l: Command l|tdm|rinit' 16:44:37 kernel: Command line: root=... noresume preempt=full mitigations=none 16:46:09 display-manager[717]: Starting service tdm 16:48:45 dbus-daemon[616]: [system] Activating service name='org.trinitydesktop.hardwarecontrol' requested by ':1.10' (uid=0 pid=838 comm="/opt/trinity/bin/tdm_greet") (using servicehelper) 16:48:45 org.trinitydesktop.hardwarecontrol[855]: [tde_dbus_hardwarecontrol] Listening... 16:48:45 dbus-daemon[616]: [system] Successfully activated service 'org.trinitydesktop.hardwarecontrol' 16:48:46 org.trinitydesktop.hardwarecontrol[855]: [tde_dbus_hardwarecontrol] Name acquired: :1.11 16:48:47 org.trinitydesktop.hardwarecontrol[855]: [tde_dbus_hardwarecontrol] Name acquired: org.trinitydesktop.hardwarecontrol # Systemd starts TDM @16.46.09, but doesn't finish until 16.48.47, nearly 2.5 minutes later. All mounting that's relevant was already done before 16.46.09: # systemd-analyze critical-chain ... graphical.target @56.424s
I switched default to multi-user.target, and with all non-essential mounts removed from fstab: # systemd-analyze Startup finished in 3.553s (kernel) + 15.260s (initrd) + 1min 23.083s (userspace) = 1min 41.897s multi-user.target reached after 1min 355ms in userspace.
Then I switched default back to graphical.target and rebooted: # systemd-analyze Startup finished in 3.553s (kernel) + 15.337s (initrd) + 1min 17.873s (userspace) = 1min 36.765s graphical.target reached after 53.930s in userspace. Similar delay repeats: Journal start: Jun 06 00:00:39 # journalctl -b --no-host | grep -E 'l: Command l|tdm|rinit' 00:00:39 kernel: Command line: root=... noresume preempt=full mitigations=none 00:01:44 display-manager[639]: Starting service tdm 00:04:20 dbus-daemon[570]: [system] Activating service name='org.trinitydesktop.hardwarecontrol' requested by ':1.7' (uid=0 pid=752 comm="/opt/trinity/bin/tdm_greet") (using servicehelper) 00:04:20 org.trinitydesktop.hardwarecontrol[767]: [tde_dbus_hardwarecontrol] Listening... 00:04:20 dbus-daemon[570]: [system] Successfully activated service 'org.trinitydesktop.hardwarecontrol' 00:04:21 org.trinitydesktop.hardwarecontrol[767]: [tde_dbus_hardwarecontrol] Name acquired: :1.8 00:04:22 org.trinitydesktop.hardwarecontrol[767]: [tde_dbus_hardwarecontrol] Name acquired: org.trinitydesktop.hardwarecontrol # This time it took 00:02:37 to get TDM painted/ready. 5 partitions on sda were referenced in journal, from 00:00:50 through 00:01:30, all done before "Starting service tdm" @ 00:01:44, after last "journald" entry @00:01:27. I've attached the entire journal from the first appearance of tdm, 00:01:44 until 00:04:22, the last. In that period, there's practially nothing besides Trinity, just a few seconds of samba-related things. I booted again after taking the triggers for samba-related things out of fstab. TDM first appeared @00:38:18, and ended @00:41:23, so took 00:03:05 to get from start to ready.
Felix Miata via tde-users wrote:
Jun 06 00:02:12 systemd[1]: Startup finished in 3.553s (kernel) + 15.337s (initrd) + 1min 17.873s (userspace) = 1min 36.765s. Jun 06 00:04:20 dbus-daemon[570]: [system] Activating service name='org.trinitydesktop.hardwarecontrol' requested by ':1.7' (uid=0 pid=752 comm="/opt/trinity/bin/tdm_greet") (using servicehelper)
Felix, what is happening here inbetween? Are you logging into the system or just waiting? I assume the latter as we see tdm_greet being triggered, but it is not clear what is happening in between
Anno domini 2023 Tue, 06 Jun 08:28:24 +0200 deloptes via tde-users scripsit:
Felix Miata via tde-users wrote:
Jun 06 00:02:12 systemd[1]: Startup finished in 3.553s (kernel) + 15.337s (initrd) + 1min 17.873s (userspace) = 1min 36.765s. Jun 06 00:04:20 dbus-daemon[570]: [system] Activating service name='org.trinitydesktop.hardwarecontrol' requested by ':1.7' (uid=0 pid=752 comm="/opt/trinity/bin/tdm_greet") (using servicehelper)
Felix, what is happening here inbetween? Are you logging into the system or just waiting? I assume the latter as we see tdm_greet being triggered, but it is not clear what is happening in between
I see this on 14.2, too, but it's nowhere near the mentioned delay: it went up from ~ 2 seconds to 10 seconds.
Nik
tde-users mailing list -- users@trinitydesktop.org To unsubscribe send an email to users-leave@trinitydesktop.org Web mail archive available at https://mail.trinitydesktop.org/mailman3/hyperkitty/list/users@trinitydeskto...
-- Please do not email me anything that you are not comfortable also sharing with the NSA, CIA ...
On 2023/06/06 06:07 PM, Dr. Nikolaus Klepp via tde-users wrote:
I see this on 14.2, too, but it's nowhere near the mentioned delay: it went up from ~ 2 seconds to 10 seconds.
Nik
Hi Nik, when did you start seeing such big increase in R14.2.0? last few days? if you are able to pinpoint a specific day/commit, that would be great. The only changes in R14.2.0 that I could think of, would be those related to recursive mutexes, although 2 to 10 is a big just IMO. Cheers Michele
deloptes composed on 2023-06-06 08:28 (UTC+0200):
Felix Miata wrote:
Jun 06 00:02:12 systemd[1]: Startup finished in 3.553s (kernel) + 15.337s (initrd) + 1min 17.873s (userspace) = 1min 36.765s. Jun 06 00:04:20 dbus-daemon[570]: [system] Activating service name='org.trinitydesktop.hardwarecontrol' requested by ':1.7' (uid=0 pid=752 comm="/opt/trinity/bin/tdm_greet") (using servicehelper)
Felix, what is happening here inbetween? Are you logging into the system or just waiting?
Waiting.
I assume the latter as we see tdm_greet being triggered, but it is not clear what is happening in between
Nothing evident to me. More than two minutes elapse between "startup finished", and next journal entry, for dbus-daemon[570]: [system] Activating service name='org.trinity....
On 2023/06/06 07:40 PM, Felix Miata via tde-users wrote:
deloptes composed on 2023-06-06 08:28 (UTC+0200):
Felix Miata wrote:
Jun 06 00:02:12 systemd[1]: Startup finished in 3.553s (kernel) + 15.337s (initrd) + 1min 17.873s (userspace) = 1min 36.765s. Jun 06 00:04:20 dbus-daemon[570]: [system] Activating service name='org.trinitydesktop.hardwarecontrol' requested by ':1.7' (uid=0 pid=752 comm="/opt/trinity/bin/tdm_greet") (using servicehelper)
Felix, what is happening here inbetween? Are you logging into the system or just waiting?
Waiting.
I assume the latter as we see tdm_greet being triggered, but it is not clear what is happening in between
Nothing evident to me. More than two minutes elapse between "startup finished", and next journal entry, for dbus-daemon[570]: [system] Activating service name='org.trinity....
Is CPU at 100%? Is it at 0%? anything else worth of notice during the waiting? There isn't anything so drastic in R14.1.0 that would/should cause such a long wait, so maybe the problem is somewhere else? What happens if you start a session without tdm but using startx? or using a different dm instead?
Cheers Michele
deloptes composed on 2023-06-06 18:02 (UTC+0200):
Felix Miata via tde-users wrote:
Felix, what is happening here inbetween? Are you logging into the system or just waiting?
Waiting.
Press ESC and see where it hangs.
Plymouth is never installed here when not mandatory, and if mandatory, it is disabled. Thus, traditional boot messages appear until a login prompt appears, shortly followed by screen cleared to black in anticipation of DM painting, leaving only _ in the upper left until painting happens minutes later. Dmesg tail offers no clues I recognize: [ 44.218248] pci 0000:00:00.0: Intel 945G Chipset [ 44.218273] pci 0000:00:00.0: detected gtt size: 262144K total, 262144K mappable [ 44.218703] pci 0000:00:00.0: detected 8192K stolen memory [ 44.218864] i915 0000:00:02.0: vgaarb: deactivate vga console [ 44.219494] Console: switching to colour dummy device 80x25 [ 44.239778] i915 0000:00:02.0: vgaarb: changed VGA decodes: olddecodes=io+mem,decodes=io+mem:owns=io+mem [ 44.287036] i915 0000:00:02.0: [drm] Initialized overlay support. [ 44.287749] [drm] Initialized i915 1.6.0 20201103 for 0000:00:02.0 on minor 0 [ 44.330336] tg3 0000:02:00.0 eth0: Link is up at 1000 Mbps, full duplex [ 44.330350] tg3 0000:02:00.0 eth0: Flow control is on for TX and on for RX [ 44.333778] fbcon: i915drmfb (fb0) is primary device [ 44.382673] Console: switching to colour frame buffer device 180x56 [ 44.402290] i915 0000:00:02.0: [drm] fb0: i915drmfb frame buffer device [ 45.103916] NET: Registered PF_PACKET protocol family [ 48.766612] EXT4-fs (sda19): mounting ext3 file system using the ext4 subsystem [ 53.061037] EXT4-fs (sda20): mounting ext3 file system using the ext4 subsystem [ 53.781251] EXT4-fs (sda19): mounted filesystem 64a3f2d0-244e-472f-bb65-3038dcee5cb8 with ordered data mode. Quota mode: none. [ 53.781280] ext3 filesystem being mounted at /home supports timestamps until 2038 (0x7fffffff) [ 54.087801] EXT4-fs (sda21): mounting ext3 file system using the ext4 subsystem [ 59.049807] EXT4-fs (sda21): mounted filesystem fbd94b01-4ce6-4d7e-9925-cc1ea850cf89 with ordered data mode. Quota mode: none. [ 59.049834] ext3 filesystem being mounted at /usr/local supports timestamps until 2038 (0x7fffffff) [ 59.251340] EXT4-fs (sda20): mounted filesystem 82d201b6-4e41-4ac3-b6cb-74230c041f43 with ordered data mode. Quota mode: none. [ 59.251368] ext3 filesystem being mounted at <filter> supports timestamps until 2038 (0x7fffffff) [ 61.625344] atkbd serio0: Spurious ACK on isa0060/serio0. Some program might be trying to access hardware directly. [ 62.624735] atkbd serio0: Spurious ACK on isa0060/serio0. Some program might be trying to access hardware directly. [ 62.627772] atkbd serio0: Spurious ACK on isa0060/serio0. Some program might be trying to access hardware directly. [ 63.627452] atkbd serio0: Spurious ACK on isa0060/serio0. Some program might be trying to access hardware directly.
In /var/log/: Xorg.0.log.old starts 83.856, ends 93.535 Xorg.o.log starts 213.462, ends 256.079 (@4+ minutes)
# tail -n22 Xorg.0.log.old [ 93.526] (II) Initializing extension XInputExtension [ 93.526] (II) Initializing extension XTEST [ 93.527] (II) Initializing extension BIG-REQUESTS [ 93.527] (II) Initializing extension SYNC [ 93.528] (II) Initializing extension XKEYBOARD [ 93.528] (II) Initializing extension XC-MISC [ 93.528] (II) Initializing extension SECURITY [ 93.529] (II) Initializing extension XFIXES [ 93.529] (II) Initializing extension RENDER [ 93.530] (II) Initializing extension RANDR [ 93.531] (II) Initializing extension COMPOSITE [ 93.531] (II) Initializing extension DAMAGE [ 93.532] (II) Initializing extension MIT-SCREEN-SAVER [ 93.532] (II) Initializing extension DOUBLE-BUFFER [ 93.533] (II) Initializing extension RECORD [ 93.533] (II) Initializing extension DPMS [ 93.533] (II) Initializing extension Present [ 93.534] (II) Initializing extension DRI3 [ 93.534] (II) Initializing extension X-Resource [ 93.534] (II) Initializing extension XVideo [ 93.535] (II) Initializing extension XVideo-MotionCompensation [ 93.535] (II) Initializing extension GLX # head -n3 X*log [ 213.462] X.Org X Server 1.21.1.8 X Protocol Version 11, Revision 0
Same PC booting Leap 15.4/TDE 14.1.0 takes about 2m 00s to get login screen painted. Near twin PC, with PCIe DVI port provider for the 945G iGPU, but SSD instead of HDD, takes about 0m 45s on Bullseye to get TDM login screen painted. Same near twin takes slightly longer with Leap 15.4/TDe 14.1.0, 0m 50s. Same near twin with KDE5/KDM3 takes about the same 50s as 15.4.
Back on original host gx620, I logged in remotely as soon as it would let me so I could run top, and saw nothing in the 2+ minute delay period to suggest why.
Attachment is tar cvjf archive of dmesg using drm.debug=0x1e log_buf_len=1M, too big to pastebin anywhere as plain text, and rejected attempting to pastebin as archive.
On 2023/06/07 04:21 AM, Felix Miata via tde-users wrote:
Same PC booting Leap 15.4/TDE 14.1.0 takes about 2m 00s to get login screen painted. Near twin PC, with PCIe DVI port provider for the 945G iGPU, but SSD instead of HDD, takes about 0m 45s on Bullseye to get TDM login screen painted. Same near twin takes slightly longer with Leap 15.4/TDe 14.1.0, 0m 50s. Same near twin with KDE5/KDM3 takes about the same 50s as 15.4.
Hi Felix, are the machines all running RPM distros? Do you see the same problem with DEB distros? If you haven't tried a DEB distro, would you be able to do a test with one (say Debian) and see if the same delay happens there too? That would provide extra feedback to us. Cheers Michele
Michele Calgaro via tde-users composed on 2023-06-07 10:39 (UTC+0900):
Felix Miata wrote:
Same PC booting Leap 15.4/TDE 14.1.0 takes about 2m 00s to get login screen painted. Near twin PC, with PCIe DVI port provider for the 945G iGPU, but SSD instead of HDD, takes about 0m 45s on Bullseye to get TDM login screen painted. Same near twin takes slightly longer with Leap 15.4/TDe 14.1.0, 0m 50s. Same near twin with KDE5/KDM3 takes about the same 50s as 15.4.
are the machines all running RPM distros? Do you see the same problem with DEB distros? If you haven't tried a DEB distro, would you be able to do a test with one (say Debian) and see if the same delay happens there too? That would provide extra feedback to us.
I hadn't been tracking which PCs or installations were exhibiting sloth, and don't remember any of which have so far. It's going to take a while to collect a sense of who and where.
Tomorrow and Saturday are latest Leap and Bookworm releases, so my focus for a while will be on getting those upgrades moving along. The problem PC of the two reported in this thread only has an 80G HDD with two openSUSEes and no space for more. The HDD vs SSD between these two makes them rather different for useful comparing. Based on recorded data so far, it's a TW-only problem.
On 2023/06/07 11:40 AM, Felix Miata via tde-users wrote:
I hadn't been tracking which PCs or installations were exhibiting sloth, and don't remember any of which have so far. It's going to take a while to collect a sense of who and where.
Ok, please do keep an eye on it and let us know if that is the case. So far all evidence seems to point towards RPM distros only. See also https://mirror.git.trinitydesktop.org/gitea/TDE/tde/issues/128 where other users reported similar issues and Francois has been able to reproduce it too.
Cheers Michele
Michele Calgaro via tde-users composed on 2023-06-08 11:40 (UTC+0900):
Felix Miata wrote:
I hadn't been tracking which PCs or installations were exhibiting sloth, and don't remember any of which have so far. It's going to take a while to collect a sense of who and where.
Ok, please do keep an eye on it and let us know if that is the case. So far all evidence seems to point towards RPM distros only. See also https://mirror.git.trinitydesktop.org/gitea/TDE/tde/issues/128 where other users reported similar issues and Francois has been able to reproduce it too.
Good reply! That bug report reminded me another for sure was on Fedora 38, on the near twin PC to my OTP PC....
On 2023/06/08 12:15 PM, Felix Miata via tde-users wrote:
Michele Calgaro via tde-users composed on 2023-06-08 11:40 (UTC+0900):
Felix Miata wrote:
I hadn't been tracking which PCs or installations were exhibiting sloth, and don't remember any of which have so far. It's going to take a while to collect a sense of who and where.
Ok, please do keep an eye on it and let us know if that is the case. So far all evidence seems to point towards RPM distros only. See also https://mirror.git.trinitydesktop.org/gitea/TDE/tde/issues/128 where other users reported similar issues and Francois has been able to reproduce it too.
Good reply! That bug report reminded me another for sure was on Fedora 38, on the near twin PC to my OTP PC....
Just replying to this email for the records and in case of future reference. The issue has been fixed has mentioned in a different email and backport packages are available. Cheer Michele