Description of problem: System takes over 2 additional minutes to boot after updating to kernel 2.6.38.8-35 Version-Release number of selected component (if applicable): 2.6.38.8-35 How reproducible: Almost every time on powering on. However, only on my AMD Athlon(tm) 64 X2 Dual Core Processor 4200+ (2 cpu cores) (version 2.20.00) It works fine on a Lenovo Netbook with Intel Atom CPUN475. Steps to Reproduce: 1.Power on the system with kernel 2.6.38.8-35 2. 3. Actual results: Extract from dmesg: [ 64.343759] multipathd (1870): /proc/1870/oom_adj is deprecated, please use /proc/1870/oom_score_adj instead. [ 65.161650] forcedeth 0000:00:07.0: irq 43 for MSI/MSI-X [ 75.602026] eth0: no IPv6 routers present [ 223.928729] powernow-k8: Found 1 AMD Athlon(tm) 64 X2 Dual Core Processor 4200+ (2 cpu cores) (version 2.20.00) [ 223.928791] powernow-k8: 0 : fid 0xe (2200 MHz), vid 0xe [ 223.928795] powernow-k8: 1 : fid 0xc (2000 MHz), vid 0x10 [ 223.928797] powernow-k8: 2 : fid 0xa (1800 MHz), vid 0x10 [ 223.928800] powernow-k8: 3 : fid 0x2 (1000 MHz), vid 0x12 Expected results: Extract from dmesg with kernel 2.6.38.8-32 [ 22.512363] multipathd (1868): /proc/1868/oom_adj is deprecated, please use /proc/1868/oom_score_adj instead. [ 23.371884] forcedeth 0000:00:07.0: irq 43 for MSI/MSI-X [ 25.735194] powernow-k8: Found 1 AMD Athlon(tm) 64 X2 Dual Core Processor 4200+ (2 cpu cores) (version 2.20.00) [ 25.735267] powernow-k8: 0 : fid 0xe (2200 MHz), vid 0xe [ 25.735270] powernow-k8: 1 : fid 0xc (2000 MHz), vid 0x10 [ 25.735273] powernow-k8: 2 : fid 0xa (1800 MHz), vid 0x10 [ 25.735276] powernow-k8: 3 : fid 0x2 (1000 MHz), vid 0x12 Additional info: It appears to be taking a long time to identify the cpu.
can you boot with initcall_debug=1 and attach the dmesg ? That might show what's happening in more detail.
Created attachment 514639 [details] Dmesg output with initcall_debug set Extract from the dmesg file with initcall_debug=1. No call seems to be taking long. So, hope the attached log helps. [ 22.177219] forcedeth 0000:00:07.0: irq 43 for MSI/MSI-X [ 32.346030] eth0: no IPv6 routers present [ 259.078209] calling powernowk8_init+0x0/0x1bc [powernow_k8] @ 2132 [ 259.078226] powernow-k8: Found 1 AMD Athlon(tm) 64 X2 Dual Core Processor 4200+ (2 cpu cores) (version 2.20.00) [ 259.078303] powernow-k8: 0 : fid 0xe (2200 MHz), vid 0xe [ 259.078306] powernow-k8: 1 : fid 0xc (2000 MHz), vid 0x10 [ 259.078309] powernow-k8: 2 : fid 0xa (1800 MHz), vid 0x10 [ 259.078311] powernow-k8: 3 : fid 0x2 (1000 MHz), vid 0x12 [ 259.078598] initcall powernowk8_init+0x0/0x1bc [powernow_k8] returned 0 after 360 usecs
strange, we don't seem to be spending time in the kernel between 32s and 259s. Try rdinitdebug. Perhaps that will show up something in the userspace initramfs.
Created attachment 514925 [details] Dmesg output with rdinitdebug and initcall_debug set Stranger still. The problem seems to disappear with rdinitdebug! [ 22.882568] forcedeth 0000:00:07.0: irq 43 for MSI/MSI-X [ 24.968829] calling powernowk8_init+0x0/0x1bc [powernow_k8] @ 2100 [ 24.968844] powernow-k8: Found 1 AMD Athlon(tm) 64 X2 Dual Core Processor 4200+ (2 cpu cores) (version 2.20.00) I have checked it a couple of times but will keep checking in case it shows up with rdinitdebug, If so, I will submit another dmesg log.
Does this still happen with the 2.6.40.6 kernel update?
Sadly, yes. Dmesg extract: [ 18.663927] EXT4-fs (sda7): mounted filesystem with ordered data mode. Opts: (null) [ 19.499608] /usr/sbin/gpm[1793]: *** info [daemon/startup.c(136)]: [ 19.499622] /usr/sbin/gpm[1793]: Started gpm successfully. Entered daemon mode. [ 23.052986] ip6_tables: (C) 2000-2006 Netfilter Core Team [ 23.079778] multipathd (1893): /proc/1893/oom_adj is deprecated, please use /proc/1893/oom_score_adj instead. [ 23.320150] nf_conntrack version 0.5.0 (16384 buckets, 65536 max) [ 23.955204] forcedeth 0000:00:07.0: irq 43 for MSI/MSI-X [ 34.594020] eth0: no IPv6 routers present [ 105.500883] powernow-k8: Found 1 AMD Athlon(tm) 64 X2 Dual Core Processor 4200+ (2 cpu cores) (version 2.20.00) [ 105.500944] powernow-k8: fid 0xe (2200 MHz), vid 0xe [ 105.500947] powernow-k8: fid 0xc (2000 MHz), vid 0x10 [ 105.500949] powernow-k8: fid 0xa (1800 MHz), vid 0x10 [ 105.500951] powernow-k8: fid 0x2 (1000 MHz), vid 0x12 But now the symptoms seem to be present even with kernel options rdinitdebug initcall_debug=1 [ 22.788681] calling ip6_tables_init+0x0/0xaa [ip6_tables] @ 1898 [ 22.788718] ip6_tables: (C) 2000-2006 Netfilter Core Team [ 22.788725] initcall ip6_tables_init+0x0/0xaa [ip6_tables] returned 0 after 33 usecs [ 22.881220] calling ip6table_filter_init+0x0/0x6c [ip6table_filter] @ 1900 [ 22.881255] initcall ip6table_filter_init+0x0/0x6c [ip6table_filter] returned 0 after 25 usecs [ 22.956126] calling nf_conntrack_standalone_init+0x0/0x12 [nf_conntrack] @ 1903 [ 22.956136] nf_conntrack version 0.5.0 (16384 buckets, 65536 max) [ 22.956570] initcall nf_conntrack_standalone_init+0x0/0x12 [nf_conntrack] returned 0 after 418 usecs [ 22.960901] calling state_mt_init+0x0/0x12 [xt_state] @ 1903 [ 22.960912] initcall state_mt_init+0x0/0x12 [xt_state] returned 0 after 2 usecs [ 22.973751] multipathd (1896): /proc/1896/oom_adj is deprecated, please use /proc/1896/oom_score_adj instead. [ 23.138626] calling nf_defrag_init+0x0/0x51 [nf_defrag_ipv6] @ 1905 [ 23.138656] initcall nf_defrag_init+0x0/0x51 [nf_defrag_ipv6] returned 0 after 19 usecs [ 23.144845] calling nf_conntrack_l3proto_ipv6_init+0x0/0xfa [nf_conntrack_ipv6] @ 1905 [ 23.144878] initcall nf_conntrack_l3proto_ipv6_init+0x0/0xfa [nf_conntrack_ipv6] returned 0 after 24 usecs [ 23.328360] calling reject_tg6_init+0x0/0x12 [ip6t_REJECT] @ 1914 [ 23.328374] initcall reject_tg6_init+0x0/0x12 [ip6t_REJECT] returned 0 after 3 usecs [ 23.835191] forcedeth 0000:00:07.0: irq 43 for MSI/MSI-X [ 33.930019] eth0: no IPv6 routers present [ 105.478112] calling powernowk8_init+0x0/0x1b7 [powernow_k8] @ 2345 [ 105.478128] powernow-k8: Found 1 AMD Athlon(tm) 64 X2 Dual Core Processor 4200+ (2 cpu cores) (version 2.20.00) [ 105.478182] powernow-k8: fid 0xe (2200 MHz), vid 0xe [ 105.478185] powernow-k8: fid 0xc (2000 MHz), vid 0x10 [ 105.478187] powernow-k8: fid 0xa (1800 MHz), vid 0x10 [ 105.478189] powernow-k8: fid 0x2 (1000 MHz), vid 0x12 [ 105.478427] initcall powernowk8_init+0x0/0x1b7 [powernow_k8] returned 0 after 297 usecs By looking at the extract from the messages log, could it be somehow related to rpc? Oct 12 22:53:40 amd rpc.statd[2352]: Version 1.2.4 starting Oct 12 22:53:40 amd kernel: [ 105.478128] powernow-k8: Found 1 AMD Athlon(tm) 64 X2 Dual Core Processor 4200+ (2 cpu cores) (version 2.20.00) Oct 12 22:53:40 amd kernel: [ 105.478182] powernow-k8: fid 0xe (2200 MHz), vid 0xe Oct 12 22:53:40 amd kernel: [ 105.478185] powernow-k8: fid 0xc (2000 MHz), vid 0x10 Oct 12 22:53:40 amd kernel: [ 105.478187] powernow-k8: fid 0xa (1800 MHz), vid 0x10 Oct 12 22:53:40 amd kernel: [ 105.478189] powernow-k8: fid 0x2 (1000 MHz), vid 0x12 Oct 12 22:53:40 amd kernel: [ 105.676523] RPC: Registered named UNIX socket transport module. Thanks & regards Anil
At the point where it hangs, the initramfs code has already switched to the on-disk rootfs so it's not hanging there. It doesn't seem to really be hanging in the kernel itself, as Dave pointed out in comment #3. Do you think you could install bootchart and get the output of a boot with that? Perhaps a service is hanging waiting on something.
Thanks for the pointer. Bootchart creates very pretty pictures - nice to learn something new. Looking at the picture, I recalled one of the kernel developers complaining about virtualbox driver. The system seemed to be taking a long time in ltspfs-entry. Decided to un-install virtualbox-4.1 and the system now boots in 54 sec! I will attach the png files with virtualbox installed and after removing it in case it is of interest to anyone.
Created attachment 528174 [details] Bootchart output when VirtualBox-4.1 is installed.
Created attachment 528175 [details] Bootchart output after removing VirtualBox-4.1
Thank you for the information. This doesn't appear to be a kernel issue, as we've said before. Given that things boot normally without VirtualBox installed, I'm going to close this bug out. I've CC'd Frank from the VirtualBox team so they are aware. You might want to discuss the issue with that team.
So far unable to reproduce. Have Fedora 15 here with VirtualBox 4.1.4 installed and it boots fine. Looks like a non-standard configuration but we will further try to analyze the problem.
Anil, do you have VirtualBox 4.1 on the Lenovo netbook installed as well? If so, can you provide any comments if the configuration of the Lenovo netbook differs from the AMD box?
Frank, I tried VirtualBox 4.1 on Lenovo and no issues. Aside from more applications and services being installed (from the common Fedora repositories) on AMD desktop, there is no substantial difference in the two installations. I was curious and tried VirtualBox 4.0 on the AMD machine and no problems! In the bootchart, the difference somehow seems to lie in the ltspfs_entry. If there is any more information/data I can provide, I will be happy to file a bug report on the VirtualBox site. The Thanks
Anil, thanks for the additional information. It is still totally mysterious to us why it took so much longer to boot your AMD box when you had VirtualBox 4.1 installed. The ltspfs daemon seems to wait for the network interface getting up. But at this time it is actually too early to blame the VirtualBox modules so we think the problem you had vanished only by coincidence when you uninstalled VirtualBox 4.1. If you have some minutes it would be a helpful test if you could try the following: Uninstall VirtualBox 4.0 and reinstall VirtualBox 4.1, then reboot to test if you get the long boot time again. Thanks in advance!
Frank, you are probably right that it was a coincidence. I replaced VirtualBox 4.0 by 4.1 and the problem hasn't shown up on 3 reboots. I hope whatever it was, it stays away.