Bug 111165

https://patchwork.freedesktop.org/series/63863/

Assigning Michal since he landed the change enabling HuC loading by default on ICL.

The CI Bug Log issue associated to this bug has been updated.

### New filters associated

* ICL: igt@debugfs_test@read_all_entries_display_off - dmesg-warn - WARN_ON(!intel_guc_log_relay_enabled(log))
  - https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6502/shard-iclb5/igt@debugfs_test@read_all_entries_display_off.html

A CI Bug Log filter associated to this bug has been updated:

{- ICL: igt@debugfs_test@read_all_entries_display_off - dmesg-warn - WARN_ON(!intel_guc_log_relay_enabled(log)) -}
{+ ICL: igt@debugfs_test@read_all_entries_display_off|igt@i915_suspend@debugfs-reader - dmesg-warn - WARN_ON(!intel_guc_log_relay_enabled(log)) +}

New failures caught by the filter:

  * https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_326/fi-icl-u3/igt@i915_suspend@debugfs-reader.html

https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_326/fi-icl-u3/igt@i915_suspend@debugfs-reader.html

] ------------[ cut here ]------------
<4> [376.421788] WARN_ON(!intel_guc_log_relay_enabled(log))
<4> [376.421908] WARNING: CPU: 3 PID: 339 at drivers/gpu/drm/i915/gt/uc/intel_guc_log.c:247 guc_log_capture_logs+0x39d/0x470 [i915]
<4> [376.421910] Modules linked in: vgem snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic mei_hdcp i915 x86_pkg_temp_thermal coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel snd_hda_intel btusb snd_hda_codec btrtl btbcm btintel snd_hwdep snd_hda_core bluetooth e1000e snd_pcm ptp cdc_ether pps_core usbnet mii ecdh_generic ecc mei_me mei prime_numbers
<4> [376.421930] CPU: 3 PID: 339 Comm: kworker/3:1H Tainted: G     U            5.2.0-g9b39702210b8-drmtip_326+ #1
<4> [376.421932] Hardware name: Intel Corporation Ice Lake Client Platform/IceLake U DDR4 SODIMM PD RVP TLC, BIOS ICLSFWR1.R00.3183.A00.1905020411 05/02/2019
<4> [376.421971] Workqueue: events_highpri capture_logs_work [i915]
<4> [376.422010] RIP: 0010:guc_log_capture_logs+0x39d/0x470 [i915]
<4> [376.422012] Code: b9 63 c0 e8 85 83 14 d4 4d 89 f3 4c 8b 14 24 48 89 da e9 3f fe ff ff 48 c7 c6 c0 45 61 c0 48 c7 c7 c4 b9 63 c0 e8 93 11 ba d3 <0f> 0b e9 c5 fe ff ff 48 c7 c6 00 20 5e c0 48 c7 c7 c0 de 6b c0 e8
<4> [376.422015] RSP: 0018:ffffa0088039bdc0 EFLAGS: 00010282
<4> [376.422017] RAX: 0000000000000000 RBX: ffff98033c94b8e0 RCX: 0000000000000003
<4> [376.422019] RDX: 00000000000021b1 RSI: ffff980353b54908 RDI: ffffffff950f8e69
<4> [376.422021] RBP: ffffa0088039bec8 R08: 00000000010b125d R09: 0000000000000000
<4> [376.422023] R10: ffffa0088039bdc0 R11: 0000000000000000 R12: ffff98035fdb9b80
<4> [376.422025] R13: ffff98033c94b8c8 R14: 0000000000000000 R15: 0000000000000000
<4> [376.422027] FS:  0000000000000000(0000) GS:ffff98035fd80000(0000) knlGS:0000000000000000
<4> [376.422030] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4> [376.422032] CR2: 000055db1136d000 CR3: 00000003e3210005 CR4: 0000000000760ee0
<4> [376.422034] PKRU: 55555554
<4> [376.422035] Call Trace:
<4> [376.422043]  ? process_one_work+0x1bf/0x610
<4> [376.422050]  process_one_work+0x245/0x610
<4> [376.422059]  worker_thread+0x37/0x380
<4> [376.422093]  ? process_one_work+0x610/0x610
<4> [376.422097]  kthread+0x119/0x130
<4> [376.422100]  ? kthread_park+0x80/0x80
<4> [376.422105]  ret_from_fork+0x24/0x50
<4> [376.422114] irq event stamp: 180780
<4> [376.422117] hardirqs last  enabled at (180779): [<ffffffff9412c57c>] vprintk_emit+0xcc/0x340
<4> [376.422120] hardirqs last disabled at (180780): [<ffffffff940019f0>] trace_hardirqs_off_thunk+0x1a/0x1c
<4> [376.422123] softirqs last  enabled at (178422): [<ffffffff94c0033a>] __do_softirq+0x33a/0x4b9
<4> [376.422125] softirqs last disabled at (178415): [<ffffffff940ba239>] irq_exit+0xa9/0xc0
<4> [376.422192] WARNING: CPU: 3 PID: 339 at drivers/gpu/drm/i915/gt/uc/intel_guc_log.c:247 guc_log_capture_logs+0x39d/0x470 [i915]
<4> [376.422194] ---[ end trace 1500936934077ddb ]---

