Bug 754581

Summary: slow boot in F15, applying microcode update
Product: [Fedora] Fedora Reporter: Ian Malone <ibmalone>
Component: microcode_ctlAssignee: Anton Arapov <anton>
Status: CLOSED RAWHIDE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 15CC: anton, jonathan, nobody
Target Milestone: ---Keywords: Reopened
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2012-07-25 22:09:25 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Attachments:
Description Flags
dmesg output none

Description Ian Malone 2011-11-16 21:46:43 UTC 
Description of problem:
Fedora 15 takes a long time to start GDM after the progress bar during boot is filled. Pressing esc to watch services come up shows it's not really doing anything => systemd is waiting for something. Looking at dmesg I see this:
[   49.201076] SELinux: initialized (dev sdb2, type ext3), uses xattr
[   86.752098] microcode: failed to load file amd-ucode/microcode_amd.bin
[   86.752109] microcode: CPU2: patch_level=0x010000b6
[  147.936104] microcode: failed to load file amd-ucode/microcode_amd.bin
[  147.936133] microcode: CPU3: patch_level=0x010000b6
[  200.300599] systemd[1]: udev-settle.service: main process exited, code=exited, status=1

Note timestamps for contiguous lines span 2.5 minutes. CPU0 and CPU1 are much earlier, their lines look like (including a bit of context):
[   20.375573] AMD64 EDAC driver v3.4.0
[   20.377749] EDAC amd64: DRAM ECC disabled.
[   20.377764] EDAC amd64: ECC disabled in the BIOS or no ECC capability, module
 will not load.
[   20.377765]  Either enable ECC checking or force module loading by setting 'e
cc_enable_override'.
[   20.377766]  (Note that use of the override may cause unknown side effects.)
[   20.660267] microcode: CPU0: patch_level=0x010000b6
[   25.670084] i2c i2c-0: nForce2 SMBus adapter at 0x4c00

