Bug 560031

Summary: 'modprobe microcode' takes 2 minutes. Boot hangs for 2 minutes.....
Product: [Fedora] Fedora Reporter: Tom London <selinux>
Component: udevAssignee: Harald Hoyer <harald>
Status: CLOSED RAWHIDE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: low    
Version: rawhideCC: anton, clydekunkel7734, dougsland, gansalmon, harald, itamar, jlaska, jonathan, kernel-maint, kmcmartin, kparal, ruben
Target Milestone: ---Keywords: Reopened
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: udev-151-3.fc13 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2010-02-10 10:09:04 EST Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---
Bug Depends On:    
Bug Blocks: 507681    
Attachments:
Description Flags
Output of 'dmesg'
none
/var/log/messages output with 'udevadm control --log-priority=debug' none

Description Tom London 2010-01-29 12:31:57 EST
Created attachment 387606 [details]
Output of 'dmesg'

Description of problem:
I noticed booting was hanging at the "apply Intel microcode" step for a few minutes.

Instrumenting /etc/init.d/microcode_ctl a bit, it seems to hang at the '/sbin/modprobe microcode' step.

If I run that command from a terminal, I see:

[root@tlondon ~]# time modprobe -v microcode
insmod /lib/modules/2.6.33-0.23.rc5.git1.fc13.x86_64/kernel/arch/x86/kernel/microcode.ko 

real	2m0.015s
user	0m0.000s
sys	0m0.012s
[root@tlondon ~]# 

A 2 minute hang.....

Examining /var/log/messages, looks like it is taking 1 minute per core:

Jan 29 09:28:06 tlondon kernel: microcode: CPU0 sig=0x10676, pf=0x80, revision=0x60c
Jan 29 09:28:06 tlondon kernel: platform microcode: firmware: requesting intel-ucode/06-17-06
Jan 29 09:29:06 tlondon kernel: microcode: CPU1 sig=0x10676, pf=0x80, revision=0x60c
Jan 29 09:29:06 tlondon kernel: platform microcode: firmware: requesting intel-ucode/06-17-06
Jan 29 09:30:06 tlondon kernel: microcode: Microcode Update Driver: v2.00 <tigran@aivazian.fsnet.co.uk>, Peter Oruba
Jan 29 09:30:07 tlondon kernel: microcode: Microcode Update Driver: v2.00 removed.

[I ran the rmmod right after the modprobe to get a time in /var/log/messages.] 

Not sure what else to provide, but am attaching output of 'dmesg'.

Version-Release number of selected component (if applicable):
kernel-2.6.33-0.23.rc5.git1.fc13.x86_64

How reproducible:
Every boot, every 'modprobe microcode'

Steps to Reproduce:
1. Boot; hangs at microcode update
2. Or, "time modprobe microcode"
3.
  
Actual results:
2 minute hang.... (one minute per CPU?)

Expected results:


Additional info:
Comment 1 Clyde E. Kunkel 2010-01-30 00:33:01 EST
Strange...experienced same thing, but reverted udev et al to 147-2.fc13.x86_64 fixed it for me.
Comment 2 Tom London 2010-01-30 16:01:06 EST
Thanks.  I can confirm that downgrading to udev-147-2.fc13.x86_64 "makes it work for me".

Doesn't work with either udev-151-1.fc13.x86_64.rpm or with udev-151-2.fc13.x86_64.rpm.

Reassigning to udev......
Comment 3 Harald Hoyer 2010-02-01 04:21:14 EST
Hmm, the firmware loading code changed from a shell script (firmware.sh) to a binary.

/lib/udev/firmware
/lib/udev/rules.d/50-firmware.rules


Can you put udev in debug mode?

# udevadm control --log-priority=debug
# modprobe microcode

and post the messages in /var/log/messages
Comment 4 Tom London 2010-02-01 09:33:07 EST
Created attachment 388054 [details]
/var/log/messages output with 'udevadm control --log-priority=debug'

As requested.....
Comment 5 Harald Hoyer 2010-02-01 09:53:21 EST
firmware --firmware=intel-ucode/06-17-06 --devpath=/devices/platform/microcode/firmware/microcode

seems like the firmware is expected to be in

