Bug 106612

*** Bug 105762 has been marked as a duplicate of this bug. ***

It still happens on CFL: https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_105/fi-cfl-s3/igt@kms_fbcon_fbt@fbc-suspend.html

It doesn't happen that often on PNV though... Not seen since drmtip_82.

Still happening: https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_125/fi-cfl-s3/igt@kms_psr@suspend.html

<4> [416.251551] ------------[ cut here ]------------
<4> [416.251557] Delta way too big! 18446743620799766369 ts=18446744055896263471 write stamp = 435096497102\x0aIf you just came from a suspend/resume,\x0aplease switch to the trace global clock:\x0a  echo global > /sys/kernel/debug/tracing/trace_clock\x0aor add trace_clock=global to the kernel command line
<4> [416.251575] WARNING: CPU: 9 PID: 2469 at kernel/trace/ring_buffer.c:2771 rb_handle_timestamp.isra.30+0x6c/0x70
<4> [416.251578] Modules linked in: vgem i915 cdc_ether usbnet r8152 mii x86_pkg_temp_thermal coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel e1000e mei_me mei prime_numbers
<4> [416.251630] CPU: 9 PID: 2469 Comm: kworker/u24:7 Tainted: G     U            4.19.0-rc7-g6c3870cc0454-drmtip_125+ #1
<4> [416.251633] Hardware name: Intel Corporation CoffeeLake Client Platform/CoffeeLake S UDIMM RVP, BIOS CNLSFWR1.R00.X118.B19.1802080131 02/08/2018
<4> [416.251640] Workqueue: events_unbound async_run_entry_fn
<4> [416.251649] RIP: 0010:rb_handle_timestamp.isra.30+0x6c/0x70
<4> [416.251654] Code: 48 8b 73 08 85 c0 48 8b 13 48 c7 c0 d8 49 07 b5 49 c7 c0 f0 0a 08 b5 4c 0f 44 c0 48 8b 0f 48 c7 c7 98 4a 07 b5 e8 54 f5 f2 ff <0f> 0b eb a8 41 54 55 48 63 f6 53 48 8b 87 a0 00 00 00 48 8b 1c f0
<4> [416.251658] RSP: 0000:ffffbc2940877cd8 EFLAGS: 00010282
<4> [416.251664] RAX: 0000000000000000 RBX: ffffbc2940877cf0 RCX: 0000000000000002
<4> [416.251668] RDX: 0000000080000002 RSI: ffffffffb50f76e2 RDI: 00000000ffffffff
<4> [416.251672] RBP: ffffa231dbdbbb50 R08: 00000000f3233359 R09: 0000000000000000
<4> [416.251675] R10: ffffbc2940877ce8 R11: 0000000000000000 R12: ffffa231dbc18358
<4> [416.251679] R13: ffffa231dbdbbb70 R14: 00000000000003e8 R15: 0000000000000000
<4> [416.251683] FS:  0000000000000000(0000) GS:ffffa231ddc40000(0000) knlGS:0000000000000000
<4> [416.251687] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4> [416.251690] CR2: 0000000000000000 CR3: 0000000495210001 CR4: 00000000003606e0
<4> [416.251694] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
<4> [416.251698] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
<4> [416.251700] Call Trace:
<4> [416.251710]  ring_buffer_lock_reserve+0x210/0x3f0
<4> [416.251785]  ? intel_engines_reset_default_submission+0x30/0x30 [i915]
<4> [416.251793]  __trace_bputs+0x5b/0x130
<4> [416.251801]  ? __mutex_unlock_slowpath+0x46/0x2b0
<4> [416.251873]  intel_engines_sanitize+0x26/0x50 [i915]
<4> [416.251922]  i915_pm_resume_early+0x9c/0x110 [i915]
<4> [416.251971]  ? vlv_resume_prepare+0x670/0x670 [i915]
<4> [416.251979]  dpm_run_callback+0x64/0x280
<4> [416.251990]  device_resume_early+0xa6/0xe0
<4> [416.251999]  async_resume_early+0x14/0x40
<4> [416.252006]  async_run_entry_fn+0x34/0x160
<4> [416.252014]  process_one_work+0x245/0x610
<4> [416.252028]  worker_thread+0x37/0x380
<4> [416.252037]  ? process_one_work+0x610/0x610
<4> [416.252043]  kthread+0x119/0x130
<4> [416.252049]  ? kthread_park+0x80/0x80
<4> [416.252058]  ret_from_fork+0x3a/0x50
<4> [416.252067] irq event stamp: 9730
<4> [416.252067] hardirqs last  enabled at (9729): [<ffffffffb40fd8de>] vprintk_emit+0x2ee/0x310
<4> [416.252067] hardirqs last disabled at (9730): [<ffffffffb4001930>] trace_hardirqs_off_thunk+0x1a/0x1c
<4> [416.252067] softirqs last  enabled at (9558): [<ffffffffb4c0031d>] __do_softirq+0x31d/0x483
<4> [416.252067] softirqs last disabled at (9551): [<ffffffffb4090279>] irq_exit+0xa9/0xc0
<4> [416.252067] WARNING: CPU: 9 PID: 2469 at kernel/trace/ring_buffer.c:2771 rb_handle_timestamp.isra.30+0x6c/0x70
<4> [416.252067] ---[ end trace 4ffd148d29b62864 ]---

