Bug 106612 - [CI] igt@*(s3|suspend) - dmesg-warn - Delta way too big!
Summary: [CI] igt@*(s3|suspend) - dmesg-warn - Delta way too big!
Status: NEW
Alias: None
Product: DRI
Classification: Unclassified
Component: DRM/Intel (show other bugs)
Version: XOrg git
Hardware: Other All
: medium normal
Assignee: Intel GFX Bugs mailing list
QA Contact: Intel GFX Bugs mailing list
URL:
Whiteboard: ReadyForDev
Keywords:
: 105762 (view as bug list)
Depends on:
Blocks:
 
Reported: 2018-05-22 07:47 UTC by Martin Peres
Modified: 2019-02-08 15:28 UTC (History)
2 users (show)

See Also:
i915 platform: CFL, PNV
i915 features: power/Other


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Martin Peres 2018-05-22 07:47:23 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_34/fi-pnv-d510/igt@gem_exec_suspend@basic-s3.html

[  201.321575] ------------[ cut here ]------------
[  201.321587] Delta way too big! 18446743859196209652 ts=18446744047386161939 write stamp = 188189952287
               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
[  201.321621] WARNING: CPU: 3 PID: 117 at kernel/trace/ring_buffer.c:2768 rb_handle_timestamp.isra.30+0x6c/0x70
[  201.321626] Modules linked in: vgem i915 coretemp snd_hda_codec_realtek snd_hda_codec_generic snd_hda_intel lpc_ich snd_hda_codec snd_hwdep snd_hda_core snd_pcm r8169 mii prime_numbers
[  201.321697] CPU: 3 PID: 117 Comm: kworker/u8:4 Tainted: G     U            4.17.0-rc4-g06e15c0f055b-drmtip_34+ #1
[  201.321703] Hardware name:  /D510MO, BIOS MOPNV10J.86A.0311.2010.0802.2346 08/02/2010
[  201.321713] Workqueue: events_unbound async_run_entry_fn
[  201.321726] RIP: 0010:rb_handle_timestamp.isra.30+0x6c/0x70
[  201.321733] RSP: 0018:ffffbb7c8033bb70 EFLAGS: 00010286
[  201.321742] RAX: 0000000000000000 RBX: ffffbb7c8033bb88 RCX: 0000000000000003
[  201.321748] RDX: 0000000080000003 RSI: 0000000000000001 RDI: 00000000ffffffff
[  201.321754] RBP: ffffa082fd337b10 R08: 0000000000000000 R09: 0000000000000000
[  201.321760] R10: ffffbb7c8033bb80 R11: ffffffff852444b8 R12: ffffa082fd018358
[  201.321766] R13: ffffa082fd337b30 R14: 00000000000003e8 R15: 0000000000000005
[  201.321773] FS:  0000000000000000(0000) GS:ffffa082fed80000(0000) knlGS:0000000000000000
[  201.321780] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  201.321785] CR2: 0000000000000000 CR3: 00000000371b2000 CR4: 00000000000006e0
[  201.321790] Call Trace:
[  201.321806]  ring_buffer_lock_reserve+0x210/0x3f0
[  201.322011]  ? i915_request_await_object+0x370/0x370 [i915]
[  201.322011]  trace_vbprintk+0xb4/0x220
[  201.322011]  __trace_bprintk+0x57/0x80
[  201.322011]  __i915_request_add+0x4f/0x7c0 [i915]
[  201.322011]  ? i915_request_alloc+0x2da/0x740 [i915]
[  201.322011]  i915_gem_switch_to_kernel_context+0x122/0x1a0 [i915]
[  201.322011]  ? pcie_port_bus_match+0x50/0x50
[  201.322011]  i915_gem_resume+0x9f/0xc0 [i915]
[  201.322011]  i915_pm_resume+0x7c/0x130 [i915]
[  201.322011]  dpm_run_callback+0x5d/0x2f0
[  201.322011]  device_resume+0xb3/0x1e0
[  201.322011]  ? dpm_watchdog_set+0x60/0x60
[  201.322011]  async_resume+0x14/0x40
[  201.322011]  async_run_entry_fn+0x34/0x160
[  201.322011]  process_one_work+0x229/0x6a0
[  201.322011]  worker_thread+0x35/0x380
[  201.322011]  ? process_one_work+0x6a0/0x6a0
[  201.322011]  kthread+0x119/0x130
[  201.322011]  ? _kthread_create_on_node+0x60/0x60
[  201.323250]  ret_from_fork+0x24/0x50
[  201.323250] Code: 24 48 8b 73 08 85 c0 48 8b 13 48 c7 c0 30 97 07 85 49 c7 c0 6e 55 08 85 4c 0f 44 c0 48 8b 0f 48 c7 c7 f0 97 07 85 e8 74 18 f3 ff <0f> 0b eb a8 41 54 55 48 63 f6 53 48 8b 87 a0 00 00 00 48 8b 1c 
[  201.323513] irq event stamp: 3250
[  201.323513] hardirqs last  enabled at (3249): [<ffffffff849487c4>] _raw_spin_unlock_irq+0x24/0x50
[  201.323513] hardirqs last disabled at (3250): [<ffffffff8494126a>] __schedule+0xaa/0xbe0
[  201.323513] softirqs last  enabled at (2922): [<ffffffff84c0032b>] __do_softirq+0x32b/0x4e1
[  201.323513] softirqs last disabled at (2915): [<ffffffff8408f6f4>] irq_exit+0xa4/0xb0
[  201.323513] WARNING: CPU: 3 PID: 117 at kernel/trace/ring_buffer.c:2768 rb_handle_timestamp.isra.30+0x6c/0x70
[  201.323513] ---[ end trace 8d91a263e8535748 ]---
Comment 1 Chris Wilson 2018-05-25 11:56:16 UTC
*** Bug 105762 has been marked as a duplicate of this bug. ***
Comment 2 Martin Peres 2018-09-07 17:05:21 UTC
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.
Comment 3 Martin Peres 2018-10-12 14:40:44 UTC
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 ]---
Comment 4 Martin Peres 2018-10-24 10:57:03 UTC
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 ]---
Comment 5 CI Bug Log 2019-01-04 15:30:59 UTC
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
Comment 6 CI Bug Log 2019-01-25 14:04:22 UTC
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
Comment 7 CI Bug Log 2019-02-07 14:40:02 UTC
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
Comment 8 CI Bug Log 2019-02-08 15:16:44 UTC
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
Comment 9 CI Bug Log 2019-02-08 15:17:42 UTC
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
Comment 10 CI Bug Log 2019-02-08 15:21:52 UTC
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
Comment 11 CI Bug Log 2019-02-08 15:28:38 UTC
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
Comment 12 CI Bug Log 2019-02-08 15:28:59 UTC
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


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.