/lib/firmware/intel-ucode/06-17-06

Either this is a bug for the microcode_ctl package or the kernel module.
Comment 6 Harald Hoyer 2010-02-01 09:55:59 EST
'trying /lib/firmware/updates/2.6.33-0.25.rc6.git0.fc13.x86_64/intel-ucode/06-17-06'
'trying /lib/firmware/updates/intel-ucode/06-17-06'
'trying /lib/firmware/2.6.33-0.25.rc6.git0.fc13.x86_64/intel-ucode/06-17-06'
'did not find firmware file 'intel-ucode/06-17-06''
Comment 7 Harald Hoyer 2010-02-01 09:57:36 EST
see also bug #248307
Comment 8 James Laska 2010-02-05 10:42:38 EST
*** Bug 561824 has been marked as a duplicate of this bug. ***
Comment 9 James Laska 2010-02-05 12:37:39 EST
Sounds like this problem my be more than 2 minutes on some systems.  Adding keyword CommonBugs so this is noted if still present during Alpha release.
Comment 10 Tom London 2010-02-05 13:01:51 EST
At least on my system, it is 1 minute per core/CPU (2 cores).
Comment 11 Kyle McMartin 2010-02-06 14:05:02 EST
Thanks, reproduced. Trying to figure this out.
Comment 12 Kyle McMartin 2010-02-06 15:37:50 EST
Sigh, looks like udev is polling waiting for something to happen, but intel microcode is shipped as a compilation loaded by microcode_ctl instead of request_firmware. (This avoids us having to create a pile of intel-ucode/%x-%x-%x files.)

I can't figure out what exactly udev is polling on, but it probably shouldn't do that.

Anyway, as a fix, I'll neuter that out of the request_firmware code, as I don't know of a place to get the firmware aside from as the microcode.dat file. (Nor do I particularly care.)
Comment 13 Kyle McMartin 2010-02-06 23:23:51 EST
Sorry Harald, just noticed while debugging the hang that it's fixed in udev HEAD.

http://git.kernel.org/?p=linux/hotplug/udev.git;a=commit;h=86a7a2f853fe6022c5b0c1b415918047b65533be

commit 86a7a2f853fe6022c5b0c1b415918047b65533be
Author: Thomas Bächler <thomas@archlinux.org>
Date:   Sun Jan 31 13:49:02 2010 +0100

    firmware: fix error reporting on missing firmware files
    
    The new firmware loader does not report an error to the kernel if a firmware
    is missing. This results in modprobe stalling for 60 seconds for each firmwa
    a module tries to load.

Tom, can you test: http://koji.fedoraproject.org/koji/taskinfo?taskID=1967183

Harald, patch to udev is: http://bombadil.infradead.org/~kyle/udev-151-3.patch

cheers, Kyle
Comment 14 Tom London 2010-02-07 00:30:19 EST
Yes, http://koji.fedoraproject.org/koji/taskinfo?taskID=1967183 boots "properly" with kernel-2.6.33-0.27.rc6.git1.fc13.x86_64 (that is, no 60 second stall per CPU).

I had to use "rpm -Uvh --force" to install these udev packages, since the 'version' was udev-151-2 (the same as the currently installed packages).

Thanks for tracking this down!
Comment 15 Kyle McMartin 2010-02-07 11:24:34 EST
Great, thanks for testing! It'll be 'fixed' by the next kernel too.
Comment 16 Harald Hoyer 2010-02-09 05:10:42 EST
udev-151-3.fc13
Comment 17 Tom London 2010-02-09 09:34:18 EST
Boots "fast" with both kernel-2.6.33-0.36.rc7.git0.fc13.x86_64 and kernel-2.6.33-0.40.rc7.git0.fc13.x86_64.

Thanks!
Comment 18 Kamil Páral 2010-02-09 09:54:26 EST
I can confirm the fix with 2.6.33-0.40.rc7.git0.fc13.x86_64.
Comment 19 Tom London 2010-02-10 10:07:01 EST
Updated udev has hit rawhide.

Close?
Comment 20 James Laska 2010-03-03 15:37:18 EST
This is fixed in F-13-Alpha, removing CommonBugs keyword