| Summary: | i915_init takes over 100 ms | ||
|---|---|---|---|
| Product: | DRI | Reporter: | Paul Menzel <pmenzel+bugs.freedesktop.org> |
| Component: | DRM/Intel | Assignee: | Intel GFX Bugs mailing list <intel-gfx-bugs> |
| Status: | RESOLVED MOVED | QA Contact: | Intel GFX Bugs mailing list <intel-gfx-bugs> |
| Severity: | enhancement | ||
| Priority: | low | CC: | david.weinehall, gicmo, intel-gfx-bugs, mario_limonciello, pmenzel+bugs.freedesktop.org, yang.a.shi |
| Version: | DRI git | ||
| Hardware: | Other | ||
| OS: | All | ||
| Whiteboard: | |||
| i915 platform: | KBL | i915 features: | display/Other |
| Attachments: | |||
|
Description
Paul Menzel
2018-03-20 10:23:41 UTC
Created attachment 138217 [details]
Linux 4.16-rc5+ messages
I hit *Submit* too soon by accident.
```
$ more /proc/version
Linux version 4.16.0-rc5+ (pmenzel@xps139370) (gcc version 7.3.0 (Debian 7.3.0-1
1)) #4 SMP Sun Mar 18 11:18:24 CET 2018
```
Created attachment 138219 [details]
Linux 4.16-rc6+ messages with only 25 ms and drm.debug=0x1e
It looks like, it’s not always reproducible. Attached Linux messages with `drm.debug=0x1e`, where it only took 25 ms.
Created attachment 138220 [details]
Linux 4.16-rc6+ messages with only 148 ms and drm.debug=0x1e
Here is an output where the problem manifested itself. It could be related to setting the brightness.
Nah, the time disappeared even before we were running: [ 2.331714] calling i915_init+0x0/0x59 [i915] @ 294 [ 2.331715] proc_thermal 0000:00:04.0: enabling device (0000 -> 0002) [ 2.331965] calling alsa_hwdep_init+0x0/0x1000 [snd_hwdep] @ 289 [ 2.331969] initcall alsa_hwdep_init+0x0/0x1000 [snd_hwdep] returned 0 after 2 usecs [ 2.333214] calling btusb_driver_init+0x0/0x1000 [btusb] @ 301 [ 2.333452] usbcore: registered new interface driver btusb [ 2.333456] initcall btusb_driver_init+0x0/0x1000 [btusb] returned 0 after 232 usecs [ 2.335541] calling hda_bus_init+0x0/0x11 [snd_hda_core] @ 289 [ 2.335554] initcall hda_bus_init+0x0/0x11 [snd_hda_core] returned 0 after 7 usecs [ 2.337340] Bluetooth: hci0: using rampatch file: qca/rampatch_usb_00000302.bin [ 2.337341] Bluetooth: hci0: QCA: patch rome 0x302 build 0x138, firmware rome 0x302 build 0x111 [ 2.338045] calling iTCO_vendor_init_module+0x0/0x1000 [iTCO_vendor_support] @ 280 [ 2.338046] iTCO_vendor_support: vendor-support=0 [ 2.338048] initcall iTCO_vendor_init_module+0x0/0x1000 [iTCO_vendor_support] returned 0 after 0 usecs [ 2.338094] calling uvc_init+0x0/0x1000 [uvcvideo] @ 295 [ 2.338569] calling iTCO_wdt_init_module+0x0/0x1000 [iTCO_wdt] @ 280 [ 2.338570] iTCO_wdt: Intel TCO WatchDog Timer Driver v1.11 [ 2.338713] iTCO_wdt: Found a Intel PCH TCO device (Version=4, TCOBASE=0x0400) [ 2.338755] uvcvideo: Found UVC 1.00 device Integrated_Webcam_HD (0bda:58f4) [ 2.338827] iTCO_wdt: initialized. heartbeat=30 sec (nowayout=0) [ 2.338851] initcall iTCO_wdt_init_module+0x0/0x1000 [iTCO_wdt] returned 0 after 271 usecs [ 2.340669] uvcvideo 1-5:1.0: Entity type for entity Extension 4 was not initialized! [ 2.340670] uvcvideo 1-5:1.0: Entity type for entity Extension 7 was not initialized! [ 2.340672] uvcvideo 1-5:1.0: Entity type for entity Processing 2 was not initialized! [ 2.340673] uvcvideo 1-5:1.0: Entity type for entity Camera 1 was not initialized! [ 2.340736] input: Integrated_Webcam_HD: Integrate as /devices/pci0000:00/0000:00:14.0/usb1/1-5/1-5:1.0/input/input9 [ 2.341447] uvcvideo: Unknown video format 00000032-0002-0010-8000-00aa00389b71 [ 2.341450] uvcvideo: Found UVC 1.00 device Integrated_Webcam_HD (0bda:58f4) [ 2.343371] uvcvideo: Unable to create debugfs 1-2 directory. [ 2.343420] uvcvideo 1-5:1.2: Entity type for entity Extension 10 was not initialized! [ 2.343422] uvcvideo 1-5:1.2: Entity type for entity Extension 12 was not initialized! [ 2.343423] uvcvideo 1-5:1.2: Entity type for entity Processing 9 was not initialized! [ 2.343424] uvcvideo 1-5:1.2: Entity type for entity Camera 11 was not initialized! [ 2.343472] input: Integrated_Webcam_HD: Integrate as /devices/pci0000:00/0000:00:14.0/usb1/1-5/1-5:1.2/input/input10 [ 2.343496] usbcore: registered new interface driver uvcvideo [ 2.343496] USB Video Class driver (1.1.1) [ 2.343501] initcall uvc_init+0x0/0x1000 [uvcvideo] returned 0 after 5275 usecs [ 2.368025] Bluetooth: hci0: using NVM file: qca/nvm_usb_00000302.bin [ 2.368132] calling ath10k_pci_init+0x0/0x1000 [ath10k_pci] @ 297 [ 2.368417] ath10k_pci 0000:02:00.0: enabling device (0000 -> 0002) [ 2.369278] calling serio_raw_drv_init+0x0/0x1000 [serio_raw] @ 280 [ 2.369288] initcall serio_raw_drv_init+0x0/0x1000 [serio_raw] returned 0 after 8 usecs [ 2.370528] calling init_module+0x0/0xf10 [efivars] @ 283 [ 2.370529] EFI Variables Facility v0.08 2004-May-17 [ 2.370540] calling init_fat_fs+0x0/0xfcb [fat] @ 327 [ 2.370665] initcall init_fat_fs+0x0/0xfcb [fat] returned 0 after 118 usecs [ 2.371435] ath10k_pci 0000:02:00.0: pci irq msi oper_irq_mode 2 irq_mode 0 reset_mode 0 [ 2.373899] calling pcspkr_platform_driver_init+0x0/0x1000 [pcspkr] @ 295 [ 2.374266] input: PC Speaker as /devices/platform/pcspkr/input/input11 [ 2.374594] initcall pcspkr_platform_driver_init+0x0/0x1000 [pcspkr] returned 0 after 675 usecs [ 2.377394] calling init_vfat_fs+0x0/0x1000 [vfat] @ 327 [ 2.377399] initcall init_vfat_fs+0x0/0x1000 [vfat] returned 0 after 1 usecs [ 2.383102] calling azx_driver_init+0x0/0xfd8 [snd_hda_intel] @ 289 [ 2.383159] calling joydev_init+0x0/0x1000 [joydev] @ 282 [ 2.383498] initcall joydev_init+0x0/0x1000 [joydev] returned 0 after 323 usecs [ 2.384594] calling pcsp_init+0x0/0x1000 [snd_pcsp] @ 295 [ 2.384597] Error: Driver 'pcspkr' is already registered, aborting... [ 2.384930] initcall pcsp_init+0x0/0x1000 [snd_pcsp] returned -16 after 324 usecs [ 2.394061] mei_me 0000:00:16.0: enabling device (0000 -> 0002) [ 2.395838] initcall proc_thermal_init+0x0/0x1000 [processor_thermal_device] returned 0 after 176806 usecs [ 2.397894] calling evdev_init+0x0/0x1000 [evdev] @ 301 [ 2.402423] initcall init_module+0x0/0xf10 [efivars] returned 0 after 31143 usecs [ 2.402573] initcall evdev_init+0x0/0x1000 [evdev] returned 0 after 4565 usecs [ 2.402828] calling init_nls_cp437+0x0/0x1000 [nls_cp437] @ 333 [ 2.402830] initcall init_nls_cp437+0x0/0x1000 [nls_cp437] returned 0 after 0 usecs [ 2.402955] calling efivars_pstore_init+0x0/0x1000 [efi_pstore] @ 283 [ 2.402956] pstore: using zlib compression [ 2.402963] pstore: Registered efi as persistent store backend [ 2.402965] initcall efivars_pstore_init+0x0/0x1000 [efi_pstore] returned 0 after 7 usecs [ 2.403948] calling init_nls_ascii+0x0/0x1000 [nls_ascii] @ 335 [ 2.403950] initcall init_nls_ascii+0x0/0x1000 [nls_ascii] returned 0 after 0 usecs [ 2.409437] [drm:i915_driver_load [i915]] Found SunrisePoint LP PCH 70ms before we did the initial pci checks. (In reply to Chris Wilson from comment #4) > Nah, the time disappeared even before we were running: I agree, that even the 2.3 seconds before are quite long too. But that is mainly due to `populate_rootfs` and the time to execute the initramfs, for example the systemd-bootchart SVG attached to [1]. > [ 2.331714] calling i915_init+0x0/0x59 [i915] @ 294 > [ 2.331715] proc_thermal 0000:00:04.0: enabling device (0000 -> 0002) > [ 2.331965] calling alsa_hwdep_init+0x0/0x1000 [snd_hwdep] @ 289 > [ 2.331969] initcall alsa_hwdep_init+0x0/0x1000 [snd_hwdep] returned 0 > after 2 usecs > [ 2.333214] calling btusb_driver_init+0x0/0x1000 [btusb] @ 301 > [ 2.333452] usbcore: registered new interface driver btusb > [ 2.333456] initcall btusb_driver_init+0x0/0x1000 [btusb] returned 0 > after 232 usecs > [ 2.335541] calling hda_bus_init+0x0/0x11 [snd_hda_core] @ 289 > [ 2.335554] initcall hda_bus_init+0x0/0x11 [snd_hda_core] returned 0 > after 7 usecs > [ 2.337340] Bluetooth: hci0: using rampatch file: > qca/rampatch_usb_00000302.bin > [ 2.337341] Bluetooth: hci0: QCA: patch rome 0x302 build 0x138, firmware > rome 0x302 build 0x111 > [ 2.338045] calling iTCO_vendor_init_module+0x0/0x1000 > [iTCO_vendor_support] @ 280 > [ 2.338046] iTCO_vendor_support: vendor-support=0 > [ 2.338048] initcall iTCO_vendor_init_module+0x0/0x1000 > [iTCO_vendor_support] returned 0 after 0 usecs > [ 2.338094] calling uvc_init+0x0/0x1000 [uvcvideo] @ 295 > [ 2.338569] calling iTCO_wdt_init_module+0x0/0x1000 [iTCO_wdt] @ 280 > [ 2.338570] iTCO_wdt: Intel TCO WatchDog Timer Driver v1.11 > [ 2.338713] iTCO_wdt: Found a Intel PCH TCO device (Version=4, > TCOBASE=0x0400) > [ 2.338755] uvcvideo: Found UVC 1.00 device Integrated_Webcam_HD > (0bda:58f4) > [ 2.338827] iTCO_wdt: initialized. heartbeat=30 sec (nowayout=0) > [ 2.338851] initcall iTCO_wdt_init_module+0x0/0x1000 [iTCO_wdt] returned > 0 after 271 usecs > [ 2.340669] uvcvideo 1-5:1.0: Entity type for entity Extension 4 was not > initialized! > [ 2.340670] uvcvideo 1-5:1.0: Entity type for entity Extension 7 was not > initialized! > [ 2.340672] uvcvideo 1-5:1.0: Entity type for entity Processing 2 was not > initialized! > [ 2.340673] uvcvideo 1-5:1.0: Entity type for entity Camera 1 was not > initialized! > [ 2.340736] input: Integrated_Webcam_HD: Integrate as > /devices/pci0000:00/0000:00:14.0/usb1/1-5/1-5:1.0/input/input9 > [ 2.341447] uvcvideo: Unknown video format > 00000032-0002-0010-8000-00aa00389b71 > [ 2.341450] uvcvideo: Found UVC 1.00 device Integrated_Webcam_HD > (0bda:58f4) > [ 2.343371] uvcvideo: Unable to create debugfs 1-2 directory. > [ 2.343420] uvcvideo 1-5:1.2: Entity type for entity Extension 10 was not > initialized! > [ 2.343422] uvcvideo 1-5:1.2: Entity type for entity Extension 12 was not > initialized! > [ 2.343423] uvcvideo 1-5:1.2: Entity type for entity Processing 9 was not > initialized! > [ 2.343424] uvcvideo 1-5:1.2: Entity type for entity Camera 11 was not > initialized! > [ 2.343472] input: Integrated_Webcam_HD: Integrate as > /devices/pci0000:00/0000:00:14.0/usb1/1-5/1-5:1.2/input/input10 > [ 2.343496] usbcore: registered new interface driver uvcvideo > [ 2.343496] USB Video Class driver (1.1.1) > [ 2.343501] initcall uvc_init+0x0/0x1000 [uvcvideo] returned 0 after 5275 > usecs > [ 2.368025] Bluetooth: hci0: using NVM file: qca/nvm_usb_00000302.bin > [ 2.368132] calling ath10k_pci_init+0x0/0x1000 [ath10k_pci] @ 297 > [ 2.368417] ath10k_pci 0000:02:00.0: enabling device (0000 -> 0002) > [ 2.369278] calling serio_raw_drv_init+0x0/0x1000 [serio_raw] @ 280 > [ 2.369288] initcall serio_raw_drv_init+0x0/0x1000 [serio_raw] returned 0 > after 8 usecs > [ 2.370528] calling init_module+0x0/0xf10 [efivars] @ 283 > [ 2.370529] EFI Variables Facility v0.08 2004-May-17 > [ 2.370540] calling init_fat_fs+0x0/0xfcb [fat] @ 327 > [ 2.370665] initcall init_fat_fs+0x0/0xfcb [fat] returned 0 after 118 > usecs > [ 2.371435] ath10k_pci 0000:02:00.0: pci irq msi oper_irq_mode 2 irq_mode > 0 reset_mode 0 > [ 2.373899] calling pcspkr_platform_driver_init+0x0/0x1000 [pcspkr] @ 295 > [ 2.374266] input: PC Speaker as /devices/platform/pcspkr/input/input11 > [ 2.374594] initcall pcspkr_platform_driver_init+0x0/0x1000 [pcspkr] > returned 0 after 675 usecs > [ 2.377394] calling init_vfat_fs+0x0/0x1000 [vfat] @ 327 > [ 2.377399] initcall init_vfat_fs+0x0/0x1000 [vfat] returned 0 after 1 > usecs > [ 2.383102] calling azx_driver_init+0x0/0xfd8 [snd_hda_intel] @ 289 > [ 2.383159] calling joydev_init+0x0/0x1000 [joydev] @ 282 > [ 2.383498] initcall joydev_init+0x0/0x1000 [joydev] returned 0 after 323 > usecs > [ 2.384594] calling pcsp_init+0x0/0x1000 [snd_pcsp] @ 295 > [ 2.384597] Error: Driver 'pcspkr' is already registered, aborting... > [ 2.384930] initcall pcsp_init+0x0/0x1000 [snd_pcsp] returned -16 after > 324 usecs > [ 2.394061] mei_me 0000:00:16.0: enabling device (0000 -> 0002) > [ 2.395838] initcall proc_thermal_init+0x0/0x1000 > [processor_thermal_device] returned 0 after 176806 usecs > [ 2.397894] calling evdev_init+0x0/0x1000 [evdev] @ 301 > [ 2.402423] initcall init_module+0x0/0xf10 [efivars] returned 0 after > 31143 usecs > [ 2.402573] initcall evdev_init+0x0/0x1000 [evdev] returned 0 after 4565 > usecs > [ 2.402828] calling init_nls_cp437+0x0/0x1000 [nls_cp437] @ 333 > [ 2.402830] initcall init_nls_cp437+0x0/0x1000 [nls_cp437] returned 0 > after 0 usecs > [ 2.402955] calling efivars_pstore_init+0x0/0x1000 [efi_pstore] @ 283 > [ 2.402956] pstore: using zlib compression > [ 2.402963] pstore: Registered efi as persistent store backend > [ 2.402965] initcall efivars_pstore_init+0x0/0x1000 [efi_pstore] returned > 0 after 7 usecs > [ 2.403948] calling init_nls_ascii+0x0/0x1000 [nls_ascii] @ 335 > [ 2.403950] initcall init_nls_ascii+0x0/0x1000 [nls_ascii] returned 0 > after 0 usecs > [ 2.409437] [drm:i915_driver_load [i915]] Found SunrisePoint LP PCH > > 70ms before we did the initial pci checks. Sorry, I do not understand the comment. So, it’s just a resource problem with the other modules? [1] https://gitlab.gnome.org/GNOME/gnome-shell/issues/126 I have no idea what caused *that* delay, afaict that is beyond our control. That we take more than just a few ms is still something we should improve. And yes, avoid initrd/initramfs if you want a fast boot. (And keep the kernel image small as well.) (In reply to Chris Wilson from comment #6) > I have no idea what caused *that* delay, afaict that is beyond our control. You talk about the 2.3 seconds, right? I know, that it’s unrelated, and I just talk about the i915_init times. > That we take more than just a few ms is still something we should improve. Understood. Please tell me, if I can provide more data. > And yes, avoid initrd/initramfs if you want a fast boot. (And keep the > kernel image small as well.) Thank you for the hints. From past experience I'd say that initcall_debug alone isn't a very useful means to measure this. There's a tool called pm-graph that's great for things like this. https://github.com/01org/pm-graph With that (in ftrace mode) I'm seeing roughly 35ms on the Broadwell I tested on. I can test on KBL too, if you believe it'll make a difference (the BDW was simply closest at hand). Created attachment 138291 [details] Screenshot from HTML output of `bootgraph.py` (In reply to David Weinehall from comment #8) > From past experience I'd say that initcall_debug alone isn't a very useful > means to measure this. There's a tool called pm-graph that's great for > things like this. > > https://github.com/01org/pm-graph > > With that (in ftrace mode) I'm seeing roughly 35ms on the Broadwell I tested > on. I can test on KBL too, if you believe it'll make a difference (the BDW > was simply closest at hand). I know about pm-graph and the script `bootgraph.py` – you told me about the script (new name) `sleepgraph.py` in another report, if I remember correctly. ;-) Anyway, the times of initcall_debug and `bootgraph.py` match. This time I I measured it both show 50 ms, which is still quite a lot. > i915_init: start=4474.445, end=4525.887, length(w/o overhead)=50.175 ms, return=0 These 50 ms are spent in `generic_hdmi_init` of `snd_hda_codec_hdmi`. Created attachment 138302 [details] Screenshot from HTML output of `bootgraph.py` with 130 ms Without changing anything, this reboot, I got around 130 ms again. (Times of `initcall_debug` and ftrace match.) > i915_init: start=3954.520, end=4089.515, length(w/o overhead)=131.768 ms, return=0 ``` $ sudo dmesg | grep i915_init [ 3.954520] calling i915_init+0x0/0x59 [i915] @ 285 [ 4.089515] initcall i915_init+0x0/0x59 [i915] returned 0 after 131768 usecs ``` Please find the screenshot of the graph attached. This time the time is spent in `fuse_dev_open` and there in `driver_probe_device`. (I have no idea how this is related.) Anyway, I am very confused by this and the interactions. I am not even sure that the graph of `bootgraph.py` is valid. By the way, I am using pm-graph with commit d58df20 (in summary add support for hang cases, where url supend and resume are missing). https://patchwork.freedesktop.org/series/40547/ will not solve the underlying issue, but perhaps reduce the priority by not blocking boot? Can you check whether /proc/interrupts indicate some surprisingly high interrupt count? I've experienced some cases of very slow suspend times that turned out to be because of interrupt storms; due to the nature of interrupts is that they interrupt the normal program flow they got accounted to different modules at different times, and thus sometimes showed up as slowing down our driver, sometimes other drivers. It *might* be something similar, though it seems less likely. As far as HDMI-probing goes, a few things that could slow down the probing: * Bad cable * Display connected via KVM * HDMI-port routed through an LSPCON * BIOS bugs If the time is spent in snd_hda_codec_hdmi(), then the issue might be in the hda driver rather than the i915 driver. But you mention that the overhead seems to move around. To me that sounds like some externally imposed delay. Do any of these components need to wait for the random number generator to refill, for instance? One suspicion I had was that it's something generic to HW probing, but if things sometimes slow down in fuse that couldn't be the case, since fuse shouldn't rely on hardware probing. Hmmm. Tricky. (In reply to David Weinehall from comment #13) > Can you check whether /proc/interrupts indicate some surprisingly high > interrupt count? I've experienced some cases of very slow suspend times that > turned out to be because of interrupt storms; due to the nature of > interrupts is that they interrupt the normal program flow they got accounted > to different modules at different times, and thus sometimes showed up as > slowing down our driver, sometimes other drivers. It *might* be something > similar, though it seems less likely. No idea, see below, though the system is up for some time already. ``` $ more /proc/interrupts CPU0 CPU1 CPU2 CPU3 CPU4 CPU5 CPU6 CPU7 0: 8 0 0 0 0 0 0 0 IR-IO-APIC 2-edge timer 1: 1203 0 0 0 43769 0 0 0 IR-IO-APIC 1-edge i8042 8: 0 0 0 0 0 1 0 0 IR-IO-APIC 8-edge rtc0 9: 116840 351381 0 0 0 0 0 0 IR-IO-APIC 9-fasteoi acpi 12: 13 0 0 211 0 0 0 0 IR-IO-APIC 12-edge i8042 14: 0 0 0 0 0 0 0 0 IR-IO-APIC 14-fasteoi INT344B:00 16: 66 0 0 0 0 0 1043 0 IR-IO-APIC 16-fasteoi i801_smbus, idma64.0, i2c_designware.0 17: 1520683 0 12455901 0 0 0 0 0 IR-IO-APIC 17-fasteoi idma64.1, i2c_designware.1 39: 1 0 0 0 0 0 1140 0 IR-IO-APIC 39-fasteoi ELAN24EE:00 51: 23536 0 0 0 0 0 0 194638 IR-IO-APIC 51-fasteoi DELL07E6:00 120: 0 0 0 0 0 0 0 0 DMAR-MSI 0-edge dmar0 121: 0 0 0 0 0 0 0 0 DMAR-MSI 1-edge dmar1 122: 0 47 0 0 0 0 0 0 IR-PCI-MSI 360448-edge mei_me 123: 135 0 0 0 0 0 0 156 IR-PCI-MSI 327680-edge xhci_hcd 124: 9079 0 0 0 0 0 0 0 IR-PCI-MSI 57671680-edge nvme0q0, nvme0q1 125: 0 0 1074 0 0 0 0 0 IR-PCI-MSI 514048-edge snd_hda_intel:card0 126: 0 5656 0 0 0 0 0 0 IR-PCI-MSI 57671681-edge nvme0q2 127: 0 0 4660 0 0 0 0 0 IR-PCI-MSI 57671682-edge nvme0q3 128: 0 0 0 4991 0 0 0 0 IR-PCI-MSI 57671683-edge nvme0q4 129: 0 0 0 0 9248 0 0 0 IR-PCI-MSI 57671684-edge nvme0q5 130: 0 0 0 0 0 13829 0 0 IR-PCI-MSI 57671685-edge nvme0q6 131: 0 0 0 0 0 0 7052 0 IR-PCI-MSI 57671686-edge nvme0q7 132: 6272 2526 7172 3321 242857 250175 2310 25887 IR-PCI-MSI 32768-edge i915 133: 1658 2185 107 5064 4251 12859 9957 26498 IR-PCI-MSI 1048576-edge ath10k_pci 134: 0 0 0 0 0 0 0 9115 IR-PCI-MSI 57671687-edge nvme0q8 135: 0 0 0 38838 0 0 0 0 IR-PCI-MSI 2621440-edge thunderbolt 136: 0 0 0 0 38838 0 0 0 IR-PCI-MSI 2621441-edge thunderbolt 151: 0 6085 32871 0 1250 0 0 81341 IR-PCI-MSI 33030144-edge xhci_hcd 152: 0 0 0 0 0 0 0 0 IR-PCI-MSI 33030145-edge xhci_hcd 153: 0 0 0 0 0 0 0 0 IR-PCI-MSI 33030146-edge xhci_hcd 154: 0 0 0 0 0 0 0 0 IR-PCI-MSI 33030147-edge xhci_hcd 155: 0 0 0 0 0 0 0 0 IR-PCI-MSI 33030148-edge xhci_hcd 156: 0 0 0 0 0 0 0 0 IR-PCI-MSI 33030149-edge xhci_hcd 157: 0 0 0 0 0 0 0 0 IR-PCI-MSI 33030150-edge xhci_hcd 158: 0 0 0 0 0 0 0 0 IR-PCI-MSI 33030151-edge xhci_hcd NMI: 47 219 231 222 216 230 221 218 Non-maskable interrupts LOC: 804697 758024 826859 807491 982973 903341 808320 833069 Local timer interrupts SPU: 0 0 0 0 0 0 0 0 Spurious interrupts PMI: 47 219 231 222 216 230 221 218 Performance monitoring interrupts IWI: 1161 544 1234 474 40990 24068 364 4518 IRQ work interrupts RTR: 0 0 0 0 0 0 0 0 APIC ICR read retries RES: 238447 120892 112676 67312 102441 90607 65695 71477 Rescheduling interrupts CAL: 137795 144599 122801 128888 119471 214609 161160 126993 Function call interrupts TLB: 111602 118338 95668 103951 93386 187914 135550 99271 TLB shootdowns TRM: 20 20 20 20 20 20 20 20 Thermal event interrupts THR: 0 0 0 0 0 0 0 0 Threshold APIC interrupts DFR: 0 0 0 0 0 0 0 0 Deferred Error APIC interrupts MCE: 0 0 0 0 0 0 0 0 Machine check exceptions MCP: 37 37 37 37 37 37 37 37 Machine check polls HYP: 0 0 0 0 0 0 0 0 Hypervisor callback interrupts HRE: 0 0 0 0 0 0 0 0 Hyper-V reenlightenment interrupts ERR: 2 MIS: 0 PIN: 0 0 0 0 0 0 0 0 Posted-interrupt notification event NPI: 0 0 0 0 0 0 0 0 Nested posted-interrupt event PIW: 0 0 0 0 0 0 0 0 Posted-interrupt wakeup event ``` > As far as HDMI-probing goes, a few things that could slow down the probing: > > * Bad cable > * Display connected via KVM > * HDMI-port routed through an LSPCON > * BIOS bugs When doing these experiments, nothing was connected to the laptop. And it only has USB-C connectors. > If the time is spent in snd_hda_codec_hdmi(), then the issue might be in the > hda driver rather than the i915 driver. > > But you mention that the overhead seems to move around. To me that sounds > like some externally imposed delay. Do any of these components need to wait > for the random number generator to refill, for instance? > > One suspicion I had was that it's something generic to HW probing, but if > things sometimes slow down in fuse that couldn't be the case, since fuse > shouldn't rely on hardware probing. Hmmm. Tricky. Where are the 35 ms spent on your system? What do you set maxdepth to? Ignore the fuse reference. That looks just like symbol lookup failure across module loads, and it is not on the critical path (i.e. it doesn't contribute 134ms to i915 driver load). Created attachment 138309 [details] SVG file created by systemd-bootchart with patch (In reply to Chris Wilson from comment #12) > https://patchwork.freedesktop.org/series/40547/ will not solve the > underlying issue, but perhaps reduce the priority by not blocking boot? Wow, initcall_debug already shows a big improvement. ``` $ sudo dmesg | grep -i i915_init [ 2.488902] calling i915_init+0x0/0x59 [i915] @ 281 [ 2.488958] initcall i915_init+0x0/0x59 [i915] returned 0 after 14 usecs ``` Please find the SVG file created by systemd-bootchart attached. Tested-by: Paul Menzel <pmenzel@molgen.mpg.de> At maxdepth 12 all time is consumed in i915_driver_load(). At that point the generated HTML-file is about 200MB and takes ages for firefox to load. I'll apply some filtering and try to dig deeper. Dave, could you test the patch? The time should now be under 5 ms. Chris, should this be tagged for the stable series too? I can confirm that Chris's patch brings the synchronous part of the init time down to roughly nothing (0.5ms). The main culprits on my laptop are: acpi_init (over 600ms) rsa_init (over 300ms) rmi_smb_driver_init (over 300ms) (In reply to David Weinehall from comment #19) > I can confirm that Chris's patch brings the synchronous part of the init > time down to roughly nothing (0.5ms). Awesome. > The main culprits on my laptop are: > > acpi_init (over 600ms) Yes, ACPI is really bad, and probably the tables created by the firmware is badly written. Users should complain more about that. > rsa_init (over 300ms) Adding `cryptomgr.notests` should disable that. > rmi_smb_driver_init (over 300ms) I do not have that on my system. The rmi-thing only happens on systems with a Synaptics touchpad/trackpoint with register mapped interface. As for ACPI, the system is a ThinkPad, and Lenovo are notoriously bad at BIOS issues in general, so I think there's little hope there. First of all. Sorry about spam. This is mass update for our bugs. Sorry if you feel this annoying but with this trying to understand if bug still valid or not. If bug investigation still in progress, please ignore this and I apologize! If you think this is not anymore valid, please comment to the bug that can be closed. If you haven't tested with our latest pre-upstream tree(drm-tip), can you do that also to see if issue is valid there still and if you cannot see issue there, please comment to the bug. With Linux 4.16-rc7+ (master branch), and the patch applied, on a Lenovo X60 `i915_init()` still takes 87 milliseconds according to `initcall_debug`. ``` [ 1.453313] calling i915_init+0x0/0x56 [i915] @ 98 [ 1.453736] pci 0000:00:00.0: Intel 945GM Chipset [ 1.453752] pci 0000:00:00.0: detected gtt size: 262144K total, 262144K mappable [ 1.454321] pci 0000:00:00.0: detected 8192K stolen memory [ 1.454430] checking generic (d0000000 300000) vs hw (d0000000 10000000) [ 1.454432] fb: switching to inteldrmfb from VESA VGA [ 1.454489] Console: switching to colour dummy device 80x25 [ 1.454733] [drm] Replacing VGA console driver [ 1.514163] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013). [ 1.514166] [drm] Driver supports precise vblank timestamp query. [ 1.514650] i915 0000:00:02.0: vgaarb: changed VGA decodes: olddecodes=io+mem,decodes=io+mem:owns=io+mem [ 1.529553] [drm] RC6 disabled, disabling runtime PM support [ 1.529637] [drm] initialized overlay support [ 1.530520] [drm] Initialized i915 1.6.0 20171222 for 0000:00:02.0 on minor 0 [ 1.530811] ACPI: Video Device [GFX0] (multi-head: yes rom: no post: no) [ 1.536777] clocksource: timekeeping watchdog on CPU0: Marking clocksource 'tsc-early' as unstable because the skew is too large: [ 1.536784] clocksource: 'hpet' wd_now: 22a9b5a wd_last: 10310d8 mask: ffffffff [ 1.536786] clocksource: 'tsc-early' cs_now: 42dfe9b3e cs_last: 3fdd506a0 mask: ffffffffffffffff [ 1.536945] clocksource: Switched to clocksource hpet [ 1.542606] acpi device:04: registered as cooling_device3 [ 1.542730] input: Video Bus as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A08:00/LNXVIDEO:00/input/input5 [ 1.543404] initcall i915_init+0x0/0x56 [i915] returned 0 after 87888 usecs ``` What needs to be done, to get this submitted? David, what is needed here? I have no idea, to be honest. We don't do performance tests on hardware that old (the 945GM is a gen3; for platforms that old we only test for functional regressions). Is the machine only using eDP, or do you have external displays connected? (In reply to David Weinehall from comment #26) > I have no idea, to be honest. We don't do performance tests on hardware that > old (the 945GM is a gen3; for platforms that old we only test for functional > regressions). > > Is the machine only using eDP, or do you have external displays connected? Please note, that *two* devices are mentioned in this report. One current one (Kaby Lake+(?) 8th generation) and one old one (945GM). On neither machine an external display was connected. The old one shouldn’t have eDP. Yes, I do note that two machines are mentioned, but I interpret comment #16 to mean that the other machine is fast after applying Chris's patch. Is that not the case? (In reply to David Weinehall from comment #28) > Yes, I do note that two machines are mentioned, but I interpret comment #16 > to mean that the other machine is fast after applying Chris's patch. Is that > not the case? Yes, it is the case, so Chris’ patch should be applied in my opinion. As another data point, on a TUXEDO Book BU1406 with Kaby Lake (HD Graphics 620 [8086:5916]) current Linux 4.17-rc2 takes 37855 μs according to `initcall_debug` with tracing for `bootgraph.py` enabled, and 28027 μs without tracing, which is close to your result. It’s still too much in my opinion. Is that with or without Chris's patch? Anyway, the patch flow to get something merged is, as always, submission, review, merge. It seems that the patch never received a Reviewed-by: tag, so it hasn't been merged. I've rectified this now, so hopefully it'll get merged eventually. (In reply to David Weinehall from comment #30) > Is that with or without Chris's patch? On the TUXEDO Book BU1406 it was *without* the patch. > Anyway, the patch flow to get something merged is, as always, submission, > review, merge. > > It seems that the patch never received a Reviewed-by: tag, so it hasn't been > merged. I've rectified this now, so hopefully it'll get merged eventually. Thank you! Paul, do you still have the issue? (In reply to Lakshmi from comment #32) > Paul, do you still have the issue? Yes, I do. I am also not totally sure, if the asynchronous call actually does anything different besides changing the number. Is there actually multi-threading(?) that early in the kernel initialization? This bug has not been updated in over a year, can it be closed? We have a SLA which requires us to look at all open bugs periodically so I am adding this comment as part of that. #assessment You are reporter of the issue currently having low priority. Do you still see issue. If so, please spesify clearly what is impact to you. I’ll need some days to check this. You should also have such a device, and can check with `bootgraph.py` [1], and `initcall_debug` and ftrace. [1]: https://github.com/intel/pm-graph -- GitLab Migration Automatic Message -- This bug has been migrated to freedesktop.org's GitLab instance and has been closed from further activity. You can subscribe and participate further through the new bug through this link to our GitLab instance: https://gitlab.freedesktop.org/drm/intel/issues/94. |
Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.