Created attachment 683258 [details] dmesg output that exhibits results of misparsing Description of problem: My system does not pick up the EDID from my LCD display, so I needed the following parameter in the kernel command line: drm_kms_helper.edid_firmware=edid/1280x1024.bin In Fedora 16, I used a self-compiled kernel and added the line. Now I have just installed Fedora 18, and CONFIG_DRM_LOAD_EDID_FIRMWARE is supposed to be set. However, when I try to add the same parameter to the stock Fedora 18 kernel, KMS breaks, and I get the following line in dmesg: [ 1.176589] drm_kms_helper: Unknown parameter `bin' It seems that something in the kernel is misparsing the command line and attempting to pick up "bin" at the end of the command line as the parameter for drm_kms_helper, instead of "edid_firmware". Version-Release number of selected component (if applicable): kernel-3.7.2-201.fc18.x86_64 How reproducible: Always Steps to Reproduce: 1. Boot the system and pause it at the GRUB screen 2. Select current kernel, and add, say "drm_kms_helper.edid_firmware=aaaaa.bbbbb" to the command line 3. Boot the kernel with the modified command line Actual results: [ 1.194711] drm_kms_helper: Unknown parameter `bbbbb' Expected results: System should attempt to look up "aaaaa.bbbbb" as a firmware file Additional info: Vanilla kernel 3.7 through 3.8-rc3 are free of this bug.
I take the 3.8-rc3 comment back. Apparently the parsing worked when compiled under Fedora 16. Now vanilla 3.8-rc4 exhibits the bug too under Fedora 18. Is this some sort of compiler bug?
I emailed Rusty Russell about this, and he says this is a known kmod bug fixed by this commit: commit 66f3228d17d66d7e2dd484427259290fbc82b2f0 Author: Lucas De Marchi <lucas.demarchi> Date: Mon Oct 8 19:04:16 2012 -0300 libkmod: Add support for '.' in module parameter on kcmdline Otherwise we fail to parse arguments in kernel command line like testmodule.testparam=1.5G Suggested-by: Selim T. Erdogan <selim.utexas.edu> So this is a kmod bug, not a kernel bug. Please publish an kmod update that includes this commit. https://bugzilla.redhat.com/show_bug.cgi?id=883805
OK.
kmod-12-1.fc18 has been submitted as an update for Fedora 18. https://admin.fedoraproject.org/updates/kmod-12-1.fc18
Package kmod-12-1.fc18: * should fix your issue, * was pushed to the Fedora 18 testing repository, * should be available at your local mirror within two days. Update it with: # su -c 'yum update --enablerepo=updates-testing kmod-12-1.fc18' as soon as you are able to. Please go to the following url: https://admin.fedoraproject.org/updates/FEDORA-2013-1482/kmod-12-1.fc18 then log in and leave karma (feedback).
I tried updating kmod and kmod-libs from updates-testing before doing a yum update. This latest ordinary update happened to offer a kernel update to kernel-3.7.4-204.fc18.x86_64 , so I used that for testing. When I added the line drm_kms_helper.edid_firmware=edid/1280x1024.bin , the kernel boot process hanged for half a minute (?!?!?), but then continued normally and obeyed the parameter. The good news is that the kernel parameter was parsed correctly. The bad news is that the delay in the kernel boot is unacceptable. If I remove the drm_kms_helper line, then the kernel boots without delays, just as before. The kernel delay is apparent in the dmesg output: [ 0.879583] systemd[1]: Starting Local File Systems. [ 0.879601] systemd[1]: Reached target Local File Systems. [ 1.003678] systemd-udevd[123]: starting version 197 [ 1.161523] [drm] Initialized drm 1.1.0 20060810 [ 1.183925] checking generic (d0000000 130000) vs hw (d0000000 10000000) [ 1.183928] fb: conflicting fb hw usage inteldrmfb vs VESA VGA - removing generic driver [ 0.714564] ACPI: Invalid Power Resource to register! [ 1.183942] Console: switching [ 1.183943] to colour dummy device 80x25 [ 1.184032] i915 0000:00:02.0: setting latency timer to 64 [ 1.206537] i915 0000:00:02.0: irq 42 for MSI/MSI-X [ 1.206546] [drm] Supports vblank timestamp caching Rev 1 (10.10.2010). [ 1.206547] [drm] Driver supports precise vblank timestamp query. [ 1.206577] vgaarb: device changed decodes: PCI:0000:00:02.0,olddecodes=io+mem,decodes=io+mem:owns=io+mem [ 1.207743] [drm] initialized overlay support [ 1.291200] input: ImPS/2 Generic Wheel Mouse as /devices/platform/i8042/serio1/input/input3 [ 1.440027] tsc: Refined TSC clocksource calibration: 2755.321 MHz [ 1.440035] Switching to clocksource tsc [ 31.613019] EXT4-fs (sdb2): mounted filesystem with ordered data mode. Opts: (null) [ 31.758218] EXT4-fs (sdb2): mounted filesystem with ordered data mode. Opts: (null) [ 61.408164] [drm] Got built-in EDID base block and 0 extensions from "edid/1280x1024.bin" for connector "VGA-1" [ 61.413664] fbcon: inteldrmfb (fb0) is primary device [ 61.481068] Console: switching to colour frame buffer device 160x64 [ 61.486625] fb0: inteldrmfb frame buffer device [ 61.486627] drm: registered panic notifier [ 61.486677] [drm] Initialized i915 1.6.0 20080730 for 0000:00:02.0 on minor 0 [ 61.574967] systemd-journald[64]: Received SIGTERM [ 62.094118] type=1404 audit(1359241072.059:2): enforcing=1 old_enforcing=0 auid=4294967295 ses=4294967295 Notice the jump from 1.440035 to 31.613019.
Created attachment 688186 [details] dmesg after kmod-12 update, shows 30-second delay in boot process
You have two delays here. The first seems to be mounting the ext4 filesystem on sdb2 of ~30 seconds. That seems unrelated. The second delay is ~60 seconds from the last DRM printk to the EDID loading line. That happens to be the amount of time the in-kernel firmware loader will wait before the firmware is loaded. My guess here is that your rootfs is on sdb2. The drm layer makes it's request_firmware call before your rootfs is loaded, and the .bin file for your EDID information is not included in your initramfs. Since the rootfs isn't mounted yet, it can't access the file directly and has to do the timeout route. I don't think that is actually an issue in kmod at all. It's being done in the kernel, and the kernel is acting as it should. Kay, you've had quite a bit of experience with this. Does the above explanation sound plausible?
The file edid/1280x1024.bin happens to be one of the built-in EDID files. I chose that one because it fits my monitor and I did not want to deal with building my own EDID file. There are no custom EDID files under /lib/firmware, under any name. Why should the kernel wait for the filesystem to be mounted before loading a built-in EDID? This same command line parameter caused no delays whatsoever under Fedora 16. Additionally, why should the kernel parameter for drm cause a delay on filesystem mount? There are no delays at all when I remove the drm_kms_helper parameter. If the kernel wants to hit the filesystem before checking that the EDID is a built-in one, it should hurry up and mount sdb2 as soon as possible.
The drm_kms_helper calls request_firmware before it searches the built-in firmwares. Saying something works in F16 isn't particularly helpful as there are several differences. Namely, the 3.7 kernel changed how it loads firmware because udev changed how it handles firmware/module loading as well. I forget all the details but Kay should remember.
I verified on 3.8-rc5 that the kernel uses request_firmware first. I patched and compiled 3.8-rc5 with the load order reversed (builtin, then request_firmware), and this makes the kernel proceed immediately (no filesystem mount delay). However, this still does not explain why the filesystem mount would get a delay if request_firmware is called before the filesystem is mounted. I used to boot 3.8-rc3 under Fedora 16, and there were no delays, without any need to patch the kernel. Why does the request_firmware call delay the filesystem mount in Fedora 18?
This is the log from the initramfs, and I would suspect both timeouts are caused by a firmware request which cannot be fulfilled. As you said above, caused by missing firmware files inside the initramfs. Udev gives up waiting for its event handler after 30 seconds, that might be the 2 timeouts we see here, likely a blocking module_init(). The drm driver unconditionally calls request_firmware(), if that happens inside the initramfs, udev will not cancel the request but leave it stay around until we reach the udev in the real rootfs. We no longer cancel firmware requests in the initramfs, to be able to handle them after the rootfs is mounted. It was supposed to work around a set of other problems with missing firmware files in the initramfs. From a general view, this seems all too fragile, and whatever behaviour we change with the userspace firmware loading, it seems to cause some sort of misbehaviour somewhere else. The whole userspace firmware loading was a pretty bad idea from day one, and caused nothing but problems so far. In recent kernels, the loading is handled in a very simple and non-blocking way inside the kernel, without the need for any of the fragile userspace transaction kludge, which might block module loading for 60 seconds. We should really just get rid of the entire userspace firmware loading hackery and rely on the recent in-kernel loading only. That means adding a kernel config option for the userspace callout and disable that option in our kernel config. It is planned anyway in the long run, to remove all the firmware loading code from userspace tools, and rely solely on the in-kernel loading. The whole userspace loop was a nice theory, but after all the years, we just need to admit that theory and reality did not match; it created far more problems than it has ever solved. I see the following options to fix that: 1. make drm check for built-in firmware first, and not unconditionally call out to userspace 2. cancel all non-fulfillable firmware requests inside the initramfs, to prevent the in-kernel firmware timeouts to block module_init() 3. rely on the (robust, non-blocking) in-kernel firmware loading only, and entirely disable the (fragile, blocking) userspace firmware loading callout in the kernel I would vote for trying 3., because that is what we want in the log rune anyway.
Or 1 and 3 combined. At any rate, this bug is to fix the cmdline parsing in kmod, which it does. It's also not kmod's fault things are getting delayed. This is probably something that needs to be resolved in the upstream kernel one way or another. There's nothing kmod itself can do about it.
kmod-12-1.fc18 has been pushed to the Fedora 18 stable repository. If problems still persist, please make note of it in this bug report.
(In reply to comment #13) > Or 1 and 3 combined. We will be able to disable the userspace firmware loading. The patches are already there: https://lkml.org/lkml/2013/1/31/125 Which will put an end to the whole mess, which cause nothing but problems for all these years. :)
There was a delay of 60 seconds: https://bugzilla.redhat.com/show_bug.cgi?id=904232#c10 After upgrading to 'kmod-12-1', the delay is gone. … […14:29:06…] Kernel command line: BOOT_IMAGE=/vmlinuz-3.7.5-201.fc18.x86_64 … drm_kms_helper.edid_firmware=DVI-I-1:edid/JC07-01-WVGA-848.edid … […14:29:08…] usb 1-6: new high-speed USB device number 6 using ehci_hcd […14:29:08…] usb 1-6: New USB device found, idVendor=17e9, idProduct=019e […14:29:08…] usb 1-6: New USB device strings: Mfr=1, Product=2, SerialNumber=3 … […14:29:09…] usb 1-6: Product: FY USB-DVI […14:29:09…] usb 1-6: Manufacturer: DisplayLink […14:29:09…] usb 1-6: SerialNumber: USB_FY1704 … […14:29:10…] [drm] Initialized drm 1.1.0 20060810 […14:29:10…] drm_kms_helper: Unknown parameter `edid' … […14:29:25…] [drm] vendor descriptor length:1b data:1b 5f 01 00 19 05 00 01 03 00 04 … […14:29:25…] [drm] Got external EDID base block and 0 extensions from "edid/JC07-01-WVGA-848.edid" for connector "DVI-I-1" … […14:29:25…] open /dev/fb0 user=0 fb_info=ffff8800c7f2a800 count=1 […14:29:25…] [drm] write mode info 153 […14:29:25…] Console: switching to colour frame buffer device 100x37 … […14:29:25…] fb0: udldrmfb frame buffer device […14:29:25…] drm: registered panic notifier […14:29:25…] [drm] Initialized udl 0.0.1 20120220 on minor 0 … […14:29:25…] usbcore: registered new interface driver udl … […14:29:26…] released /dev/fb0 user=0 count=0 … […14:29:40…] [drm] Got external EDID base block and 0 extensions from "edid/JC07-01-WVGA-848.edid" for connector "DVI-I-1" […14:29:40…] [drm] Got external EDID base block and 0 extensions from "edid/JC07-01-WVGA-848.edid" for connector "DVI-I-1" […14:29:40…] [drm] write mode info 153 […14:29:43…] [drm] Got external EDID base block and 0 extensions from "edid/JC07-01-WVGA-848.edid" for connector "DVI-I-1" … […14:29:48…] [drm] Got external EDID base block and 0 extensions from "edid/JC07-01-WVGA-848.edid" for connector "DVI-I-1" … In parallel with these, /etc/modprobe.d/drm_kms_helper.conf: options drm_kms_helper edid_firmware=DVI-I-1:edid/JC07-01-WVGA-848.edid actually has no effect. Is this just a placeholder parameter or what?
(In reply to comment #16) > There was a delay of 60 seconds: > https://bugzilla.redhat.com/show_bug.cgi?id=904232#c10 > After upgrading to 'kmod-12-1', the delay is gone. It turned out that the kernel 3.7.5-201 is an exception[1]. No success even with 3.8.0-0.rc7.git0.1.fc19.x86_64. [1] https://bugzilla.redhat.com/show_bug.cgi?id=904232#c12
Resolved with a third(sys) method :) https://bugzilla.redhat.com/show_bug.cgi?id=904232#c13 Cheers, poma