A CI Bug Log filter associated to this bug has been updated:

{- ICL: igt@debugfs_test@read_all_entries_display_off|igt@i915_suspend@debugfs-reader - dmesg-warn - WARN_ON(!intel_guc_log_relay_enabled(log)) -}
{+ GUC: igt@debugfs_test@read_all_entries_display_off|igt@i915_suspend@debugfs-reader - dmesg-warn - WARN_ON(!intel_guc_log_relay_enabled(log)) +}

New failures caught by the filter:

  * https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_326/fi-apl-guc/igt@i915_suspend@debugfs-reader.html
  * https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_328/fi-cfl-guc/igt@i915_suspend@debugfs-reader.html

A CI Bug Log filter associated to this bug has been updated:

{- GUC: igt@debugfs_test@read_all_entries_display_off|igt@i915_suspend@debugfs-reader - dmesg-warn - WARN_ON(!intel_guc_log_relay_enabled(log)) -}
{+ GUC: igt@debugfs_test@read_all_entries_display_off|igt@i915_suspend@debugfs-reader - dmesg-warn - WARN_ON(!intel_guc_log_relay_enabled(log)) +}


  No new failures caught with the new filter

A CI Bug Log filter associated to this bug has been updated:

{- GUC: igt@debugfs_test@read_all_entries_display_off|igt@i915_suspend@debugfs-reader - dmesg-warn - WARN_ON(!intel_guc_log_relay_enabled(log)) -}
{+ GUC: igt@debugfs_test@read_all_entries_display_off|igt@i915_suspend@debugfs-reader - dmesg-warn - WARN_ON(!intel_guc_log_relay_enabled(log)) +}

New failures caught by the filter:

  * https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_333/fi-cfl-guc/igt@debugfs_test@read_all_entries_display_on.html

A CI Bug Log filter associated to this bug has been updated:

{- GUC: igt@debugfs_test@read_all_entries_display_off|igt@i915_suspend@debugfs-reader - dmesg-warn - WARN_ON(!intel_guc_log_relay_enabled(log)) -}
{+ GUC: igt@debugfs_test@read_all_entries_display_(off|on)|igt@i915_suspend@debugfs-reader - dmesg-warn - WARN_ON(!intel_guc_log_relay_enabled(log)) +}


  No new failures caught with the new filter

The CI Bug Log issue associated to this bug has been updated.

### New filters associated

* GUC: igt@runner@aborted - fail - Previous test: debugfs_test (read_all_entries_display_on)
  - https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_333/fi-cfl-guc/igt@runner@aborted.html

Based on the comments from Michal, Updating the priority as the user impact is negligible impact, P2/P3 due to WARN.

The relay log is a developer only feature and an extension of the standard GuC logging mechanism.  Its testing should not be part of the BAT set.  It is being implicitly enabled by existing tests, which provide no consumer for the logs.  
The issue is that IGT tests that cycle through reading the debugfs entries will call the open file op for the guc_log_relay control file and this currently causes the file to be both created and the logging to be started.  These tests have no consumer for the logs which go on to overflow, run out of sub-buffers or misbehave in suspend and reset handling.
A proposed change, that will follow as RFC patches, is to separate the creation and logging start, updating the guc_log_relay_write function, which currently just flushes the log, to also support starting the logging based on the value written.
An additional new test to actually explicitly test this relay log developer feature will follow separately.

Same issue as 109536 and 111148. Proposed fix tested and passing.  Patches in prep for posting.

RFC patch sent out for review: drm/i915/guc: Enable guc logging on guc log relay write.

While creating and testing the patch also noticed that the IGT tool intel_guc_logger needs to be updated for the new relay implementation. Will create another patch to update the IGT tool.

(In reply to Robert M. Fosha from comment #14)
> RFC patch sent out for review: drm/i915/guc: Enable guc logging on guc log
> relay write.

That doesn't fix this bug; that just papers over the bug by not encountering it.

A CI Bug Log filter associated to this bug has been updated:

{- GUC: igt@debugfs_test@read_all_entries_display_(off|on)|igt@i915_suspend@debugfs-reader - dmesg-warn - WARN_ON(!intel_guc_log_relay_enabled(log)) -}
{+ GUC: igt@debugfs_test@read_all_entries_display_(off|on)|igt@i915_suspend@debugfs-reader - dmesg-warn - WARN_ON(!intel_guc_log_relay_enabled(log)) +}

New failures caught by the filter:

  * https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_385/fi-cfl-guc/igt@debugfs_test@read_all_entries.html

A CI Bug Log filter associated to this bug has been updated:

{- GUC: igt@runner@aborted - fail - Previous test: debugfs_test (read_all_entries_display_on) -}
{+ GUC: igt@runner@aborted - fail - Previous test: debugfs_test (read_all_entries_display_on) +}

New failures caught by the filter:

  * https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_385/fi-cfl-guc/igt@runner@aborted.html

-- 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/338.