Bug 1093942

Created attachment 892173 [details]
dmesg

3.15.0-0.rc3.git0.1.fc21.x86_64

Created attachment 892174 [details]
journal

kernel-3.15.0-0.rc3.git0.1.fc21.x86_64

These things seem suspicious, but maybe aren't at all related to the problem.

1.
Why is NetworkManager seemingly causing the kernel to load cfg80211? This is a VM and doesn't have wireless hardware.

[    6.034200] rawhide.localdomain systemd[1]: Starting Network Manager...
[    6.111313] rawhide.localdomain NetworkManager[559]: <info> NetworkManager (version 0.9.9.1-5.git20140319.fc21) is starting...
[    6.111672] rawhide.localdomain NetworkManager[559]: <info> Read config: /etc/NetworkManager/NetworkManager.conf
[    6.112205] rawhide.localdomain NetworkManager[559]: <info> WEXT support is enabled
[    6.139399] rawhide.localdomain kernel: cfg80211: Calling CRDA to update world regulatory domain


2.
There's a large time gap between NetworkManager startup complete, and the start of NetworkManager-wait-online.

[    8.708717] rawhide.localdomain avahi-daemon[426]: Registering new address record for fe80::a00:27ff:fee3:26e3 on enp0s3.*.
[   12.005997] rawhide.localdomain NetworkManager[559]: <info> startup complete
[   12.017118] rawhide.localdomain systemd[1]: Started Network Manager Wait Online.

Created attachment 892175 [details]
journal with systemd.log_level=debug

Nearly one second gap:
[   18.626906] rawhide.localdomain NetworkManager[557]: <info> Activation (enp0s3) Stage 2 of 5 (Device Configure) complete.
[   18.633364] rawhide.localdomain systemd[625]: Executing: /usr/bin/nm-online -q --timeout=30
[   19.418640] rawhide.localdomain NetworkManager[557]: <info> Activation (enp0s3) Stage 3 of 5 (IP Configure Start) scheduled.

Nearly 4 second gap:
[   19.518454] rawhide.localdomain dbus-daemon[442]: dbus[442]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
[   19.523738] rawhide.localdomain systemd[1]: Started Network Manager Script Dispatcher Service.
[   20.003527] rawhide.localdomain ModemManager[429]: <warn>  Couldn't find support for device at '/sys/devices/pci0000:00/0000:00:03.0': not supported by any plugin
[   20.445155] rawhide.localdomain avahi-daemon[425]: Registering new address record for fe80::a00:27ff:fee3:26e3 on enp0s3.*.
[   24.006218] rawhide.localdomain NetworkManager[557]: <info> startup complete
[   24.023384] rawhide.localdomain systemd[1]: Started Network Manager Wait Online.
[   24.024888] rawhide.localdomain systemd[1]: Starting Network is Online.
[   24.025352] rawhide.localdomain systemd[1]: Reached target Network is Online.


Is NetworkManager-wait-online.service somehow getting hit with an Avahi startup delay? systemd-analyze blame puts it at
315ms avahi-daemon.service


By far the longest pause in console during startup is the last line in this sequence:

[  OK  ] Started Network Manager.
         Starting Network Manager Wait Online...
         Starting Network Manager Script Dispatcher Service...
[  OK  ] Started Network Manager Script Dispatcher Service.

There is about a 1 second pause at "Started Network Manager" and fully 8 seconds of pause at "Started Network Manager Script Dispatcher Service." And I cannot login locally or remotely until this clears.

I don't seem to be able to reproduce the problem on a physical machine.

The 4 second delay before "<info> startup complete" looks suspicious to me. It could be a timeout inside NM waiting for some event. It might be related to carried detection and the virtual driver. You may try setting
ignore-carrier=* in NetworkManager.conf to see whether it helps.

In any case it would be helpful to see debugging logs from NM. Can you put these lines to NetworkManager.conf and reboot:
[logging]
level=DEBUG
domains=ALL

Created attachment 892752 [details]
journalctl with NM debug

Created attachment 892755 [details]
journalctl with NM debug and ignore-carrier

NetworkManager.conf currently reads:

[main]
plugins=ifcfg-rh
ignore-carrier=*
[logging]
level=DEBUG
domains=ALL

In the same VM, but a new virtual disk, I've clean installed Rawhide minimal system from netinstall media. The problem is not reproducible, NetworkManager-wait-online.service isn't even a listed service.

Switching to the VDI with the older Rawhide, which is nevertheless as up to date as this one, still has NetworkManager-wait-online.service slowness. It has the same kernel and version of Network Manager as the new install. The two differences between them, oldslow is a Gnome packageset install on Btrfs; the newfast is a Minimal packageset install on ext4 yet NetworkManager completes 18x faster.

So something in the older install with Gnome packageset is pulling in NetworkManager-wait-online.service and also causing a delay. Is it possible this is virbr0-nic or TUN/TAP related? Since Gnome includes Boxes, it pulls in libvirt. And that's sorta pointless to have in a VM. So maybe that's why I have this problem in a VM, while it doesn't happen on baremetal?

# systemd-analyze blame
           725ms firewalld.service
           558ms sshd.service
           275ms NetworkManager.service
           144ms fedora-readonly.service
           126ms systemd-logind.service
           126ms plymouth-read-write.service
           125ms plymouth-start.service
           109ms systemd-udev-trigger.service
            99ms systemd-journal-flush.service
            99ms dev-mqueue.mount
            95ms dev-hugepages.mount
            95ms systemd-fsck-root.service
            91ms auditd.service
            83ms systemd-vconsole-setup.service
            72ms systemd-tmpfiles-setup-dev.service
            63ms polkit.service
            55ms systemd-user-sessions.service
            53ms plymouth-quit-wait.service
            53ms plymouth-quit.service
            47ms kmod-static-nodes.service
            39ms systemd-random-seed.service
            35ms user
            32ms systemd-update-utmp.service
            30ms systemd-remount-fs.service
            26ms systemd-tmpfiles-setup.service
            21ms systemd-sysctl.service
            19ms sys-kernel-debug.mount
            16ms systemd-udevd.service
            14ms tmp.mount
             4ms systemd-update-utmp-runlevel.service
             2ms sys-kernel-config.mount

This bug appears to have been reported against 'rawhide' during the Fedora 22 development cycle.
Changing version to '22'.

More information and reason for this action is here:
https://fedoraproject.org/wiki/Fedora_Program_Management/HouseKeeping/Fedora22

This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.

Fedora 22 changed to end-of-life (EOL) status on 2016-07-19. Fedora 22 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.