https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_132/fi-icl-u/igt@drv_suspend@forcewake.html

https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_132/fi-icl-u/igt@gem_eio@in-flight-suspend.html

<4> [350.625864] ------------[ cut here ]------------
<4> [350.625868] Delta way too big! 18446743711799753644 ts=18446744052547616611 write stamp = 340747862967\x0aIf you just came from a suspend/resume,\x0aplease switch to the trace global clock:\x0a  echo global > /sys/kernel/debug/tracing/trace_clock\x0aor add trace_clock=global to the kernel command line
<4> [350.625880] WARNING: CPU: 6 PID: 2430 at kernel/trace/ring_buffer.c:2771 rb_handle_timestamp.isra.30+0x6c/0x70
<4> [350.625886] Modules linked in: vgem snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic i915 x86_pkg_temp_thermal ax88179_178a usbnet coretemp mii snd_hda_intel crct10dif_pclmul crc32_pclmul ghash_clmulni_intel snd_hda_codec snd_hwdep snd_hda_core e1000e snd_pcm prime_numbers
<4> [350.625936] CPU: 6 PID: 2430 Comm: kworker/u16:45 Tainted: G     U  W         4.19.0-rc8-gae98bc614f3a-drmtip_132+ #1
<4> [350.625939] Hardware name: Intel Corporation Ice Lake Client Platform/IceLake U DDR4 SODIMM PD RVP, BIOS ICLSFWR1.R00.2392.A04.1809260455 09/26/2018
<4> [350.625944] Workqueue: events_unbound async_run_entry_fn
<4> [350.625950] RIP: 0010:rb_handle_timestamp.isra.30+0x6c/0x70
<4> [350.625953] Code: 48 8b 73 08 85 c0 48 8b 13 48 c7 c0 58 4c 07 83 49 c7 c0 70 0d 08 83 4c 0f 44 c0 48 8b 0f 48 c7 c7 18 4d 07 83 e8 c4 f4 f2 ff <0f> 0b eb a8 41 54 55 48 63 f6 53 48 8b 87 a0 00 00 00 48 8b 1c f0
<4> [350.625956] RSP: 0000:ffffa10380bd7cd8 EFLAGS: 00010282
<4> [350.625961] RAX: 0000000000000000 RBX: ffffa10380bd7cf0 RCX: 0000000000000002
<4> [350.625964] RDX: 0000000080000002 RSI: ffffffff830f7992 RDI: 00000000ffffffff
<4> [350.625967] RBP: ffff932cae25a0c0 R08: 00000000f868858b R09: 0000000000000000
<4> [350.625969] R10: ffffa10380bd7ce8 R11: 0000000000000000 R12: ffff932cae018358
<4> [350.625972] R13: ffff932cae25a0e0 R14: 00000000000003e8 R15: 0000000000000000
<4> [350.625975] FS:  0000000000000000(0000) GS:ffff932caff80000(0000) knlGS:0000000000000000
<4> [350.625978] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4> [350.625981] CR2: 0000000000000000 CR3: 000000036e210001 CR4: 0000000000760ee0
<4> [350.625984] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
<4> [350.625987] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
<4> [350.625989] PKRU: 00000000
<4> [350.625991] Call Trace:
<4> [350.625997]  ring_buffer_lock_reserve+0x210/0x3f0
<4> [350.626050]  ? intel_engines_reset_default_submission+0x30/0x30 [i915]
<4> [350.626056]  __trace_bputs+0x5b/0x130
<4> [350.626061]  ? __mutex_unlock_slowpath+0x46/0x2b0
<4> [350.626112]  intel_engines_sanitize+0x26/0x50 [i915]
<4> [350.626150]  i915_pm_resume_early+0x9c/0x110 [i915]
<4> [350.626189]  ? vlv_resume_prepare+0x670/0x670 [i915]
<4> [350.626195]  dpm_run_callback+0x64/0x280
<4> [350.626202]  device_resume_early+0xa6/0xe0
<4> [350.626209]  async_resume_early+0x14/0x40
<4> [350.626213]  async_run_entry_fn+0x34/0x160
<4> [350.626219]  process_one_work+0x245/0x610
<4> [350.626230]  worker_thread+0x37/0x380
<4> [350.626237]  ? process_one_work+0x610/0x610
<4> [350.626241]  kthread+0x119/0x130
<4> [350.626245]  ? kthread_park+0x80/0x80
<4> [350.626251]  ret_from_fork+0x3a/0x50
<4> [350.626265] irq event stamp: 620
<4> [350.626270] hardirqs last  enabled at (619): [<ffffffff820fd8ee>] vprintk_emit+0x2ee/0x310
<4> [350.626274] hardirqs last disabled at (620): [<ffffffff82001930>] trace_hardirqs_off_thunk+0x1a/0x1c
<4> [350.626278] softirqs last  enabled at (582): [<ffffffff82c0031d>] __do_softirq+0x31d/0x483
<4> [350.626282] softirqs last disabled at (575): [<ffffffff82090279>] irq_exit+0xa9/0xc0
<4> [350.626287] WARNING: CPU: 6 PID: 2430 at kernel/trace/ring_buffer.c:2771 rb_handle_timestamp.isra.30+0x6c/0x70
<4> [350.626289] ---[ end trace f410470ab7747c30 ]---

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

