systemd-update-utmp.services wastes 16.990s while booting.

814ckf0x · 2014-03-02 16:32:37

Info:

uname -a

Linux arch-linux-desk 3.13.5-1-ARCH #1 SMP PREEMPT Sun Feb 23 00:25:24 CET 2014 x86_64 GNU/Linux

lscpu

Architecture:          x86_64
CPU op-mode(s):        32-bit, 64-bit
Byte Order:            Little Endian
CPU(s):                4
On-line CPU(s) list:   0-3
Thread(s) per core:    1
Core(s) per socket:    4
Socket(s):             1
NUMA node(s):          1
Vendor ID:             AuthenticAMD
CPU family:            16
Model:                 4
Model name:            AMD Phenom(tm) II X4 965 Processor
Stepping:              3
CPU MHz:               3816.867
BogoMIPS:              7636.80
Virtualization:        AMD-V
L1d cache:             64K
L1i cache:             64K
L2 cache:              512K
L3 cache:              6144K
NUMA node0 CPU(s):     0-3

journalctl -u system-update-utmp

[ ... ]
-- Reboot --
Mar 01 19:00:28 arch-linux-desk systemd[1]: Merged into installed job systemd-update-utmp.service/start as 51
Mar 01 19:00:48 arch-linux-desk systemd[1]: Starting Update UTMP about System Reboot/Shutdown...
Mar 01 19:00:48 arch-linux-desk systemd[1]: About to execute: /usr/lib/systemd/systemd-update-utmp reboot
Mar 01 19:00:48 arch-linux-desk systemd[1]: Forked /usr/lib/systemd/systemd-update-utmp as 532
Mar 01 19:00:48 arch-linux-desk systemd[1]: systemd-update-utmp.service changed dead -> start
Mar 01 19:00:48 arch-linux-desk systemd[532]: Executing: /usr/lib/systemd/systemd-update-utmp reboot
Mar 01 19:00:48 arch-linux-desk systemd[1]: Child 532 belongs to systemd-update-utmp.service
Mar 01 19:00:48 arch-linux-desk systemd[1]: systemd-update-utmp.service: main process exited, code=exited, status=0/SUCCESS
Mar 01 19:00:48 arch-linux-desk systemd[1]: systemd-update-utmp.service changed start -> exited
Mar 01 19:00:48 arch-linux-desk systemd[1]: Job systemd-update-utmp.service/start finished, result=done
Mar 01 19:00:48 arch-linux-desk systemd[1]: Started Update UTMP about System Reboot/Shutdown.
Mar 01 19:29:41 arch-linux-desk systemd[1]: Installed new job systemd-update-utmp.service/stop as 2431
Mar 01 19:29:44 arch-linux-desk systemd[1]: Stopping Update UTMP about System Reboot/Shutdown...
Mar 01 19:29:44 arch-linux-desk systemd[1]: About to execute: /usr/lib/systemd/systemd-update-utmp shutdown
Mar 01 19:29:44 arch-linux-desk systemd[1]: Forked /usr/lib/systemd/systemd-update-utmp as 20268
Mar 01 19:29:44 arch-linux-desk systemd[1]: systemd-update-utmp.service changed exited -> stop
Mar 01 19:29:44 arch-linux-desk systemd[20268]: Executing: /usr/lib/systemd/systemd-update-utmp shutdown
Mar 01 19:29:45 arch-linux-desk systemd[1]: Child 20268 belongs to systemd-update-utmp.service
Mar 01 19:29:45 arch-linux-desk systemd[1]: systemd-update-utmp.service: control process exited, code=exited status=0
Mar 01 19:29:45 arch-linux-desk systemd[1]: systemd-update-utmp.service got final SIGCHLD for state stop
Mar 01 19:29:45 arch-linux-desk systemd[1]: systemd-update-utmp.service changed stop -> dead
Mar 01 19:29:45 arch-linux-desk systemd[1]: Job systemd-update-utmp.service/stop finished, result=done
Mar 01 19:29:45 arch-linux-desk systemd[1]: Stopped Update UTMP about System Reboot/Shutdown.
-- Reboot --
Mar 01 19:31:00 arch-linux-desk systemd[1]: Merged into installed job systemd-update-utmp.service/start as 52
Mar 01 19:31:03 arch-linux-desk systemd[1]: Starting Update UTMP about System Reboot/Shutdown...
Mar 01 19:31:03 arch-linux-desk systemd[1]: About to execute: /usr/lib/systemd/systemd-update-utmp reboot
Mar 01 19:31:03 arch-linux-desk systemd[1]: Forked /usr/lib/systemd/systemd-update-utmp as 550
Mar 01 19:31:03 arch-linux-desk systemd[1]: systemd-update-utmp.service changed dead -> start
Mar 01 19:31:03 arch-linux-desk systemd[550]: Executing: /usr/lib/systemd/systemd-update-utmp reboot
Mar 01 19:31:03 arch-linux-desk systemd[1]: Child 550 belongs to systemd-update-utmp.service
Mar 01 19:31:06 arch-linux-desk systemd[1]: systemd-update-utmp.service: main process exited, code=exited, status=0/SUCCESS
Mar 01 19:31:20 arch-linux-desk systemd[1]: systemd-update-utmp.service changed start -> exited
Mar 01 19:31:20 arch-linux-desk systemd[1]: Job systemd-update-utmp.service/start finished, result=done
Mar 01 19:31:20 arch-linux-desk systemd[1]: Started Update UTMP about System Reboot/Shutdown.
Mar 01 19:36:32 arch-linux-desk systemd[1]: systemd-update-utmp.service changed dead -> exited
Mar 01 21:54:04 arch-linux-desk systemd[1]: Installed new job systemd-update-utmp.service/stop as 1797
Mar 01 21:54:07 arch-linux-desk systemd[1]: Stopping Update UTMP about System Reboot/Shutdown...
Mar 01 21:54:07 arch-linux-desk systemd[1]: About to execute: /usr/lib/systemd/systemd-update-utmp shutdown
Mar 01 21:54:07 arch-linux-desk systemd[1]: Forked /usr/lib/systemd/systemd-update-utmp as 11234
Mar 01 21:54:07 arch-linux-desk systemd[1]: systemd-update-utmp.service changed exited -> stop
Mar 01 21:54:07 arch-linux-desk systemd[11234]: Executing: /usr/lib/systemd/systemd-update-utmp shutdown
Mar 01 21:54:07 arch-linux-desk systemd[1]: Child 11234 belongs to systemd-update-utmp.service
Mar 01 21:54:07 arch-linux-desk systemd[1]: systemd-update-utmp.service: control process exited, code=exited status=0
Mar 01 21:54:07 arch-linux-desk systemd[1]: systemd-update-utmp.service got final SIGCHLD for state stop
Mar 01 21:54:07 arch-linux-desk systemd[1]: systemd-update-utmp.service changed stop -> dead
Mar 01 21:54:07 arch-linux-desk systemd[1]: Job systemd-update-utmp.service/stop finished, result=done
Mar 01 21:54:07 arch-linux-desk systemd[1]: Stopped Update UTMP about System Reboot/Shutdown.
-- Reboot --
Mar 02 16:06:04 arch-linux-desk systemd[1]: Merged into installed job systemd-update-utmp.service/start as 52
Mar 02 16:06:09 arch-linux-desk systemd[1]: Starting Update UTMP about System Reboot/Shutdown...
Mar 02 16:06:09 arch-linux-desk systemd[1]: About to execute: /usr/lib/systemd/systemd-update-utmp reboot
Mar 02 16:06:09 arch-linux-desk systemd[1]: Forked /usr/lib/systemd/systemd-update-utmp as 526
Mar 02 16:06:09 arch-linux-desk systemd[1]: systemd-update-utmp.service changed dead -> start
Mar 02 16:06:09 arch-linux-desk systemd[526]: Executing: /usr/lib/systemd/systemd-update-utmp reboot
Mar 02 16:06:09 arch-linux-desk systemd[1]: Child 526 belongs to systemd-update-utmp.service
Mar 02 16:06:11 arch-linux-desk systemd[1]: systemd-update-utmp.service: main process exited, code=exited, status=0/SUCCESS
Mar 02 16:06:26 arch-linux-desk systemd[1]: systemd-update-utmp.service changed start -> exited
Mar 02 16:06:26 arch-linux-desk systemd[1]: Job systemd-update-utmp.service/start finished, result=done
Mar 02 16:06:26 arch-linux-desk systemd[1]: Started Update UTMP about System Reboot/Shutdown.
Mar 02 16:33:59 arch-linux-desk systemd[1]: systemd-update-utmp.service changed dead -> exited
Mar 02 16:34:11 arch-linux-desk systemd[1]: systemd-update-utmp.service changed dead -> exited
Mar 02 16:34:24 arch-linux-desk systemd[1]: systemd-update-utmp.service changed dead -> exited
Mar 02 16:34:37 arch-linux-desk systemd[1]: systemd-update-utmp.service changed dead -> exited
Mar 02 16:34:46 arch-linux-desk systemd[1]: systemd-update-utmp.service changed dead -> exited
Mar 02 16:34:58 arch-linux-desk systemd[1]: systemd-update-utmp.service changed dead -> exited
Mar 02 16:35:02 arch-linux-desk systemd[1]: systemd-update-utmp.service changed dead -> exited
Mar 02 16:51:11 arch-linux-desk systemd[1]: systemd-update-utmp.service changed dead -> exited

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.