and...
[   26.155383] cfg80211:     (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[   26.243334] microcode: CPU1: patch_level=0x010000b6
[   26.558247] mtp-probe[847]: checking bus 2, device 3: "/sys/devices/pci0000:00/0000:00:0b.0/usb2/2-6"

Later there is:
[  206.248100] udevd[518]: worker [530] unexpectedly returned with status 0x0100
[  206.248351] udevd[518]: worker [530] failed while handling '/devices/platform
/microcode/firmware/microcode'
[  206.248784] udevd[518]: worker [533] unexpectedly returned with status 0x0100
[  206.249034] udevd[518]: worker [533] failed while handling '/devices/platform
/microcode/firmware/microcode'

...and:
[  208.864102] microcode: failed to load file amd-ucode/microcode_amd.bin
[  208.865313] microcode: Microcode Update Driver: v2.00 <tigran.co.uk>, Peter Oruba
[  208.878060] Loading kernel module for a network device with CAP_SYS_MODULE (deprecated).  Use CAP_NET_ADMIN and alias netdev-microcode instead
[  208.878692] Loading kernel module for a network device with CAP_SYS_MODULE (deprecated).  Use CAP_NET_ADMIN and alias netdev-microcode instead
[  208.881547] Loading kernel module for a network device with CAP_SYS_MODULE (deprecated).  Use CAP_NET_ADMIN and alias netdev-microcode instead
[  208.883813] Loading kernel module for a network device with CAP_SYS_MODULE (deprecated).  Use CAP_NET_ADMIN and alias netdev-microcode instead
[  208.900198] Loading kernel module for a network device with CAP_SYS_MODULE (deprecated).  Use CAP_NET_ADMIN and alias netdev-microcode instead
[  208.906100] Loading kernel module for a network device with CAP_SYS_MODULE (deprecated).  Use CAP_NET_ADMIN and alias netdev-microcode instead
[  208.912101] Loading kernel module for a network device with CAP_SYS_MODULE (deprecated).  Use CAP_NET_ADMIN and alias netdev-microcode instead


Version-Release number of selected component (if applicable):
Updated microcode_ctl:
Nov 12 12:08:47 Updated: 1:microcode_ctl-1.17-19.fc15.x86_64


How reproducible:
On boot.

When I get a chance I'll try downgrading to confirm it's this component, the other possibility is a systemd update on the 12th which has exposed a pre-existing problem.

cat /proc/cpuinfo 
processor	: 0
vendor_id	: AuthenticAMD
cpu family	: 16
model		: 5
model name	: AMD Athlon(tm) II X4 640 Processor
stepping	: 3
cpu MHz		: 800.000
cache size	: 512 KB
physical id	: 0
siblings	: 4
core id		: 0
cpu cores	: 4
apicid		: 0
initial apicid	: 0
fpu		: yes
fpu_exception	: yes
cpuid level	: 5
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt pdpe1gb rdtscp lm 3dnowext 3dnow constant_tsc rep_good nopl nonstop_tsc extd_apicid pni monitor cx16 popcnt lahf_lm cmp_legacy svm extapic cr8_legacy abm sse4a misalignsse 3dnowprefetch osvw ibs skinit wdt npt lbrv svm_lock nrip_save
bogomips	: 6012.46
TLB size	: 1024 4K pages
clflush size	: 64
cache_alignment	: 64
address sizes	: 48 bits physical, 48 bits virtual
power management: ts ttp tm stc 100mhzsteps hwpstate

processor	: 1
vendor_id	: AuthenticAMD
cpu family	: 16
model		: 5
model name	: AMD Athlon(tm) II X4 640 Processor
stepping	: 3
cpu MHz		: 800.000
cache size	: 512 KB
physical id	: 0
siblings	: 4
core id		: 1
cpu cores	: 4
apicid		: 1
initial apicid	: 1
fpu		: yes
fpu_exception	: yes
cpuid level	: 5
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt pdpe1gb rdtscp lm 3dnowext 3dnow constant_tsc rep_good nopl nonstop_tsc extd_apicid pni monitor cx16 popcnt lahf_lm cmp_legacy svm extapic cr8_legacy abm sse4a misalignsse 3dnowprefetch osvw ibs skinit wdt npt lbrv svm_lock nrip_save
bogomips	: 6012.37
TLB size	: 1024 4K pages
clflush size	: 64
cache_alignment	: 64
address sizes	: 48 bits physical, 48 bits virtual
power management: ts ttp tm stc 100mhzsteps hwpstate

processor	: 2
vendor_id	: AuthenticAMD
cpu family	: 16
model		: 5
model name	: AMD Athlon(tm) II X4 640 Processor
stepping	: 3
cpu MHz		: 800.000
cache size	: 512 KB
physical id	: 0
siblings	: 4
core id		: 2
cpu cores	: 4
apicid		: 2
initial apicid	: 2
fpu		: yes
fpu_exception	: yes
cpuid level	: 5
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt pdpe1gb rdtscp lm 3dnowext 3dnow constant_tsc rep_good nopl nonstop_tsc extd_apicid pni monitor cx16 popcnt lahf_lm cmp_legacy svm extapic cr8_legacy abm sse4a misalignsse 3dnowprefetch osvw ibs skinit wdt npt lbrv svm_lock nrip_save
bogomips	: 6012.39
TLB size	: 1024 4K pages
clflush size	: 64
cache_alignment	: 64
address sizes	: 48 bits physical, 48 bits virtual
power management: ts ttp tm stc 100mhzsteps hwpstate

processor	: 3
vendor_id	: AuthenticAMD
cpu family	: 16
model		: 5
model name	: AMD Athlon(tm) II X4 640 Processor
stepping	: 3
cpu MHz		: 800.000
cache size	: 512 KB
physical id	: 0
siblings	: 4
core id		: 3
cpu cores	: 4
apicid		: 3
initial apicid	: 3
fpu		: yes
fpu_exception	: yes
cpuid level	: 5
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt pdpe1gb rdtscp lm 3dnowext 3dnow constant_tsc rep_good nopl nonstop_tsc extd_apicid pni monitor cx16 popcnt lahf_lm cmp_legacy svm extapic cr8_legacy abm sse4a misalignsse 3dnowprefetch osvw ibs skinit wdt npt lbrv svm_lock nrip_save
bogomips	: 6012.38
TLB size	: 1024 4K pages
clflush size	: 64
cache_alignment	: 64
address sizes	: 48 bits physical, 48 bits virtual
power management: ts ttp tm stc 100mhzsteps hwpstate
Comment 1 Ian Malone 2011-11-16 22:23:33 UTC 
Okay, it seems I can't reproduce this, have even tried cold booting. Very strange:

[   19.396330] microcode: CPU0: patch_level=0x010000b6
[   20.002419] microcode: CPU1: patch_level=0x010000b6
[   20.006583] microcode: CPU2: patch_level=0x010000b6
[   20.010624] microcode: CPU3: patch_level=0x010000b6
[   20.014899] microcode: Microcode Update Driver: v2.00 <tigran.co.uk>, Peter Oruba

Sorry for the BZ noise.
Comment 2 Ian Malone 2011-11-18 22:35:57 UTC 
Created attachment 534513 [details]
dmesg output

Okay, this has happened again, so it's not a one-off, but not very reproducible. I'm wondering if there's a hardware or timing issue in play. The only common factor is that both times I've seen it it was the machine being switched on from cold. Even then though it's not reliable, because switching it on in the morning hasn't caused it yet. Powering down and starting up again hasn't managed to cause it.
Attaching dmesg output in case it's useful.
Comment 3 Ian Malone 2011-11-18 22:36:38 UTC 
May as well reopen in case this can be chased down.
Comment 4 Anton Arapov 2011-11-23 12:43:25 UTC 
Thanks for reporting this issue, I will look into it.
Comment 5 Anton Arapov 2012-07-25 22:09:25 UTC 
The issue was due to incorrect udev rule. It is not used anymore.