Created attachment 131133 [details]
i915_guc_load_status

This is a kind of bug/feature request.
We need this log printed for test purposes (make sure firmware is loaded and check init time).

dmesg is not a user interface, but a collection of user visible strings with all the rigmarole associated with that. /sys/kernel/debug/dri/0/i915_guc_load_status (or a friend) is the debug interface that CI should be using, and if that is insufficient we need to report it similarly through one of the debugfs/sysfs/ioctl interfaces.

Not dmesg.

This is not about the CI, this is tested manually as part of firmware validation activities.
For previous GuCs we used following logs:
[drm:intel_guc_setup] GuC fw status: fetch SUCCESS, load PENDING
[drm:intel_guc_setup] GuC fw status: fetch SUCCESS, load SUCCESS

Now log is different and the second part disappeared:
[    3.229292] [drm:intel_guc_init_hw [i915]] GuC fw status: fetch SUCCESS, load PENDING

@cprigent Yes. The messages that dmesg now prints has changed as a part of guc cleanup. But like Chris has pointed out, /sys/kernel/debug/dri/0/i915_guc_load_status  has to be used to test the load status.

(In reply to anusha from comment #5)
> @cprigent Yes. The messages that dmesg now prints has changed as a part of
> guc cleanup. But like Chris has pointed out,
> /sys/kernel/debug/dri/0/i915_guc_load_status  has to be used to test the
> load status.

OK. And what about init time?

@cprigent @Luis 

We do get a GuC loaded message in the dmesg:

[    0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-4.12.0-rc4+ root=UUID=87333792-62cd-4ac4-b173-15bbe2a07b60 ro splash drm.debug=0xe i915.enable_guc_loading=2 vt.handoff=7
[    0.000000] Kernel command line: BOOT_IMAGE=/boot/vmlinuz-4.12.0-rc4+ root=UUID=87333792-62cd-4ac4-b173-15bbe2a07b60 ro splash drm.debug=0xe i915.enable_guc_loading=2 i915.disable_firmware=0 vt.handoff=7
[    7.138883] Setting dangerous option enable_guc_loading - tainting kernel
[    7.149275] [drm:intel_device_info_dump [i915]] i915 device info: has_guc: yes
[    7.149299] [drm:intel_device_info_dump [i915]] i915 device info: has_guc_ct: no
[    7.187160] [drm:fetch_uc_fw [i915]] fetch uC fw from i915/skl_guc_ver6_1.bin succeeded, fw ffff98569e320960
[    7.191331] [drm:intel_guc_init_hw [i915]] GuC fw status: path i915/skl_guc_ver6_1.bin, fetch SUCCESS, load NONE
[    7.191354] [drm:intel_guc_init_hw [i915]] GuC fw status: fetch SUCCESS, load PENDING
[    7.201502] [drm:guc_ucode_xfer_dma [i915]] DMA status 0x10, GuC status 0x8002f0ec
[    7.201531] [drm:guc_ucode_xfer_dma [i915]] returning 0
[    7.201533] [drm] GuC loaded (firmware i915/skl_guc_ver6_1.bin [version 6.1])

Adding dmesg output for SKL:
[    0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-4.13.0-rc1-drm-tip-ww30-commit-2a4f730+ root=UUID=2a8388ef-fcb0-4ae0-964a-bd124748729c ro quiet drm.debug=0x1e auto panic=1 i915.enable_guc_loading=2 nmi_watchdog=panic i915.enable_guc_submission=2 resume=/dev/sda3 fastboot
[    0.000000] Kernel command line: BOOT_IMAGE=/boot/vmlinuz-4.13.0-rc1-drm-tip-ww30-commit-2a4f730+ root=UUID=2a8388ef-fcb0-4ae0-964a-bd124748729c ro quiet drm.debug=0x1e auto panic=1 i915.enable_guc_loading=2 nmi_watchdog=panic i915.enable_guc_submission=2 resume=/dev/sda3 fastboot
[    2.939947] Setting dangerous option enable_guc_loading - tainting kernel
[    2.939954] Setting dangerous option enable_guc_submission - tainting kernel
[    2.947901] [drm:intel_device_info_dump [i915]] i915 device info: has_guc: yes
[    2.947939] [drm:intel_device_info_dump [i915]] i915 device info: has_guc_ct: no
[    3.256701] [drm:fetch_uc_fw [i915]] fetch uC fw from i915/skl_guc_ver6_1.bin succeeded, fw ffff880456639428
[    3.265590] [drm:intel_guc_init_hw [i915]] GuC fw status: path i915/skl_guc_ver6_1.bin, fetch SUCCESS, load NONE
[    3.265623] [drm:intel_guc_init_hw [i915]] GuC fw status: fetch SUCCESS, load PENDING
[    3.276391] [drm:guc_ucode_xfer_dma [i915]] DMA status 0x10, GuC status 0x8002f0ec
[    3.276427] [drm:guc_ucode_xfer_dma [i915]] returning 0
[    3.276429] [drm] GuC submission enabled (firmware i915/skl_guc_ver6_1.bin [version 6.1])
[    3.287182] [drm:i915_guc_submission_enable [i915]] reserved cacheline 0x0, next 0x40, linesize 64
[    3.287219] [drm:i915_guc_submission_enable [i915]] Host engines 0x1f => GuC engines used 0x1f
[    3.289429] [drm:i915_guc_submission_enable [i915]] new priority 2 client ffff8804566cbbd8 for engine(s) 0x1f: stage_id 0
[    3.289465] [drm:i915_guc_submission_enable [i915]] doorbell id 0, cacheline offset 0x0




And this is from GLK:
[    0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-4.13.0-rc2-drm-tip-ww30-commit-30d8319+ root=UUID=8645d92b-a748-451d-9e82-b826714a48c3 ro quiet splash drm.debug=0xe i915.alpha_support=1 i915.enable_guc_submission=2 i915.enable_guc_loading=2 vt.handoff=7
[    0.000000] Kernel command line: BOOT_IMAGE=/boot/vmlinuz-4.13.0-rc2-drm-tip-ww30-commit-30d8319+ root=UUID=8645d92b-a748-451d-9e82-b826714a48c3 ro quiet splash drm.debug=0xe i915.alpha_support=1 i915.enable_guc_submission=2 i915.enable_guc_loading=2 vt.handoff=7
[    5.005223] Setting dangerous option enable_guc_submission - tainting kernel
[    5.005228] Setting dangerous option enable_guc_loading - tainting kernel
[    5.012529] [drm:intel_device_info_dump [i915]] i915 device info: has_guc: yes
[    5.012588] [drm:intel_device_info_dump [i915]] i915 device info: has_guc_ct: no
[    5.048740] [drm:fetch_uc_fw [i915]] fetch uC fw from i915/glk_guc_ver10_56.bin succeeded, fw ffff880175146178
[    5.070248] [drm:intel_guc_init_hw [i915]] GuC fw status: path i915/glk_guc_ver10_56.bin, fetch SUCCESS, load NONE
[    5.070308] [drm:intel_guc_init_hw [i915]] GuC fw status: fetch SUCCESS, load PENDING
[    5.076409] [drm:guc_ucode_xfer_dma [i915]] DMA status 0x10, GuC status 0x8002f0ec
[    5.076477] [drm:guc_ucode_xfer_dma [i915]] returning 0
[    5.076481] [drm] GuC submission enabled (firmware i915/glk_guc_ver10_56.bin [version 10.56])
[    5.082405] [drm:i915_guc_submission_enable [i915]] reserved cacheline 0x0, next 0x40, linesize 64
[    5.082501] [drm:i915_guc_submission_enable [i915]] Host engines 0x17 => GuC engines used 0xf
[    5.084097] [drm:i915_guc_submission_enable [i915]] new priority 2 client ffff8801757637b8 for engine(s) 0x17: stage_id 0
[    5.084161] [drm:i915_guc_submission_enable [i915]] doorbell id 0, cacheline offset 0x0


So, these log lines are the ones we need to use for loading calculation?
[    5.070248] [drm:intel_guc_init_hw [i915]] GuC fw status: path i915/glk_guc_ver10_56.bin, fetch SUCCESS, load NONE
[    5.076481] [drm] GuC submission enabled (firmware i915/glk_guc_ver10_56.bin [version 10.56])
5.076481 - 5.070248 = 6.233 miliseconds
Is this assumption correct?

Hello Anusha, 

Comparing Luis dmesg:
[    3.276429] [drm] GuC submission enabled (firmware i915/skl_guc_ver6_1.bin [version 6.1])

With yours:
[    7.201533] [drm] GuC loaded (firmware i915/skl_guc_ver6_1.bin [version 6.1])

Seems to be a slightly difference. Is the message "GuC submission enabled" meaning the same as "GuC loaded", or is quite the opposite?

Thanks.

(In reply to Elizabeth from comment #9)
> Hello Anusha, 
> 
> Comparing Luis dmesg:
> [    3.276429] [drm] GuC submission enabled (firmware
> i915/skl_guc_ver6_1.bin [version 6.1])
> 
> With yours:
> [    7.201533] [drm] GuC loaded (firmware i915/skl_guc_ver6_1.bin [version
> 6.1])
> 
> Seems to be a slightly difference. Is the message "GuC submission enabled"
> meaning the same as "GuC loaded", or is quite the opposite?
> 
> Thanks.

Hi Elizabeth, its not quite the same. There are two parameters, that are related but not the same. GuC submission can be enabled only if guc is loaded. So getting "Submission enabled" is a confirmation that guc is loaded. But "GuC loaded" message comes at the time GuC is loaded to microkernel, regardless of submission being enabled or not.

Patches are being reviewed and are in public ML.
https://patchwork.freedesktop.org/patch/180481/ 

There is going to be minor changes if any, the logic remains the same. I have tested this series on a SKL and the load times are shown as expected and well within range. 

The patches can be applied and checked if needed.

Thanks Anusha. And from the https://patchwork.freedesktop.org/series/31363/ you can see CI results - no negative impact over there.

I see that data in dmesg for SKL and APL at least ... it should not be different on CFL or GLK - right?

This is not a loading bug, but a bug describing that loading time is not shown is dmesg in some platforms such as GLK.

GuC support has been removed upstream due to the lack of public firmware for this platforms.

So the bug here is probably the debugfs lying.

Luis, is this tested with the latest kernel on a GLK?

no response, closing.