graphical.target @43.083s
└─multi-user.target @43.082s
  └─spamassassin.service @31.838s +11.243s
    └─network.target @31.831s
      └─NetworkManager.service @27.053s +4.774s
        └─basic.target @26.943s
          └─timers.target @26.934s
            └─systemd-tmpfiles-clean.timer @26.934s
              └─sysinit.target @26.870s
                └─systemd-update-utmp.service @9.874s +16.990s
                  └─systemd-tmpfiles-setup.service @9.287s +577ms
                    └─local-fs.target @9.278s
                      └─tmp.mount @9.118s +155ms
                        └─local-fs-pre.target @1.972s
                          └─systemd-tmpfiles-setup-dev.service @1.567s +397ms
                            └─kmod-static-nodes.service @686ms +872ms
                              └─systemd-journald.socket @648ms
                                └─-.mount @647ms
                                  └─system.slice @1.069s
                                    └─-.slice @1.061s

Last edited by 814ckf0x (2014-03-02 18:03:00)

karol · 2014-03-02 16:48:27

Please edit your post.
When posting configs, code or command output, please use [ code ] tags https://bbs.archlinux.org/help.php#bbcode

like this

It makes the code more readable and - in case of longer listings - more convenient to scroll through.

ewaller · 2014-03-02 17:28:06

