Note: This is a public test instance of Red Hat Bugzilla. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback at bugzilla.redhat.com.
Bug 560031 - 'modprobe microcode' takes 2 minutes. Boot hangs for 2 minutes.....
Summary: 'modprobe microcode' takes 2 minutes. Boot hangs for 2 minutes.....
Keywords:
Status: CLOSED RAWHIDE
Alias: None
Product: Fedora
Classification: Fedora
Component: udev
Version: rawhide
Hardware: All
OS: Linux
low
medium
Target Milestone: ---
Assignee: Harald Hoyer
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
: 561824 (view as bug list)
Depends On:
Blocks: F13Blocker, F13FinalBlocker
TreeView+ depends on / blocked
 
Reported: 2010-01-29 17:31 UTC by Tom London
Modified: 2010-03-03 20:37 UTC (History)
12 users (show)

Fixed In Version: udev-151-3.fc13
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2010-02-10 15:09:04 UTC
Type: ---
Embargoed:

Attachments (Terms of Use)
Output of 'dmesg' (deleted)
2010-01-29 17:31 UTC, Tom London 		no flags Details
/var/log/messages output with 'udevadm control --log-priority=debug' (deleted)
2010-02-01 14:33 UTC, Tom London 		no flags Details
View All

Description Tom London 2010-01-29 17:31:57 UTC 
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.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 05:33:01 UTC 
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 21:01:06 UTC 
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 09:21:14 UTC 
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 14:33:07 UTC 
Created attachment 388054 [details]
/var/log/messages output with 'udevadm control --log-priority=debug'

As requested.....
Comment 5 Harald Hoyer 2010-02-01 14:53:21 UTC 
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 14:55:59 UTC 
'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 14:57:36 UTC 
see also bug #248307
Comment 8 James Laska 2010-02-05 15:42:38 UTC 
*** Bug 561824 has been marked as a duplicate of this bug. ***
Comment 9 James Laska 2010-02-05 17:37:39 UTC 
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 18:01:51 UTC 
At least on my system, it is 1 minute per core/CPU (2 cores).
Comment 11 Kyle McMartin 2010-02-06 19:05:02 UTC 
Thanks, reproduced. Trying to figure this out.
Comment 12 Kyle McMartin 2010-02-06 20:37:50 UTC 
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-07 04:23:51 UTC 
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>
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 05:30:19 UTC 
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 16:24:34 UTC 
Great, thanks for testing! It'll be 'fixed' by the next kernel too.
Comment 16 Harald Hoyer 2010-02-09 10:10:42 UTC 
udev-151-3.fc13
Comment 17 Tom London 2010-02-09 14:34:18 UTC 
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 14:54:26 UTC 
I can confirm the fix with 2.6.33-0.40.rc7.git0.fc13.x86_64.
Comment 19 Tom London 2010-02-10 15:07:01 UTC 
Updated udev has hit rawhide.

Close?
Comment 20 James Laska 2010-03-03 20:37:18 UTC 
This is fixed in F-13-Alpha, removing CommonBugs keyword
Note You need to log in before you can comment on or make changes to this bug.