{- CFL ICL: igt@runner@aborted - fail - Previous test: (gem_workarounds \(suspend-resume\)|gem_ctx_isolation \(vecs0-s3\)|i915_suspend \(fence-restore-untiled\)|.) -}
{+ CFL ICL: igt@runner@aborted - fail - many reasons +}

 No new failures caught with the new filter

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

{- CFL ICL: igt@runner@aborted - fail - many reasons -}
{+ CFL ICL: igt@runner@aborted - fail - many reasons +}

New failures caught by the filter:

* https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_196/fi-icl-u3/igt@runner@aborted.html

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

{- CFL ICL: igt@runner@aborted - fail - many reasons -}
{+ CFL ICL: igt@runner@aborted - fail - many reasons +}

New failures caught by the filter:

* https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_210/fi-icl-u3/igt@runner@aborted.html

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

{- PNV CFL ICL: igt@*(s3|suspend)* - dmesg-warn / dmesg-fail - Delta way too big! -}
{+ PNV CFL ICL: igt@*(s3|suspend)* - dmesg-warn / dmesg-fail - Delta way too big! +}

New failures caught by the filter:

* https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_212/fi-icl-u3/igt@kms_flip@2x-flip-vs-suspend-interruptible.html

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

{- CFL ICL: igt@runner@aborted - fail - many reasons -}
{+ CFL ICL: igt@runner@aborted - fail - many reasons +}

New failures caught by the filter:

* https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_212/fi-icl-u3/igt@runner@aborted.html

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

{- CFL ICL: igt@runner@aborted - fail - many reasons -}
{+ CFL ICL: igt@runner@aborted - fail - many reasons +}

New failures caught by the filter:

* https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_212/fi-icl-u3/igt@runner@aborted.html

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

{- PNV CFL ICL: igt@*(s3|suspend)* - dmesg-warn / dmesg-fail - Delta way too big! -}
{+ PNV CFL ICL: igt@*(s3|suspend)* - dmesg-warn / dmesg-fail - Delta way too big! +}

New failures caught by the filter:

* https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_212/fi-icl-u3/igt@kms_psr@psr2_suspend.html

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

{- CFL ICL: igt@runner@aborted - fail - many reasons -}
{+ CFL ICL: igt@runner@aborted - fail - many reasons +}

New failures caught by the filter:

* https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_212/fi-icl-u3/igt@runner@aborted.html

The following happens on ICL as well (besides PNV and CFL):

If you just came from a suspend/resume,
please switch to the trace global clock:
echo global > /sys/kernel/debug/tracing/trace_clock
or add trace_clock=global to the kernel command line

In bug 105762 Chris mentioned that this shouldn't happen on new hardware. Should the ICL cases be reported upstream then?

Different issue; it's an unstable tsc clock source that is unexpected. The delta too big from ftrace across suspend is expected by ftrace at least.

(In reply to Chris Wilson from comment #14)
> Different issue; it's an unstable tsc clock source that is unexpected. The
> delta too big from ftrace across suspend is expected by ftrace at least.

Ah, ok, so here (on all of PNV, CFL, ICL) we should just do what dmesg tells us.

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

New failures matching the above filters will not be associated to this bug anymore.

This seems fixed anyway! No failures after 460 runs, when it used to fail roughly every other run...