Why are you telling us this? Is there some point you are trying to make?
As Karol points out, please use BBCode tags

814ckf0x · 2014-03-02 18:04:43

karol wrote:

Please edit your post.
When posting configs, code or command output, please use [ code ] tags https://bbs.archlinux.org/help.php#bbcode
like this
It makes the code more readable and - in case of longer listings - more convenient to scroll through.

Sorry, I tried before but it doesn't work. maybe for bad syntax.

814ckf0x · 2014-03-02 18:10:15

ewaller wrote:

Why are you telling us this? Is there some point you are trying to make?
As Karol points out, please use BBCode tags

I'm trying to say that archlinux takes a long time booting up and systemd-update-utmp wastes 17s, not a joke.

There most be an error and I don't know where can it be.

ewaller · 2014-03-02 18:57:20

Okay. For reference, that step takes 0.055 seconds on my box.

ewaller$@$odin ~ 1002 %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.

graphical.target @24.443s
`-multi-user.target @24.443s
  `-postfix.service @21.770s +2.672s
    `-network.target @21.768s
      `-netctl-auto@wlan0.service @11.892s +9.876s
        `-basic.target @11.062s
          `-timers.target @11.059s
            `-systemd-tmpfiles-clean.timer @11.059s
              `-sysinit.target @11.059s
                `-systemd-update-utmp.service @11.003s +55ms
                  `-systemd-tmpfiles-setup.service @10.904s +98ms
                    `-local-fs.target @10.903s
                      `-home.mount @10.750s +152ms
                        `-systemd-fsck@dev-disk-by\x2duuid-1e70da27\x2d41c7\x2d4
                          `-dev-disk-by\x2duuid-1e70da27\x2d41c7\x2d43fc\x2d963b
ewaller$@$odin ~ 1003 %

I think you should look through your journal for more information. You may want to pastebin it and post a link here.

NikTh · 2014-03-05 13:34:09

Check your /etc/fstab file, also check the UUIDs (blkid) , are correct ? (matching)

Arch Linux

#1 2014-03-02 16:32:37

systemd-update-utmp.services wastes 16.990s while booting.

#2 2014-03-02 16:48:27

Re: systemd-update-utmp.services wastes 16.990s while booting.

#3 2014-03-02 17:28:06

Re: systemd-update-utmp.services wastes 16.990s while booting.

#4 2014-03-02 18:04:43

Re: systemd-update-utmp.services wastes 16.990s while booting.

#5 2014-03-02 18:10:15

Re: systemd-update-utmp.services wastes 16.990s while booting.

#6 2014-03-02 18:57:20

Re: systemd-update-utmp.services wastes 16.990s while booting.

#7 2014-03-05 13:34:09

Re: systemd-update-utmp.services wastes 16.990s while booting.

Board footer