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


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

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@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 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@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 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.