Bug 105622 - i915_init takes over 100 ms
Summary: i915_init takes over 100 ms
Status: ASSIGNED
Alias: None
Product: DRI
Classification: Unclassified
Component: DRM/Intel (show other bugs)
Version: DRI git
Hardware: Other All
: low enhancement
Assignee: Intel GFX Bugs mailing list
QA Contact: Intel GFX Bugs mailing list
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2018-03-20 10:23 UTC by Paul Menzel
Modified: 2018-09-10 16:04 UTC (History)
6 users (show)

See Also:
i915 platform: KBL
i915 features: display/Other


Attachments
Linux 4.16-rc5+ messages (116.96 KB, text/plain)
2018-03-20 10:24 UTC, Paul Menzel
no flags Details
Linux 4.16-rc6+ messages with only 25 ms and drm.debug=0x1e (332.98 KB, text/plain)
2018-03-20 11:59 UTC, Paul Menzel
no flags Details
Linux 4.16-rc6+ messages with only 148 ms and drm.debug=0x1e (399.52 KB, text/plain)
2018-03-20 12:04 UTC, Paul Menzel
no flags Details
Screenshot from HTML output of `bootgraph.py` (611.18 KB, image/png)
2018-03-22 21:38 UTC, Paul Menzel
no flags Details
Screenshot from HTML output of `bootgraph.py` with 130 ms (603.41 KB, image/png)
2018-03-23 07:05 UTC, Paul Menzel
no flags Details
SVG file created by systemd-bootchart with patch (553.61 KB, image/svg+xml)
2018-03-23 10:38 UTC, Paul Menzel
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Paul Menzel 2018-03-20 10:23:41 UTC
For a quick boot, it is important, that modules load as fast as possible. Currently on a Dell XPS 13 9370 with , according to `initcall_debug` the function `i915_init` takes 130 ms.

```
$ lspci -s 02.0 -nn
00:02.0 VGA compatible controller [0300]: Intel Corporation UHD Graphics 620 [8086:5917] (rev 07)
$ 
$ sudo dmesg
[…]
[    2.260353] calling  i915_init+0x0/0x59 [i915] @ 301
[…]
[    2.320132] fb: switching to inteldrmfb from EFI VGA
[    2.320147] Console: switching to colour dummy device 80x25
[    2.320732] [drm] Replacing VGA console driver
[    2.323454] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
[    2.323455] [drm] Driver supports precise vblank timestamp query.
[    2.330618] i915 0000:00:02.0: vgaarb: changed VGA decodes: olddecodes=io+mem,decodes=io+mem:owns=io+mem
[    2.331609] [drm] Finished loading DMC firmware i915/kbl_dmc_ver1_04.bin (v1.4)
[    2.338525] [drm] Initialized i915 1.6.0 20171222 for 0000:00:02.0 on minor 0
[…]
[    2.392787] initcall i915_init+0x0/0x59 [i915] returned 0 after 129294 usecs
[    2.392789] snd_hda_intel 0000:00:1f.3: enabling device (0000 -> 0002)
[    2.392925] initcall azx_driver_init+0x0/0xfd8 [snd_hda_intel] returned 0 after 123877 usecs
[    2.393932] snd_hda_intel 0000:00:1f.3: bound 0000:00:02.0 (ops i915_audio_component_bind_ops [i915])
```
Comment 1 Paul Menzel 2018-03-20 10:24:54 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
```
Comment 2 Paul Menzel 2018-03-20 11:59:04 UTC
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.
Comment 3 Paul Menzel 2018-03-20 12:04:55 UTC
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.
Comment 4 Chris Wilson 2018-03-20 12:11:19 UTC
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.
Comment 5 Paul Menzel 2018-03-20 12:26:26 UTC
(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
Comment 6 Chris Wilson 2018-03-20 12:30:46 UTC
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.)
Comment 7 Paul Menzel 2018-03-20 12:38:14 UTC
(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.
Comment 8 David Weinehall 2018-03-22 16:51:07 UTC
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).
Comment 9 Paul Menzel 2018-03-22 21:38:16 UTC
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`.
Comment 10 Paul Menzel 2018-03-23 07:05:39 UTC
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.
Comment 11 Paul Menzel 2018-03-23 07:27:25 UTC
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).
Comment 12 Chris Wilson 2018-03-23 09:11:26 UTC
https://patchwork.freedesktop.org/series/40547/ will not solve the underlying issue, but perhaps reduce the priority by not blocking boot?
Comment 13 David Weinehall 2018-03-23 10:11:51 UTC
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.
Comment 14 Paul Menzel 2018-03-23 10:19:14 UTC
(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?
Comment 15 Chris Wilson 2018-03-23 10:21:33 UTC
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).
Comment 16 Paul Menzel 2018-03-23 10:38:06 UTC
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>
Comment 17 David Weinehall 2018-03-23 10:45:44 UTC
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.
Comment 18 Paul Menzel 2018-03-23 12:51:05 UTC
Dave, could you test the patch? The time should now be under 5 ms.

Chris, should this be tagged for the stable series too?
Comment 19 David Weinehall 2018-03-23 14:34:39 UTC
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)
Comment 20 Paul Menzel 2018-03-23 14:43:11 UTC
(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.
Comment 21 David Weinehall 2018-03-26 13:49:13 UTC
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.
Comment 22 Jani Saarinen 2018-03-29 07:11:00 UTC
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.
Comment 23 Paul Menzel 2018-03-29 15:40:16 UTC
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
```
Comment 24 Paul Menzel 2018-04-23 11:46:36 UTC
What needs to be done, to get this submitted?
Comment 25 Jani Saarinen 2018-04-25 11:27:09 UTC
David, what is needed here?
Comment 26 David Weinehall 2018-04-26 08:42:58 UTC
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?
Comment 27 Paul Menzel 2018-04-26 09:05:14 UTC
(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.
Comment 28 David Weinehall 2018-04-26 11:36:18 UTC
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?
Comment 29 Paul Menzel 2018-04-26 12:27:26 UTC
(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.
Comment 30 David Weinehall 2018-04-26 12:42:23 UTC
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.
Comment 31 Paul Menzel 2018-04-26 12:50:10 UTC
(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!
Comment 32 Lakshmi 2018-09-10 16:02:42 UTC
Paul, do you still have the issue?
Comment 33 Paul Menzel 2018-09-10 16:04:40 UTC
(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?


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.