Created attachment 446928 [details] dmesg output booting with 'systemd.log_level=debug' and 26 second pause Description of problem: I'm noticing what appears to be a 26 second 'pause' during boots. systemd.debug messages place it here: Sep 13 06:02:04 tlondon kernel: init[1]: rsyslog.service changed start -> running Sep 13 06:02:04 tlondon kernel: init[1]: Job rsyslog.service/start finished, success=yes Sep 13 06:02:05 tlondon avahi-daemon[1232]: Found user 'avahi' (UID 498) and group 'avahi' (GID 491). Sep 13 06:02:05 tlondon avahi-daemon[1232]: Successfully dropped root privileges. Sep 13 06:02:05 tlondon avahi-daemon[1232]: avahi-daemon 0.6.27 starting up. Sep 13 06:02:05 tlondon avahi-daemon[1232]: Successfully called chroot(). Sep 13 06:02:05 tlondon avahi-daemon[1232]: Successfully dropped remaining capabilities. Sep 13 06:02:05 tlondon avahi-daemon[1232]: Loading service file /services/ssh.service. Sep 13 06:02:05 tlondon avahi-daemon[1232]: Loading service file /services/udisks.service. Sep 13 06:02:05 tlondon avahi-daemon[1232]: Network interface enumeration completed. Sep 13 06:02:05 tlondon avahi-daemon[1232]: Registering HINFO record with values 'X86_64'/'LINUX'. Sep 13 06:02:05 tlondon avahi-daemon[1232]: Server startup complete. Host name is tlondon.local. Local service cookie is 3534871078. Sep 13 06:02:05 tlondon avahi-daemon[1232]: Service "tlondon" (/services/udisks.service) successfully established. Sep 13 06:02:05 tlondon avahi-daemon[1232]: Service "tlondon" (/services/ssh.service) successfully established. Sep 13 06:02:05 tlondon udev-configure-printer: invalid or missing IEEE 1284 Device ID Sep 13 06:02:31 tlondon ntpd[1347]: ntpd 4.2.6p2 Fri Aug 27 17:20:24 UTC 2010 (1) Sep 13 06:02:31 tlondon ntpd[1347]: proto: precision = 0.698 usec Sep 13 06:02:31 tlondon ntpd[1347]: 0.0.0.0 c01d 0d kern kernel time sync enabled Sep 13 06:02:31 tlondon gpm[1350]: *** debug [daemon/init_mice.c(39)]: initialize /dev/input/mice with proto exps2 Sep 13 06:02:31 tlondon gpm[1350]: *** debug [daemon/init_mice.c(46)]: finished initialization I attach complete output of 'dmesg'. [Noticed some fc14 BZs related to network not starting. Not sure if this is the same issue....] Version-Release number of selected component (if applicable): systemd-9-3.fc15.x86_64 initscripts-9.20-1.fc15.x86_64 How reproducible: Every boot Steps to Reproduce: 1. 2. 3. Actual results: Expected results: Additional info:
Please boot with "systemd.log_level=debug systemd.log_target=kmsg" on the kernel command line. Then attach the output of "dmesg" after the boot finished here.
Created attachment 447097 [details] output of dmesg showing boot with systemd.log_level=debug systemd.log_target=kmsg'
I updated systemd, hal, readahead, ... systemd-10-1.fc14.x86_64 dbus-1.4.0-1.fc15.x86_64 hal-0.5.14-5.fc15.x86_64 readahead-1.5.7-1.fc15.x86_64 Booting, I see this: Sep 14 06:33:26 tlondon avahi-daemon[1271]: Successfully dropped root privileges. Sep 14 06:33:26 tlondon avahi-daemon[1271]: avahi-daemon 0.6.27 starting up. Sep 14 06:33:26 tlondon rpc.statd[1296]: Version 1.2.2 starting Sep 14 06:33:26 tlondon sm-notify[1299]: Version 1.2.2 starting Sep 14 06:33:26 tlondon kernel: RPC: Registered udp transport module. Sep 14 06:33:26 tlondon kernel: RPC: Registered tcp transport module. Sep 14 06:33:26 tlondon kernel: RPC: Registered tcp NFSv4.1 backchannel transport module. Sep 14 06:33:26 tlondon dbus: avc: netlink poll: error 4 Sep 14 06:33:26 tlondon avahi-daemon[1271]: Successfully called chroot(). Sep 14 06:33:26 tlondon avahi-daemon[1271]: Successfully dropped remaining capabilities. Sep 14 06:33:26 tlondon avahi-daemon[1271]: Loading service file /services/ssh.service. Sep 14 06:33:26 tlondon avahi-daemon[1271]: Loading service file /services/udisks.service. Sep 14 06:33:26 tlondon avahi-daemon[1271]: Network interface enumeration completed. Sep 14 06:33:26 tlondon avahi-daemon[1271]: Registering HINFO record with values 'X86_64'/'LINUX'. Sep 14 06:33:26 tlondon avahi-daemon[1271]: Server startup complete. Host name is tlondon.local. Local service cookie is 992705520. Sep 14 06:33:26 tlondon avahi-daemon[1271]: Service "tlondon" (/services/udisks.service) successfully established. Sep 14 06:33:26 tlondon avahi-daemon[1271]: Service "tlondon" (/services/ssh.service) successfully established. Sep 14 06:33:27 tlondon udev-configure-printer: invalid or missing IEEE 1284 Device ID Sep 14 06:33:27 tlondon udev-configure-printer: invalid or missing IEEE 1284 Device ID kkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkk Sep 14 06:33:51 tlondon NetworkManager[1356]: <info> NetworkManager (version 0.8.1-6.git20100831.fc15) is starting... Sep 14 06:33:51 tlondon NetworkManager[1356]: <info> Read config file /etc/NetworkManager/NetworkManager.conf dbus netlink poll error? 14 seconds after udev-configure-printer? Not sure its important..... I'll try to reproduce with 'systemd.log_level=debug systemd.log_target=kmsg'
Sorry, 24 seconds after udev-configure-printer..... (too early to subtract...)
Created attachment 447230 [details] dmesg output booting with 'systemd.log_level=debug' and pauses
Created attachment 447527 [details] /var/log/messages showing 24 second "pause" after udev-configure-printer This is now pretty consistent..... there is a 20-30 second "pause" during the boot process when the system hits udev-configure-printer. I've attached /var/log/messages from a boot with 'systemd.log_level=debug systemd.log_target=kmsg'. /var/log/messages conveniently time stamps the log entries, providing some indication of the timing. The (apparently) significant lines showing "no activity" for 24 seconds: Sep 15 06:05:01 tlondon kernel: init[1]: Child 1282 belongs to cups.service Sep 15 06:05:01 tlondon kernel: init[1]: cups.service: control process exited, code=exited status=0 Sep 15 06:05:01 tlondon kernel: init[1]: cups.service got final SIGCHLD for state start Sep 15 06:05:01 tlondon kernel: init[1]: cups.service changed start -> running Sep 15 06:05:01 tlondon kernel: init[1]: Job cups.service/start finished, success=yes Sep 15 06:05:01 tlondon udev-configure-printer: invalid or missing IEEE 1284 Device ID Sep 15 06:05:01 tlondon kernel: init[1]: Received SIGCHLD Sep 15 06:05:01 tlondon udev-configure-printer: invalid or missing IEEE 1284 Device ID kkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkk Sep 15 06:05:01 tlondon kernel: init[1]: Got SIGCHLD for process 1308 (udev-configure-) Sep 15 06:05:01 tlondon kernel: init[1]: Child 1308 died (code=exited, status=1/FAILURE) Sep 15 06:05:01 tlondon kernel: init[1]: Got SIGCHLD for process 1310 (udev-configure-) Sep 15 06:05:01 tlondon kernel: init[1]: Child 1310 died (code=exited, status=1/FAILURE) Sep 15 06:05:01 tlondon kernel: init[1]: Received SIGCHLD Sep 15 06:05:25 tlondon kernel: init[1]: Received SIGCHLD Sep 15 06:05:25 tlondon kernel: init[1]: Got SIGCHLD for process 1285 (netfs) Sep 15 06:05:25 tlondon kernel: init[1]: Child 1285 died (code=exited, status=0/SUCCESS) Sep 15 06:05:25 tlondon kernel: init[1]: Child 1285 belongs to netfs.service Sep 15 06:05:25 tlondon kernel: init[1]: netfs.service: control process exited, code=exited status=0 Sep 15 06:05:25 tlondon kernel: init[1]: netfs.service got final SIGCHLD for state start Sep 15 06:05:25 tlondon kernel: init[1]: netfs.service changed start -> exited Sep 15 06:05:25 tlondon kernel: init[1]: Job netfs.service/start finished, success=yes Suggestions on additional info to provide? Anything more I can do to help?
huh, 1022 letters 'k'? Where can that come from? Suspiciously close to 1024 and suspiciously identical to kernel's freed slab poison (#define POISON_FREE 0x6b), but that may be accidental. Any change if you disconnect your printer?
Sorry, from a better look at the full log I see it is not a printer but a USB<->LPT bridge. Try disconnecting that.
Ah.... My printer actually is a (very, very) old HP5MP that is usually powered off. But, I connect it through a "convert the old printer jack to USB" gizmo. Believe this is it: http://www.prolific.com.tw/eng/products.asp?id=6 'lsusb' says: Bus 001 Device 004: ID 067b:2305 Prolific Technology, Inc. PL2305 Parallel Port I will reboot 2 more times: the first with the printer powered on, the second with the USB gizmo unplugged. I'll report back......
And there's also an ordering cycle at Sep 15 06:04:58: init[1]: Found ordering cycle on nfslock.service/start init[1]: Walked on cycle path to network.target/start init[1]: Walked on cycle path to NetworkManager.service/start init[1]: Walked on cycle path to udev-post.service/start init[1]: Walked on cycle path to netfs.service/start init[1]: Walked on cycle path to nfslock.service/start init[1]: Breaking ordering cycle by deleting job network.target/start init[1]: Deleting job remote-fs.target/start as dependency of job network.target/start
Created attachment 447537 [details] /var/log/messages showing 24 second "pause", disconnected USB device, ..... Booting with the "strange" printer->USB gizmo disconnected did not seem to make a difference. Still see what appears to be a 24 second "pause" after "cups" and before "netfs". Sep 15 11:31:04 tlondon kernel: init[1]: Got SIGCHLD for process 1271 (cups) Sep 15 11:31:04 tlondon kernel: init[1]: Child 1271 died (code=exited, status=0/SUCCESS) Sep 15 11:31:04 tlondon kernel: init[1]: Child 1271 belongs to cups.service Sep 15 11:31:04 tlondon kernel: init[1]: cups.service: control process exited, code=exited status=0 Sep 15 11:31:04 tlondon kernel: init[1]: cups.service got final SIGCHLD for state start Sep 15 11:31:04 tlondon kernel: init[1]: cups.service changed start -> running Sep 15 11:31:04 tlondon kernel: init[1]: Job cups.service/start finished, success=yes Sep 15 11:31:28 tlondon kernel: init[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus Sep 15 11:31:28 tlondon kernel: init[1]: Running GC... Sep 15 11:31:28 tlondon kernel: init[1]: Received SIGCHLD Sep 15 11:31:28 tlondon kernel: init[1]: Got SIGCHLD for process 1273 (netfs) Sep 15 11:31:28 tlondon kernel: init[1]: Child 1273 died (code=exited, status=0/SUCCESS) Sep 15 11:31:28 tlondon kernel: init[1]: Child 1273 belongs to netfs.service Sep 15 11:31:28 tlondon kernel: init[1]: netfs.service: control process exited, code=exited status=0 Sep 15 11:31:28 tlondon kernel: init[1]: netfs.service got final SIGCHLD for state start
I blame the ordering cycle. At least the involvement of NetworkManager.service in the cycle seems to be caused by systemd parsing dependency information from it not only from the native unit, but also from the SysV service (similar as https://bugzilla.redhat.com/show_bug.cgi?id=630225#c36). You can try chkconfig NetworkManager off
Created attachment 447567 [details] booting after 'chkconfig NetworkManager off' After 'chkconfig NetworkManager off' and rebooting: Looks like that change "eliminated" the "24 second gap". Appears the network is started earlier, and other good things.... Thanks! So, will a fix for 630225 fix this as well? Or is there another issue....?
Yes, it has the same cause. Thanks for testing. *** This bug has been marked as a duplicate of bug 630225 ***