* [PATCH] drm/i915: Use trace_printk to provide a death rattle for GEM
@ 2017-11-08 12:20 Chris Wilson
2017-11-08 14:57 ` ✓ Fi.CI.BAT: success for " Patchwork
` (6 more replies)
0 siblings, 7 replies; 12+ messages in thread
From: Chris Wilson @ 2017-11-08 12:20 UTC (permalink / raw)
To: intel-gfx
Trying to enable printk debugging for GEM is fraught with the issue of
spam; interactions with HW are very frequent and often boring. However,
one instance where they are not so boring is just before a BUG; here
ftrace provides a facility to dump its ringbuffer on an oops. So for CI
let's enable trace_printk() to capture the last exchanges with HW as a
death rattle.
For example,
[ 72.120722] ------------[ cut here ]------------
[ 72.120748] kernel BUG at drivers/gpu/drm/i915/intel_lrc.c:905!
[ 72.120756] invalid opcode: 0000 [#1] SMP
[ 72.120762] Dumping ftrace buffer:
[ 72.120768] ---------------------------------
...
[ 72.200424] gem_conc-1064 0..s1 71949306us : intel_lrc_irq_handler: bcs0 in: ctx=4.1, seqno=161
[ 72.200469] gem_conc-1064 0..s1 71949312us : intel_lrc_irq_handler: bcs0 in: ctx=6.2, seqno=160
[ 72.200512] gem_conc-1066 1..s1 71949325us : intel_lrc_irq_handler: bcs0 csb[4/4]: status=0x00008002
[ 72.200555] gem_conc-1066 1..s1 71949326us : intel_lrc_irq_handler: bcs0 out: ctx=6, seqno=160
[ 72.200601] gem_conc-1066 1..s. 71956923us : intel_lrc_irq_handler: bcs0 csb[5/5]: status=0x00000014
[ 72.200646] gem_conc-1066 1..s. 71956928us : intel_lrc_irq_handler: bcs0 out: ctx=6, seqno=160
[ 72.200690] gem_conc-1066 1..s. 71956939us : intel_lrc_irq_handler: bcs0 in: ctx=8.1, seqno=164
[ 72.200736] gem_conc-1066 1..s. 71956940us : intel_lrc_irq_handler: bcs0 in: ctx=4.2, seqno=162
[ 72.200780] gem_conc-1066 1..s. 71956951us : intel_lrc_irq_handler: bcs0 csb[0/0]: status=0x00008002
[ 72.200824] gem_conc-1066 1..s. 71956951us : intel_lrc_irq_handler: bcs0 out: ctx=4, seqno=162
[ 72.200867] <idle>-0 1..s1 71967999us : intel_lrc_irq_handler: bcs0 csb[1/1]: status=0x00000014
[ 72.200912] <idle>-0 1..s1 71968001us : intel_lrc_irq_handler: bcs0 out: ctx=4, seqno=162
[ 72.200956] <idle>-0 1.Ns1 71979385us : intel_lrc_irq_handler: bcs0 csb[2/2]: status=0x00000018
[ 72.201001] <idle>-0 1.Ns1 71979388us : intel_lrc_irq_handler: bcs0 out: ctx=8, seqno=164
[ 72.201044] gem_conc-1063 3..s1 72086825us : intel_lrc_irq_handler: bcs0 in: ctx=7.1, seqno=165
[ 72.201088] gem_conc-1066 1..s. 72086918us : intel_lrc_irq_handler: bcs0 csb[3/3]: status=0x00000001
[ 72.201132] gem_conc-1066 1..s. 72086932us : intel_lrc_irq_handler: bcs0 in: ctx=7.2, seqno=166
[ 72.201176] gem_conc-1066 1..s. 72086941us : intel_lrc_irq_handler: bcs0 csb[4/4]: status=0x00008002
[ 72.201219] gem_conc-1066 1..s. 72086941us : intel_lrc_irq_handler: bcs0 out: ctx=7, seqno=166
[ 72.201263] gem_conc-1066 1..s. 72103855us : intel_lrc_irq_handler: bcs0 csb[5/5]: status=0x00000018
[ 72.201307] gem_conc-1066 1..s. 72103858us : intel_lrc_irq_handler: bcs0 out: ctx=7, seqno=166
[ 72.201351] gem_conc-1064 0..s1 72116924us : intel_lrc_irq_handler: bcs0 in: ctx=4.1, seqno=167
[ 72.201394] gem_conc-1064 0..s1 72116981us : intel_lrc_irq_handler: bcs0 in: ctx=4.2, seqno=168
[ 72.201438] gem_conc-1066 1..s1 72117545us : intel_lrc_irq_handler: bcs0 csb[0/2]: status=0x00000012
[ 72.201482] gem_conc-1066 1..s1 72117547us : intel_lrc_irq_handler: bcs0 out: ctx=4, seqno=168
[ 72.201526] gem_conc-1066 1..s1 72117548us : intel_lrc_irq_handler: bcs0 csb[1/2]: status=0x00008002
[ 72.201570] gem_conc-1066 1..s1 72117548us : intel_lrc_irq_handler: bcs0 out: ctx=4, seqno=168
[ 72.201578] ---------------------------------
Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>
Cc: Mika Kuoppala <mika.kuoppala@linux.intel.com>
Cc: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
Cc: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
---
drivers/gpu/drm/i915/Kconfig.debug | 14 ++++++++++++++
drivers/gpu/drm/i915/i915_gem.h | 6 ++++++
drivers/gpu/drm/i915/intel_lrc.c | 13 +++++++++++++
3 files changed, 33 insertions(+)
diff --git a/drivers/gpu/drm/i915/Kconfig.debug b/drivers/gpu/drm/i915/Kconfig.debug
index 19c77c6feb24..9e53edbc713b 100644
--- a/drivers/gpu/drm/i915/Kconfig.debug
+++ b/drivers/gpu/drm/i915/Kconfig.debug
@@ -28,6 +28,7 @@ config DRM_I915_DEBUG
select SW_SYNC # signaling validation framework (igt/syncobj*)
select DRM_I915_SW_FENCE_DEBUG_OBJECTS
select DRM_I915_SELFTEST
+ select DRM_I915_TRACE_GEM
default n
help
Choose this option to turn on extra driver debugging that may affect
@@ -49,6 +50,19 @@ config DRM_I915_DEBUG_GEM
If in doubt, say "N".
+config DRM_I915_TRACE_GEM
+ bool "Insert extra ftrace output from the GEM internals"
+ select TRACING
+ default n
+ help
+ Enable additional and verbose debugging output that will spam
+ ordinary tests, but may be vital for post-mortem debugging when
+ used with /proc/sys/kernel/ftrace_dump_on_oops
+
+ Recommended for driver developers only.
+
+ If in doubt, say "N".
+
config DRM_I915_SW_FENCE_DEBUG_OBJECTS
bool "Enable additional driver debugging for fence objects"
depends on DRM_I915
diff --git a/drivers/gpu/drm/i915/i915_gem.h b/drivers/gpu/drm/i915/i915_gem.h
index ee54597465b6..d7905e4a1cf4 100644
--- a/drivers/gpu/drm/i915/i915_gem.h
+++ b/drivers/gpu/drm/i915/i915_gem.h
@@ -44,6 +44,12 @@
#define GEM_DEBUG_BUG_ON(expr)
#endif
+#if IS_ENABLED(CONFIG_DRM_I915_TRACE_GEM)
+#define GEM_TRACE(...) trace_printk(__VA_ARGS__)
+#else
+#define GEM_TRACE(...)
+#endif
+
#define I915_NUM_ENGINES 5
#endif /* __I915_GEM_H__ */
diff --git a/drivers/gpu/drm/i915/intel_lrc.c b/drivers/gpu/drm/i915/intel_lrc.c
index 4f56ff5cb908..5c3919ea519d 100644
--- a/drivers/gpu/drm/i915/intel_lrc.c
+++ b/drivers/gpu/drm/i915/intel_lrc.c
@@ -467,6 +467,12 @@ static void execlists_submit_ports(struct intel_engine_cs *engine)
port_set(&port[n], port_pack(rq, count));
desc = execlists_update_context(rq);
GEM_DEBUG_EXEC(port[n].context_id = upper_32_bits(desc));
+
+ GEM_TRACE("%s in: ctx=%d.%d, seqno=%x\n",
+ engine->name,
+ rq->ctx->hw_id,
+ count,
+ rq->global_seqno);
} else {
GEM_BUG_ON(!n);
desc = 0;
@@ -521,6 +527,7 @@ static void inject_preempt_context(struct intel_engine_cs *engine)
ce->ring->tail &= (ce->ring->size - 1);
ce->lrc_reg_state[CTX_RING_TAIL+1] = ce->ring->tail;
+ GEM_TRACE("\n");
for (n = execlists_num_ports(&engine->execlists); --n; )
elsp_write(0, elsp);
@@ -860,6 +867,8 @@ static void intel_lrc_irq_handler(unsigned long data)
*/
status = READ_ONCE(buf[2 * head]); /* maybe mmio! */
+ GEM_TRACE("%s csb[%d/%d]: status=0x%08x\n",
+ engine->name, head, tail, status);
if (!(status & GEN8_CTX_STATUS_COMPLETED_MASK))
continue;
@@ -888,6 +897,10 @@ static void intel_lrc_irq_handler(unsigned long data)
rq = port_unpack(port, &count);
GEM_BUG_ON(count == 0);
+ GEM_TRACE("%s out: ctx=%d, seqno=%x\n",
+ engine->name,
+ rq->ctx->hw_id,
+ rq->global_seqno);
if (--count == 0) {
GEM_BUG_ON(status & GEN8_CTX_STATUS_PREEMPTED);
GEM_BUG_ON(!i915_gem_request_completed(rq));
--
2.15.0
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx
^ permalink raw reply related [flat|nested] 12+ messages in thread
* ✓ Fi.CI.BAT: success for drm/i915: Use trace_printk to provide a death rattle for GEM
2017-11-08 12:20 [PATCH] drm/i915: Use trace_printk to provide a death rattle for GEM Chris Wilson
@ 2017-11-08 14:57 ` Patchwork
2017-11-08 15:40 ` ✗ Fi.CI.IGT: warning " Patchwork
` (5 subsequent siblings)
6 siblings, 0 replies; 12+ messages in thread
From: Patchwork @ 2017-11-08 14:57 UTC (permalink / raw)
To: Chris Wilson; +Cc: intel-gfx
== Series Details ==
Series: drm/i915: Use trace_printk to provide a death rattle for GEM
URL : https://patchwork.freedesktop.org/series/33421/
State : success
== Summary ==
Series 33421v1 drm/i915: Use trace_printk to provide a death rattle for GEM
https://patchwork.freedesktop.org/api/1.0/series/33421/revisions/1/mbox/
Test chamelium:
Subgroup dp-crc-fast:
fail -> PASS (fi-kbl-7500u) fdo#102514
fdo#102514 https://bugs.freedesktop.org/show_bug.cgi?id=102514
fi-bdw-5557u total:289 pass:268 dwarn:0 dfail:0 fail:0 skip:21 time:446s
fi-bdw-gvtdvm total:289 pass:265 dwarn:0 dfail:0 fail:0 skip:24 time:461s
fi-blb-e6850 total:289 pass:223 dwarn:1 dfail:0 fail:0 skip:65 time:380s
fi-bsw-n3050 total:289 pass:243 dwarn:0 dfail:0 fail:0 skip:46 time:533s
fi-bwr-2160 total:289 pass:183 dwarn:0 dfail:0 fail:0 skip:106 time:275s
fi-bxt-dsi total:289 pass:259 dwarn:0 dfail:0 fail:0 skip:30 time:501s
fi-bxt-j4205 total:289 pass:260 dwarn:0 dfail:0 fail:0 skip:29 time:500s
fi-byt-j1900 total:289 pass:254 dwarn:0 dfail:0 fail:0 skip:35 time:496s
fi-byt-n2820 total:289 pass:250 dwarn:0 dfail:0 fail:0 skip:39 time:484s
fi-elk-e7500 total:289 pass:229 dwarn:0 dfail:0 fail:0 skip:60 time:439s
fi-gdg-551 total:289 pass:178 dwarn:1 dfail:0 fail:1 skip:109 time:267s
fi-glk-1 total:289 pass:261 dwarn:0 dfail:0 fail:0 skip:28 time:538s
fi-hsw-4770 total:289 pass:262 dwarn:0 dfail:0 fail:0 skip:27 time:427s
fi-hsw-4770r total:289 pass:262 dwarn:0 dfail:0 fail:0 skip:27 time:438s
fi-ilk-650 total:289 pass:228 dwarn:0 dfail:0 fail:0 skip:61 time:429s
fi-ivb-3520m total:289 pass:260 dwarn:0 dfail:0 fail:0 skip:29 time:481s
fi-ivb-3770 total:289 pass:260 dwarn:0 dfail:0 fail:0 skip:29 time:461s
fi-kbl-7500u total:289 pass:264 dwarn:1 dfail:0 fail:0 skip:24 time:480s
fi-kbl-7567u total:289 pass:269 dwarn:0 dfail:0 fail:0 skip:20 time:471s
fi-kbl-r total:289 pass:262 dwarn:0 dfail:0 fail:0 skip:27 time:537s
fi-pnv-d510 total:289 pass:222 dwarn:1 dfail:0 fail:0 skip:66 time:565s
fi-skl-6260u total:289 pass:269 dwarn:0 dfail:0 fail:0 skip:20 time:456s
fi-skl-6600u total:289 pass:262 dwarn:0 dfail:0 fail:0 skip:27 time:543s
fi-skl-6700hq total:289 pass:263 dwarn:0 dfail:0 fail:0 skip:26 time:561s
fi-skl-6700k total:289 pass:265 dwarn:0 dfail:0 fail:0 skip:24 time:513s
fi-skl-6770hq total:289 pass:269 dwarn:0 dfail:0 fail:0 skip:20 time:493s
fi-skl-gvtdvm total:289 pass:266 dwarn:0 dfail:0 fail:0 skip:23 time:458s
fi-snb-2520m total:289 pass:250 dwarn:0 dfail:0 fail:0 skip:39 time:556s
fi-snb-2600 total:289 pass:249 dwarn:0 dfail:0 fail:0 skip:40 time:422s
Blacklisted hosts:
fi-cnl-y total:289 pass:262 dwarn:0 dfail:0 fail:0 skip:27 time:563s
fi-glk-dsi total:289 pass:258 dwarn:0 dfail:0 fail:1 skip:30 time:486s
748f2c6b4046b23a623b4af3799563ef3110bb0d drm-tip: 2017y-11m-08d-07h-50m-13s UTC integration manifest
99aa224023e3 drm/i915: Use trace_printk to provide a death rattle for GEM
== Logs ==
For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/Patchwork_7011/
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx
^ permalink raw reply [flat|nested] 12+ messages in thread
* ✗ Fi.CI.IGT: warning for drm/i915: Use trace_printk to provide a death rattle for GEM
2017-11-08 12:20 [PATCH] drm/i915: Use trace_printk to provide a death rattle for GEM Chris Wilson
2017-11-08 14:57 ` ✓ Fi.CI.BAT: success for " Patchwork
@ 2017-11-08 15:40 ` Patchwork
2017-11-09 11:15 ` [PATCH v2] " Chris Wilson
` (4 subsequent siblings)
6 siblings, 0 replies; 12+ messages in thread
From: Patchwork @ 2017-11-08 15:40 UTC (permalink / raw)
To: Chris Wilson; +Cc: intel-gfx
== Series Details ==
Series: drm/i915: Use trace_printk to provide a death rattle for GEM
URL : https://patchwork.freedesktop.org/series/33421/
State : warning
== Summary ==
Test kms_chv_cursor_fail:
Subgroup pipe-c-128x128-bottom-edge:
pass -> SKIP (shard-hsw)
Test kms_properties:
Subgroup plane-properties-atomic:
pass -> SKIP (shard-hsw)
Test perf:
Subgroup blocking:
pass -> FAIL (shard-hsw) fdo#102252
Test kms_cursor_legacy:
Subgroup flip-vs-cursor-toggle:
skip -> PASS (shard-hsw) fdo#102670
Test kms_setmode:
Subgroup basic:
fail -> PASS (shard-hsw) fdo#99912
fdo#102252 https://bugs.freedesktop.org/show_bug.cgi?id=102252
fdo#102670 https://bugs.freedesktop.org/show_bug.cgi?id=102670
fdo#99912 https://bugs.freedesktop.org/show_bug.cgi?id=99912
shard-hsw total:2540 pass:1430 dwarn:1 dfail:0 fail:10 skip:1099 time:9264s
== Logs ==
For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/Patchwork_7011/shards.html
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx
^ permalink raw reply [flat|nested] 12+ messages in thread
* [PATCH v2] drm/i915: Use trace_printk to provide a death rattle for GEM
2017-11-08 12:20 [PATCH] drm/i915: Use trace_printk to provide a death rattle for GEM Chris Wilson
2017-11-08 14:57 ` ✓ Fi.CI.BAT: success for " Patchwork
2017-11-08 15:40 ` ✗ Fi.CI.IGT: warning " Patchwork
@ 2017-11-09 11:15 ` Chris Wilson
2017-11-09 11:53 ` Joonas Lahtinen
2017-11-09 12:19 ` ✓ Fi.CI.BAT: success for drm/i915: Use trace_printk to provide a death rattle for GEM (rev2) Patchwork
` (3 subsequent siblings)
6 siblings, 1 reply; 12+ messages in thread
From: Chris Wilson @ 2017-11-09 11:15 UTC (permalink / raw)
To: intel-gfx
Trying to enable printk debugging for GEM is fraught with the issue of
spam; interactions with HW are very frequent and often boring. However,
one instance where they are not so boring is just before a BUG; here
ftrace provides a facility to dump its ringbuffer on an oops. So for CI
let's enable trace_printk() to capture the last exchanges with HW as a
death rattle.
For example,
[ 72.120722] ------------[ cut here ]------------
[ 72.120748] kernel BUG at drivers/gpu/drm/i915/intel_lrc.c:905!
[ 72.120756] invalid opcode: 0000 [#1] SMP
[ 72.120762] Dumping ftrace buffer:
[ 72.120768] ---------------------------------
...
[ 72.200424] gem_conc-1064 0..s1 71949306us : intel_lrc_irq_handler: bcs0 in: ctx=4.1, seqno=161
[ 72.200469] gem_conc-1064 0..s1 71949312us : intel_lrc_irq_handler: bcs0 in: ctx=6.2, seqno=160
[ 72.200512] gem_conc-1066 1..s1 71949325us : intel_lrc_irq_handler: bcs0 csb[4/4]: status=0x00008002
[ 72.200555] gem_conc-1066 1..s1 71949326us : intel_lrc_irq_handler: bcs0 out: ctx=6, seqno=160
[ 72.200601] gem_conc-1066 1..s. 71956923us : intel_lrc_irq_handler: bcs0 csb[5/5]: status=0x00000014
[ 72.200646] gem_conc-1066 1..s. 71956928us : intel_lrc_irq_handler: bcs0 out: ctx=6, seqno=160
[ 72.200690] gem_conc-1066 1..s. 71956939us : intel_lrc_irq_handler: bcs0 in: ctx=8.1, seqno=164
[ 72.200736] gem_conc-1066 1..s. 71956940us : intel_lrc_irq_handler: bcs0 in: ctx=4.2, seqno=162
[ 72.200780] gem_conc-1066 1..s. 71956951us : intel_lrc_irq_handler: bcs0 csb[0/0]: status=0x00008002
[ 72.200824] gem_conc-1066 1..s. 71956951us : intel_lrc_irq_handler: bcs0 out: ctx=4, seqno=162
[ 72.200867] <idle>-0 1..s1 71967999us : intel_lrc_irq_handler: bcs0 csb[1/1]: status=0x00000014
[ 72.200912] <idle>-0 1..s1 71968001us : intel_lrc_irq_handler: bcs0 out: ctx=4, seqno=162
[ 72.200956] <idle>-0 1.Ns1 71979385us : intel_lrc_irq_handler: bcs0 csb[2/2]: status=0x00000018
[ 72.201001] <idle>-0 1.Ns1 71979388us : intel_lrc_irq_handler: bcs0 out: ctx=8, seqno=164
[ 72.201044] gem_conc-1063 3..s1 72086825us : intel_lrc_irq_handler: bcs0 in: ctx=7.1, seqno=165
[ 72.201088] gem_conc-1066 1..s. 72086918us : intel_lrc_irq_handler: bcs0 csb[3/3]: status=0x00000001
[ 72.201132] gem_conc-1066 1..s. 72086932us : intel_lrc_irq_handler: bcs0 in: ctx=7.2, seqno=166
[ 72.201176] gem_conc-1066 1..s. 72086941us : intel_lrc_irq_handler: bcs0 csb[4/4]: status=0x00008002
[ 72.201219] gem_conc-1066 1..s. 72086941us : intel_lrc_irq_handler: bcs0 out: ctx=7, seqno=166
[ 72.201263] gem_conc-1066 1..s. 72103855us : intel_lrc_irq_handler: bcs0 csb[5/5]: status=0x00000018
[ 72.201307] gem_conc-1066 1..s. 72103858us : intel_lrc_irq_handler: bcs0 out: ctx=7, seqno=166
[ 72.201351] gem_conc-1064 0..s1 72116924us : intel_lrc_irq_handler: bcs0 in: ctx=4.1, seqno=167
[ 72.201394] gem_conc-1064 0..s1 72116981us : intel_lrc_irq_handler: bcs0 in: ctx=4.2, seqno=168
[ 72.201438] gem_conc-1066 1..s1 72117545us : intel_lrc_irq_handler: bcs0 csb[0/2]: status=0x00000012
[ 72.201482] gem_conc-1066 1..s1 72117547us : intel_lrc_irq_handler: bcs0 out: ctx=4, seqno=168
[ 72.201526] gem_conc-1066 1..s1 72117548us : intel_lrc_irq_handler: bcs0 csb[1/2]: status=0x00008002
[ 72.201570] gem_conc-1066 1..s1 72117548us : intel_lrc_irq_handler: bcs0 out: ctx=4, seqno=168
[ 72.201578] ---------------------------------
v2: Tweak the formatting to be more consistent between in/out.
Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>
Cc: Mika Kuoppala <mika.kuoppala@linux.intel.com>
Cc: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
Cc: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
---
drivers/gpu/drm/i915/Kconfig.debug | 14 ++++++++++++++
drivers/gpu/drm/i915/i915_gem.h | 6 ++++++
drivers/gpu/drm/i915/intel_lrc.c | 14 ++++++++++++++
3 files changed, 34 insertions(+)
diff --git a/drivers/gpu/drm/i915/Kconfig.debug b/drivers/gpu/drm/i915/Kconfig.debug
index 19c77c6feb24..9e53edbc713b 100644
--- a/drivers/gpu/drm/i915/Kconfig.debug
+++ b/drivers/gpu/drm/i915/Kconfig.debug
@@ -28,6 +28,7 @@ config DRM_I915_DEBUG
select SW_SYNC # signaling validation framework (igt/syncobj*)
select DRM_I915_SW_FENCE_DEBUG_OBJECTS
select DRM_I915_SELFTEST
+ select DRM_I915_TRACE_GEM
default n
help
Choose this option to turn on extra driver debugging that may affect
@@ -49,6 +50,19 @@ config DRM_I915_DEBUG_GEM
If in doubt, say "N".
+config DRM_I915_TRACE_GEM
+ bool "Insert extra ftrace output from the GEM internals"
+ select TRACING
+ default n
+ help
+ Enable additional and verbose debugging output that will spam
+ ordinary tests, but may be vital for post-mortem debugging when
+ used with /proc/sys/kernel/ftrace_dump_on_oops
+
+ Recommended for driver developers only.
+
+ If in doubt, say "N".
+
config DRM_I915_SW_FENCE_DEBUG_OBJECTS
bool "Enable additional driver debugging for fence objects"
depends on DRM_I915
diff --git a/drivers/gpu/drm/i915/i915_gem.h b/drivers/gpu/drm/i915/i915_gem.h
index ee54597465b6..d7905e4a1cf4 100644
--- a/drivers/gpu/drm/i915/i915_gem.h
+++ b/drivers/gpu/drm/i915/i915_gem.h
@@ -44,6 +44,12 @@
#define GEM_DEBUG_BUG_ON(expr)
#endif
+#if IS_ENABLED(CONFIG_DRM_I915_TRACE_GEM)
+#define GEM_TRACE(...) trace_printk(__VA_ARGS__)
+#else
+#define GEM_TRACE(...)
+#endif
+
#define I915_NUM_ENGINES 5
#endif /* __I915_GEM_H__ */
diff --git a/drivers/gpu/drm/i915/intel_lrc.c b/drivers/gpu/drm/i915/intel_lrc.c
index 4f56ff5cb908..fb2a46f5a9c0 100644
--- a/drivers/gpu/drm/i915/intel_lrc.c
+++ b/drivers/gpu/drm/i915/intel_lrc.c
@@ -467,6 +467,12 @@ static void execlists_submit_ports(struct intel_engine_cs *engine)
port_set(&port[n], port_pack(rq, count));
desc = execlists_update_context(rq);
GEM_DEBUG_EXEC(port[n].context_id = upper_32_bits(desc));
+
+ GEM_TRACE("%s in[%d]: ctx=%d.%d, seqno=%x\n",
+ engine->name, n,
+ rq->ctx->hw_id,
+ count,
+ rq->global_seqno);
} else {
GEM_BUG_ON(!n);
desc = 0;
@@ -521,6 +527,7 @@ static void inject_preempt_context(struct intel_engine_cs *engine)
ce->ring->tail &= (ce->ring->size - 1);
ce->lrc_reg_state[CTX_RING_TAIL+1] = ce->ring->tail;
+ GEM_TRACE("\n");
for (n = execlists_num_ports(&engine->execlists); --n; )
elsp_write(0, elsp);
@@ -860,6 +867,9 @@ static void intel_lrc_irq_handler(unsigned long data)
*/
status = READ_ONCE(buf[2 * head]); /* maybe mmio! */
+ GEM_TRACE("%s csb[%d/%d]: status=0x%08x:0x%08x\n",
+ engine->name, head, tail,
+ status, buf[2*head + 1]);
if (!(status & GEN8_CTX_STATUS_COMPLETED_MASK))
continue;
@@ -887,6 +897,10 @@ static void intel_lrc_irq_handler(unsigned long data)
GEM_DEBUG_BUG_ON(buf[2 * head + 1] != port->context_id);
rq = port_unpack(port, &count);
+ GEM_TRACE("%s out[0]: ctx=%d.%d, seqno=%x\n",
+ engine->name,
+ rq->ctx->hw_id, count,
+ rq->global_seqno);
GEM_BUG_ON(count == 0);
if (--count == 0) {
GEM_BUG_ON(status & GEN8_CTX_STATUS_PREEMPTED);
--
2.15.0
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx
^ permalink raw reply related [flat|nested] 12+ messages in thread
* Re: [PATCH v2] drm/i915: Use trace_printk to provide a death rattle for GEM
2017-11-09 11:15 ` [PATCH v2] " Chris Wilson
@ 2017-11-09 11:53 ` Joonas Lahtinen
2017-11-09 11:58 ` Chris Wilson
0 siblings, 1 reply; 12+ messages in thread
From: Joonas Lahtinen @ 2017-11-09 11:53 UTC (permalink / raw)
To: Chris Wilson, intel-gfx
On Thu, 2017-11-09 at 11:15 +0000, Chris Wilson wrote:
> Trying to enable printk debugging for GEM is fraught with the issue of
> spam; interactions with HW are very frequent and often boring. However,
> one instance where they are not so boring is just before a BUG; here
> ftrace provides a facility to dump its ringbuffer on an oops. So for CI
> let's enable trace_printk() to capture the last exchanges with HW as a
> death rattle.
>
> For example,
> [ 72.120722] ------------[ cut here ]------------
> [ 72.120748] kernel BUG at drivers/gpu/drm/i915/intel_lrc.c:905!
> [ 72.120756] invalid opcode: 0000 [#1] SMP
> [ 72.120762] Dumping ftrace buffer:
> [ 72.120768] ---------------------------------
> ...
> [ 72.200424] gem_conc-1064 0..s1 71949306us : intel_lrc_irq_handler: bcs0 in: ctx=4.1, seqno=161
> [ 72.200469] gem_conc-1064 0..s1 71949312us : intel_lrc_irq_handler: bcs0 in: ctx=6.2, seqno=160
> [ 72.200512] gem_conc-1066 1..s1 71949325us : intel_lrc_irq_handler: bcs0 csb[4/4]: status=0x00008002
> [ 72.200555] gem_conc-1066 1..s1 71949326us : intel_lrc_irq_handler: bcs0 out: ctx=6, seqno=160
> [ 72.200601] gem_conc-1066 1..s. 71956923us : intel_lrc_irq_handler: bcs0 csb[5/5]: status=0x00000014
> [ 72.200646] gem_conc-1066 1..s. 71956928us : intel_lrc_irq_handler: bcs0 out: ctx=6, seqno=160
> [ 72.200690] gem_conc-1066 1..s. 71956939us : intel_lrc_irq_handler: bcs0 in: ctx=8.1, seqno=164
> [ 72.200736] gem_conc-1066 1..s. 71956940us : intel_lrc_irq_handler: bcs0 in: ctx=4.2, seqno=162
> [ 72.200780] gem_conc-1066 1..s. 71956951us : intel_lrc_irq_handler: bcs0 csb[0/0]: status=0x00008002
> [ 72.200824] gem_conc-1066 1..s. 71956951us : intel_lrc_irq_handler: bcs0 out: ctx=4, seqno=162
> [ 72.200867] <idle>-0 1..s1 71967999us : intel_lrc_irq_handler: bcs0 csb[1/1]: status=0x00000014
> [ 72.200912] <idle>-0 1..s1 71968001us : intel_lrc_irq_handler: bcs0 out: ctx=4, seqno=162
> [ 72.200956] <idle>-0 1.Ns1 71979385us : intel_lrc_irq_handler: bcs0 csb[2/2]: status=0x00000018
> [ 72.201001] <idle>-0 1.Ns1 71979388us : intel_lrc_irq_handler: bcs0 out: ctx=8, seqno=164
> [ 72.201044] gem_conc-1063 3..s1 72086825us : intel_lrc_irq_handler: bcs0 in: ctx=7.1, seqno=165
> [ 72.201088] gem_conc-1066 1..s. 72086918us : intel_lrc_irq_handler: bcs0 csb[3/3]: status=0x00000001
> [ 72.201132] gem_conc-1066 1..s. 72086932us : intel_lrc_irq_handler: bcs0 in: ctx=7.2, seqno=166
> [ 72.201176] gem_conc-1066 1..s. 72086941us : intel_lrc_irq_handler: bcs0 csb[4/4]: status=0x00008002
> [ 72.201219] gem_conc-1066 1..s. 72086941us : intel_lrc_irq_handler: bcs0 out: ctx=7, seqno=166
> [ 72.201263] gem_conc-1066 1..s. 72103855us : intel_lrc_irq_handler: bcs0 csb[5/5]: status=0x00000018
> [ 72.201307] gem_conc-1066 1..s. 72103858us : intel_lrc_irq_handler: bcs0 out: ctx=7, seqno=166
> [ 72.201351] gem_conc-1064 0..s1 72116924us : intel_lrc_irq_handler: bcs0 in: ctx=4.1, seqno=167
> [ 72.201394] gem_conc-1064 0..s1 72116981us : intel_lrc_irq_handler: bcs0 in: ctx=4.2, seqno=168
> [ 72.201438] gem_conc-1066 1..s1 72117545us : intel_lrc_irq_handler: bcs0 csb[0/2]: status=0x00000012
> [ 72.201482] gem_conc-1066 1..s1 72117547us : intel_lrc_irq_handler: bcs0 out: ctx=4, seqno=168
> [ 72.201526] gem_conc-1066 1..s1 72117548us : intel_lrc_irq_handler: bcs0 csb[1/2]: status=0x00008002
> [ 72.201570] gem_conc-1066 1..s1 72117548us : intel_lrc_irq_handler: bcs0 out: ctx=4, seqno=168
> [ 72.201578] ---------------------------------
You could update this example trace for v2, too.
>
> v2: Tweak the formatting to be more consistent between in/out.
>
> Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>
> Cc: Mika Kuoppala <mika.kuoppala@linux.intel.com>
> Cc: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
> Cc: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
<SNIP>
> +++ b/drivers/gpu/drm/i915/i915_gem.h
> @@ -44,6 +44,12 @@
> #define GEM_DEBUG_BUG_ON(expr)
> #endif
>
> +#if IS_ENABLED(CONFIG_DRM_I915_TRACE_GEM)
> +#define GEM_TRACE(...) trace_printk(__VA_ARGS__)
> +#else
> +#define GEM_TRACE(...)
I guess we want one of them "do { } while(false)" tricks here not to
cause mayhem when disabled.
> @@ -860,6 +867,9 @@ static void intel_lrc_irq_handler(unsigned long data)
> */
>
> status = READ_ONCE(buf[2 * head]); /* maybe mmio! */
> + GEM_TRACE("%s csb[%d/%d]: status=0x%08x:0x%08x\n",
csb[%d..%d] for better readability?
> @@ -887,6 +897,10 @@ static void intel_lrc_irq_handler(unsigned long data)
> GEM_DEBUG_BUG_ON(buf[2 * head + 1] != port->context_id);
>
> rq = port_unpack(port, &count);
> + GEM_TRACE("%s out[0]: ctx=%d.%d, seqno=%x\n",
> + engine->name,
> + rq->ctx->hw_id, count,
Make up your mind, in above GEM_TRACE count is on its own line.
Reviewed-by: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
Looks like this could be an useful feature. I'm kinda wondering if the
actual tracepoint could be useful too, and a way to turn the other
tracepoints to the log as future steps.
Regards, Joonas
--
Joonas Lahtinen
Open Source Technology Center
Intel Corporation
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [PATCH v2] drm/i915: Use trace_printk to provide a death rattle for GEM
2017-11-09 11:53 ` Joonas Lahtinen
@ 2017-11-09 11:58 ` Chris Wilson
0 siblings, 0 replies; 12+ messages in thread
From: Chris Wilson @ 2017-11-09 11:58 UTC (permalink / raw)
To: Joonas Lahtinen, intel-gfx
Quoting Joonas Lahtinen (2017-11-09 11:53:53)
> On Thu, 2017-11-09 at 11:15 +0000, Chris Wilson wrote:
> > Trying to enable printk debugging for GEM is fraught with the issue of
> > spam; interactions with HW are very frequent and often boring. However,
> > one instance where they are not so boring is just before a BUG; here
> > ftrace provides a facility to dump its ringbuffer on an oops. So for CI
> > let's enable trace_printk() to capture the last exchanges with HW as a
> > death rattle.
> >
> > For example,
> > [ 72.120722] ------------[ cut here ]------------
> > [ 72.120748] kernel BUG at drivers/gpu/drm/i915/intel_lrc.c:905!
> > [ 72.120756] invalid opcode: 0000 [#1] SMP
> > [ 72.120762] Dumping ftrace buffer:
> > [ 72.120768] ---------------------------------
> > ...
> > [ 72.200424] gem_conc-1064 0..s1 71949306us : intel_lrc_irq_handler: bcs0 in: ctx=4.1, seqno=161
> > [ 72.200469] gem_conc-1064 0..s1 71949312us : intel_lrc_irq_handler: bcs0 in: ctx=6.2, seqno=160
> > [ 72.200512] gem_conc-1066 1..s1 71949325us : intel_lrc_irq_handler: bcs0 csb[4/4]: status=0x00008002
> > [ 72.200555] gem_conc-1066 1..s1 71949326us : intel_lrc_irq_handler: bcs0 out: ctx=6, seqno=160
> > [ 72.200601] gem_conc-1066 1..s. 71956923us : intel_lrc_irq_handler: bcs0 csb[5/5]: status=0x00000014
> > [ 72.200646] gem_conc-1066 1..s. 71956928us : intel_lrc_irq_handler: bcs0 out: ctx=6, seqno=160
> > [ 72.200690] gem_conc-1066 1..s. 71956939us : intel_lrc_irq_handler: bcs0 in: ctx=8.1, seqno=164
> > [ 72.200736] gem_conc-1066 1..s. 71956940us : intel_lrc_irq_handler: bcs0 in: ctx=4.2, seqno=162
> > [ 72.200780] gem_conc-1066 1..s. 71956951us : intel_lrc_irq_handler: bcs0 csb[0/0]: status=0x00008002
> > [ 72.200824] gem_conc-1066 1..s. 71956951us : intel_lrc_irq_handler: bcs0 out: ctx=4, seqno=162
> > [ 72.200867] <idle>-0 1..s1 71967999us : intel_lrc_irq_handler: bcs0 csb[1/1]: status=0x00000014
> > [ 72.200912] <idle>-0 1..s1 71968001us : intel_lrc_irq_handler: bcs0 out: ctx=4, seqno=162
> > [ 72.200956] <idle>-0 1.Ns1 71979385us : intel_lrc_irq_handler: bcs0 csb[2/2]: status=0x00000018
> > [ 72.201001] <idle>-0 1.Ns1 71979388us : intel_lrc_irq_handler: bcs0 out: ctx=8, seqno=164
> > [ 72.201044] gem_conc-1063 3..s1 72086825us : intel_lrc_irq_handler: bcs0 in: ctx=7.1, seqno=165
> > [ 72.201088] gem_conc-1066 1..s. 72086918us : intel_lrc_irq_handler: bcs0 csb[3/3]: status=0x00000001
> > [ 72.201132] gem_conc-1066 1..s. 72086932us : intel_lrc_irq_handler: bcs0 in: ctx=7.2, seqno=166
> > [ 72.201176] gem_conc-1066 1..s. 72086941us : intel_lrc_irq_handler: bcs0 csb[4/4]: status=0x00008002
> > [ 72.201219] gem_conc-1066 1..s. 72086941us : intel_lrc_irq_handler: bcs0 out: ctx=7, seqno=166
> > [ 72.201263] gem_conc-1066 1..s. 72103855us : intel_lrc_irq_handler: bcs0 csb[5/5]: status=0x00000018
> > [ 72.201307] gem_conc-1066 1..s. 72103858us : intel_lrc_irq_handler: bcs0 out: ctx=7, seqno=166
> > [ 72.201351] gem_conc-1064 0..s1 72116924us : intel_lrc_irq_handler: bcs0 in: ctx=4.1, seqno=167
> > [ 72.201394] gem_conc-1064 0..s1 72116981us : intel_lrc_irq_handler: bcs0 in: ctx=4.2, seqno=168
> > [ 72.201438] gem_conc-1066 1..s1 72117545us : intel_lrc_irq_handler: bcs0 csb[0/2]: status=0x00000012
> > [ 72.201482] gem_conc-1066 1..s1 72117547us : intel_lrc_irq_handler: bcs0 out: ctx=4, seqno=168
> > [ 72.201526] gem_conc-1066 1..s1 72117548us : intel_lrc_irq_handler: bcs0 csb[1/2]: status=0x00008002
> > [ 72.201570] gem_conc-1066 1..s1 72117548us : intel_lrc_irq_handler: bcs0 out: ctx=4, seqno=168
> > [ 72.201578] ---------------------------------
>
> You could update this example trace for v2, too.
>
> >
> > v2: Tweak the formatting to be more consistent between in/out.
> >
> > Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>
> > Cc: Mika Kuoppala <mika.kuoppala@linux.intel.com>
> > Cc: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
> > Cc: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>
> <SNIP>
>
> > +++ b/drivers/gpu/drm/i915/i915_gem.h
> > @@ -44,6 +44,12 @@
> > #define GEM_DEBUG_BUG_ON(expr)
> > #endif
> >
> > +#if IS_ENABLED(CONFIG_DRM_I915_TRACE_GEM)
> > +#define GEM_TRACE(...) trace_printk(__VA_ARGS__)
> > +#else
> > +#define GEM_TRACE(...)
>
> I guess we want one of them "do { } while(false)" tricks here not to
> cause mayhem when disabled.
Ok.
> > @@ -860,6 +867,9 @@ static void intel_lrc_irq_handler(unsigned long data)
> > */
> >
> > status = READ_ONCE(buf[2 * head]); /* maybe mmio! */
> > + GEM_TRACE("%s csb[%d/%d]: status=0x%08x:0x%08x\n",
>
> csb[%d..%d] for better readability?
Nah, it's not a range either. I guess we document head/tail at the start
of the loop, we can include mmio vs hswp readout.
> > @@ -887,6 +897,10 @@ static void intel_lrc_irq_handler(unsigned long data)
> > GEM_DEBUG_BUG_ON(buf[2 * head + 1] != port->context_id);
> >
> > rq = port_unpack(port, &count);
> > + GEM_TRACE("%s out[0]: ctx=%d.%d, seqno=%x\n",
> > + engine->name,
> > + rq->ctx->hw_id, count,
>
> Make up your mind, in above GEM_TRACE count is on its own line.
Consistency, moi? Numquam!
-Chris
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx
^ permalink raw reply [flat|nested] 12+ messages in thread
* ✓ Fi.CI.BAT: success for drm/i915: Use trace_printk to provide a death rattle for GEM (rev2)
2017-11-08 12:20 [PATCH] drm/i915: Use trace_printk to provide a death rattle for GEM Chris Wilson
` (2 preceding siblings ...)
2017-11-09 11:15 ` [PATCH v2] " Chris Wilson
@ 2017-11-09 12:19 ` Patchwork
2017-11-09 14:23 ` ✗ Fi.CI.IGT: failure " Patchwork
` (2 subsequent siblings)
6 siblings, 0 replies; 12+ messages in thread
From: Patchwork @ 2017-11-09 12:19 UTC (permalink / raw)
To: Chris Wilson; +Cc: intel-gfx
== Series Details ==
Series: drm/i915: Use trace_printk to provide a death rattle for GEM (rev2)
URL : https://patchwork.freedesktop.org/series/33421/
State : success
== Summary ==
Series 33421v2 drm/i915: Use trace_printk to provide a death rattle for GEM
https://patchwork.freedesktop.org/api/1.0/series/33421/revisions/2/mbox/
Test gem_exec_reloc:
Subgroup basic-gtt-active:
fail -> PASS (fi-gdg-551) fdo#102582 +2
fdo#102582 https://bugs.freedesktop.org/show_bug.cgi?id=102582
fi-bdw-5557u total:289 pass:268 dwarn:0 dfail:0 fail:0 skip:21 time:444s
fi-bdw-gvtdvm total:289 pass:265 dwarn:0 dfail:0 fail:0 skip:24 time:455s
fi-blb-e6850 total:289 pass:223 dwarn:1 dfail:0 fail:0 skip:65 time:380s
fi-bsw-n3050 total:289 pass:243 dwarn:0 dfail:0 fail:0 skip:46 time:536s
fi-bwr-2160 total:289 pass:183 dwarn:0 dfail:0 fail:0 skip:106 time:275s
fi-bxt-dsi total:289 pass:259 dwarn:0 dfail:0 fail:0 skip:30 time:499s
fi-bxt-j4205 total:289 pass:260 dwarn:0 dfail:0 fail:0 skip:29 time:503s
fi-byt-j1900 total:289 pass:254 dwarn:0 dfail:0 fail:0 skip:35 time:496s
fi-byt-n2820 total:289 pass:250 dwarn:0 dfail:0 fail:0 skip:39 time:486s
fi-elk-e7500 total:289 pass:229 dwarn:0 dfail:0 fail:0 skip:60 time:433s
fi-gdg-551 total:289 pass:178 dwarn:1 dfail:0 fail:1 skip:109 time:264s
fi-glk-1 total:289 pass:261 dwarn:0 dfail:0 fail:0 skip:28 time:540s
fi-hsw-4770 total:289 pass:262 dwarn:0 dfail:0 fail:0 skip:27 time:433s
fi-hsw-4770r total:289 pass:262 dwarn:0 dfail:0 fail:0 skip:27 time:441s
fi-ilk-650 total:289 pass:228 dwarn:0 dfail:0 fail:0 skip:61 time:422s
fi-ivb-3520m total:289 pass:260 dwarn:0 dfail:0 fail:0 skip:29 time:472s
fi-ivb-3770 total:289 pass:260 dwarn:0 dfail:0 fail:0 skip:29 time:461s
fi-kbl-7500u total:289 pass:264 dwarn:1 dfail:0 fail:0 skip:24 time:483s
fi-kbl-7560u total:289 pass:270 dwarn:0 dfail:0 fail:0 skip:19 time:519s
fi-kbl-7567u total:289 pass:269 dwarn:0 dfail:0 fail:0 skip:20 time:480s
fi-kbl-r total:289 pass:262 dwarn:0 dfail:0 fail:0 skip:27 time:536s
fi-pnv-d510 total:289 pass:222 dwarn:1 dfail:0 fail:0 skip:66 time:579s
fi-skl-6260u total:289 pass:269 dwarn:0 dfail:0 fail:0 skip:20 time:459s
fi-skl-6600u total:289 pass:262 dwarn:0 dfail:0 fail:0 skip:27 time:548s
fi-skl-6700hq total:289 pass:263 dwarn:0 dfail:0 fail:0 skip:26 time:562s
fi-skl-6700k total:289 pass:265 dwarn:0 dfail:0 fail:0 skip:24 time:515s
fi-skl-6770hq total:289 pass:269 dwarn:0 dfail:0 fail:0 skip:20 time:496s
fi-skl-gvtdvm total:289 pass:266 dwarn:0 dfail:0 fail:0 skip:23 time:459s
fi-snb-2520m total:289 pass:250 dwarn:0 dfail:0 fail:0 skip:39 time:556s
fi-snb-2600 total:289 pass:249 dwarn:0 dfail:0 fail:0 skip:40 time:421s
Blacklisted hosts:
fi-cnl-y total:289 pass:262 dwarn:0 dfail:0 fail:0 skip:27 time:559s
fi-glk-dsi total:289 pass:259 dwarn:0 dfail:0 fail:0 skip:30 time:487s
65dc54b704d3ee0486f9f5b11f00c28973f783a2 drm-tip: 2017y-11m-09d-08h-53m-46s UTC integration manifest
a370c2523da8 drm/i915: Use trace_printk to provide a death rattle for GEM
== Logs ==
For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/Patchwork_7035/
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx
^ permalink raw reply [flat|nested] 12+ messages in thread
* ✗ Fi.CI.IGT: failure for drm/i915: Use trace_printk to provide a death rattle for GEM (rev2)
2017-11-08 12:20 [PATCH] drm/i915: Use trace_printk to provide a death rattle for GEM Chris Wilson
` (3 preceding siblings ...)
2017-11-09 12:19 ` ✓ Fi.CI.BAT: success for drm/i915: Use trace_printk to provide a death rattle for GEM (rev2) Patchwork
@ 2017-11-09 14:23 ` Patchwork
2017-11-09 14:30 ` [PATCH v3] drm/i915: Use trace_printk to provide a death rattle for GEM Chris Wilson
2017-11-09 15:06 ` ✗ Fi.CI.BAT: warning for drm/i915: Use trace_printk to provide a death rattle for GEM (rev3) Patchwork
6 siblings, 0 replies; 12+ messages in thread
From: Patchwork @ 2017-11-09 14:23 UTC (permalink / raw)
To: Chris Wilson; +Cc: intel-gfx
== Series Details ==
Series: drm/i915: Use trace_printk to provide a death rattle for GEM (rev2)
URL : https://patchwork.freedesktop.org/series/33421/
State : failure
== Summary ==
Test perf:
Subgroup blocking:
fail -> PASS (shard-hsw) fdo#102252
Test kms_frontbuffer_tracking:
Subgroup fbc-1p-primscrn-pri-indfb-draw-blt:
pass -> FAIL (shard-hsw)
Test kms_flip:
Subgroup rcs-wf_vblank-vs-modeset-interruptible:
pass -> DMESG-WARN (shard-hsw) fdo#102614
Test kms_vblank:
Subgroup accuracy-idle:
pass -> FAIL (shard-hsw) fdo#102583
fdo#102252 https://bugs.freedesktop.org/show_bug.cgi?id=102252
fdo#102614 https://bugs.freedesktop.org/show_bug.cgi?id=102614
fdo#102583 https://bugs.freedesktop.org/show_bug.cgi?id=102583
shard-hsw total:2540 pass:1430 dwarn:1 dfail:0 fail:12 skip:1097 time:9286s
== Logs ==
For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/Patchwork_7035/shards.html
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx
^ permalink raw reply [flat|nested] 12+ messages in thread
* [PATCH v3] drm/i915: Use trace_printk to provide a death rattle for GEM
2017-11-08 12:20 [PATCH] drm/i915: Use trace_printk to provide a death rattle for GEM Chris Wilson
` (4 preceding siblings ...)
2017-11-09 14:23 ` ✗ Fi.CI.IGT: failure " Patchwork
@ 2017-11-09 14:30 ` Chris Wilson
2017-11-09 14:32 ` Chris Wilson
2017-11-09 15:03 ` Chris Wilson
2017-11-09 15:06 ` ✗ Fi.CI.BAT: warning for drm/i915: Use trace_printk to provide a death rattle for GEM (rev3) Patchwork
6 siblings, 2 replies; 12+ messages in thread
From: Chris Wilson @ 2017-11-09 14:30 UTC (permalink / raw)
To: intel-gfx
Trying to enable printk debugging for GEM is fraught with the issue of
spam; interactions with HW are very frequent and often boring. However,
one instance where they are not so boring is just before a BUG; here
ftrace provides a facility to dump its ringbuffer on an oops. So for CI
let's enable trace_printk() to capture the last exchanges with HW as a
death rattle.
For example,
[ 79.234110] ------------[ cut here ]------------
[ 79.234137] kernel BUG at drivers/gpu/drm/i915/intel_lrc.c:907!
[ 79.234145] invalid opcode: 0000 [#1] SMP
[ 79.234153] Dumping ftrace buffer:
[ 79.234158] ---------------------------------
...
[ 79.314044] gem_conc-1059 1..s1 79203443us : intel_lrc_irq_handler: bcs0 out[0]: ctx=5.2, seqno=145
[ 79.314089] gem_conc-1059 1..s. 79220800us : intel_lrc_irq_handler: bcs0 csb[1/1]: status=0x00000018:0x00000005
[ 79.314133] gem_conc-1059 1..s. 79220803us : intel_lrc_irq_handler: bcs0 out[0]: ctx=5.1, seqno=145
[ 79.314177] gem_conc-1062 2..s1 79230458us : intel_lrc_irq_handler: bcs0 in[0]: ctx=8.1, seqno=146
[ 79.314220] gem_conc-1062 2..s1 79230515us : intel_lrc_irq_handler: bcs0 in[0]: ctx=8.2, seqno=147
[ 79.314265] gem_conc-1059 1..s1 79230951us : intel_lrc_irq_handler: bcs0 csb[2/3]: status=0x00000012:0x00000008
[ 79.314309] gem_conc-1059 1..s1 79230954us : intel_lrc_irq_handler: bcs0 out[0]: ctx=8.2, seqno=147
[ 79.314353] gem_conc-1059 1..s1 79230954us : intel_lrc_irq_handler: bcs0 csb[3/3]: status=0x00008002:0x00000008
[ 79.314396] gem_conc-1059 1..s1 79230955us : intel_lrc_irq_handler: bcs0 out[0]: ctx=8.1, seqno=147
[ 79.314402] ---------------------------------
v2: Tweak the formatting to be more consistent between in/out.
v3: do {} while (0) stub macro protection
Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>
Cc: Mika Kuoppala <mika.kuoppala@linux.intel.com>
Cc: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
Cc: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
Reviewed-by: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
---
drivers/gpu/drm/i915/Kconfig.debug | 14 ++++++++++++++
drivers/gpu/drm/i915/i915_gem.h | 6 ++++++
drivers/gpu/drm/i915/intel_lrc.c | 17 +++++++++++++++++
3 files changed, 37 insertions(+)
diff --git a/drivers/gpu/drm/i915/Kconfig.debug b/drivers/gpu/drm/i915/Kconfig.debug
index 19c77c6feb24..9e53edbc713b 100644
--- a/drivers/gpu/drm/i915/Kconfig.debug
+++ b/drivers/gpu/drm/i915/Kconfig.debug
@@ -28,6 +28,7 @@ config DRM_I915_DEBUG
select SW_SYNC # signaling validation framework (igt/syncobj*)
select DRM_I915_SW_FENCE_DEBUG_OBJECTS
select DRM_I915_SELFTEST
+ select DRM_I915_TRACE_GEM
default n
help
Choose this option to turn on extra driver debugging that may affect
@@ -49,6 +50,19 @@ config DRM_I915_DEBUG_GEM
If in doubt, say "N".
+config DRM_I915_TRACE_GEM
+ bool "Insert extra ftrace output from the GEM internals"
+ select TRACING
+ default n
+ help
+ Enable additional and verbose debugging output that will spam
+ ordinary tests, but may be vital for post-mortem debugging when
+ used with /proc/sys/kernel/ftrace_dump_on_oops
+
+ Recommended for driver developers only.
+
+ If in doubt, say "N".
+
config DRM_I915_SW_FENCE_DEBUG_OBJECTS
bool "Enable additional driver debugging for fence objects"
depends on DRM_I915
diff --git a/drivers/gpu/drm/i915/i915_gem.h b/drivers/gpu/drm/i915/i915_gem.h
index ee54597465b6..ff42b5f0e981 100644
--- a/drivers/gpu/drm/i915/i915_gem.h
+++ b/drivers/gpu/drm/i915/i915_gem.h
@@ -44,6 +44,12 @@
#define GEM_DEBUG_BUG_ON(expr)
#endif
+#if IS_ENABLED(CONFIG_DRM_I915_TRACE_GEM)
+#define GEM_TRACE(...) trace_printk(__VA_ARGS__)
+#else
+#define GEM_TRACE(...) do { } while (0)
+#endif
+
#define I915_NUM_ENGINES 5
#endif /* __I915_GEM_H__ */
diff --git a/drivers/gpu/drm/i915/intel_lrc.c b/drivers/gpu/drm/i915/intel_lrc.c
index 6840ec8db037..020ca7c9c75f 100644
--- a/drivers/gpu/drm/i915/intel_lrc.c
+++ b/drivers/gpu/drm/i915/intel_lrc.c
@@ -466,6 +466,11 @@ static void execlists_submit_ports(struct intel_engine_cs *engine)
port_set(&port[n], port_pack(rq, count));
desc = execlists_update_context(rq);
GEM_DEBUG_EXEC(port[n].context_id = upper_32_bits(desc));
+
+ GEM_TRACE("%s in[%d]: ctx=%d.%d, seqno=%x\n",
+ engine->name, n,
+ rq->ctx->hw_id, count,
+ rq->global_seqno);
} else {
GEM_BUG_ON(!n);
desc = 0;
@@ -520,6 +525,7 @@ static void inject_preempt_context(struct intel_engine_cs *engine)
ce->ring->tail &= (ce->ring->size - 1);
ce->lrc_reg_state[CTX_RING_TAIL+1] = ce->ring->tail;
+ GEM_TRACE("\n");
for (n = execlists_num_ports(&engine->execlists); --n; )
elsp_write(0, elsp);
@@ -832,6 +838,10 @@ static void intel_lrc_irq_handler(unsigned long data)
head = execlists->csb_head;
tail = READ_ONCE(buf[write_idx]);
}
+ GEM_TRACE("%s cs-irq head=%d [%d], tail=%d [%d]\n",
+ engine->name,
+ head, GEN8_CSB_READ_PTR(readl(dev_priv->regs + i915_mmio_reg_offset(RING_CONTEXT_STATUS_PTR(engine)))),
+ tail, GEN8_CSB_WRITE_PTR(readl(dev_priv->regs + i915_mmio_reg_offset(RING_CONTEXT_STATUS_PTR(engine)))));
while (head != tail) {
struct drm_i915_gem_request *rq;
@@ -859,6 +869,9 @@ static void intel_lrc_irq_handler(unsigned long data)
*/
status = READ_ONCE(buf[2 * head]); /* maybe mmio! */
+ GEM_TRACE("%s csb[%dd]: status=0x%08x:0x%08x\n",
+ engine->name, head,
+ status, buf[2*head + 1]);
if (!(status & GEN8_CTX_STATUS_COMPLETED_MASK))
continue;
@@ -886,6 +899,10 @@ static void intel_lrc_irq_handler(unsigned long data)
GEM_DEBUG_BUG_ON(buf[2 * head + 1] != port->context_id);
rq = port_unpack(port, &count);
+ GEM_TRACE("%s out[0]: ctx=%d.%d, seqno=%x\n",
+ engine->name,
+ rq->ctx->hw_id, count,
+ rq->global_seqno);
GEM_BUG_ON(count == 0);
if (--count == 0) {
GEM_BUG_ON(status & GEN8_CTX_STATUS_PREEMPTED);
--
2.15.0
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx
^ permalink raw reply related [flat|nested] 12+ messages in thread
* Re: [PATCH v3] drm/i915: Use trace_printk to provide a death rattle for GEM
2017-11-09 14:30 ` [PATCH v3] drm/i915: Use trace_printk to provide a death rattle for GEM Chris Wilson
@ 2017-11-09 14:32 ` Chris Wilson
2017-11-09 15:03 ` Chris Wilson
1 sibling, 0 replies; 12+ messages in thread
From: Chris Wilson @ 2017-11-09 14:32 UTC (permalink / raw)
To: intel-gfx
Quoting Chris Wilson (2017-11-09 14:30:19)
> Trying to enable printk debugging for GEM is fraught with the issue of
> spam; interactions with HW are very frequent and often boring. However,
> one instance where they are not so boring is just before a BUG; here
> ftrace provides a facility to dump its ringbuffer on an oops. So for CI
> let's enable trace_printk() to capture the last exchanges with HW as a
> death rattle.
>
> For example,
> [ 79.234110] ------------[ cut here ]------------
> [ 79.234137] kernel BUG at drivers/gpu/drm/i915/intel_lrc.c:907!
> [ 79.234145] invalid opcode: 0000 [#1] SMP
> [ 79.234153] Dumping ftrace buffer:
> [ 79.234158] ---------------------------------
> ...
> [ 79.314044] gem_conc-1059 1..s1 79203443us : intel_lrc_irq_handler: bcs0 out[0]: ctx=5.2, seqno=145
> [ 79.314089] gem_conc-1059 1..s. 79220800us : intel_lrc_irq_handler: bcs0 csb[1/1]: status=0x00000018:0x00000005
> [ 79.314133] gem_conc-1059 1..s. 79220803us : intel_lrc_irq_handler: bcs0 out[0]: ctx=5.1, seqno=145
> [ 79.314177] gem_conc-1062 2..s1 79230458us : intel_lrc_irq_handler: bcs0 in[0]: ctx=8.1, seqno=146
> [ 79.314220] gem_conc-1062 2..s1 79230515us : intel_lrc_irq_handler: bcs0 in[0]: ctx=8.2, seqno=147
> [ 79.314265] gem_conc-1059 1..s1 79230951us : intel_lrc_irq_handler: bcs0 csb[2/3]: status=0x00000012:0x00000008
> [ 79.314309] gem_conc-1059 1..s1 79230954us : intel_lrc_irq_handler: bcs0 out[0]: ctx=8.2, seqno=147
> [ 79.314353] gem_conc-1059 1..s1 79230954us : intel_lrc_irq_handler: bcs0 csb[3/3]: status=0x00008002:0x00000008
> [ 79.314396] gem_conc-1059 1..s1 79230955us : intel_lrc_irq_handler: bcs0 out[0]: ctx=8.1, seqno=147
> [ 79.314402] ---------------------------------
>
> v2: Tweak the formatting to be more consistent between in/out.
> v3: do {} while (0) stub macro protection
I should include a
Suggested-by: Michał Winiarski <michal.winiarski@intel.com>
as the idea that we can use trace_printk for oops debugging came from him.
-Chris
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [PATCH v3] drm/i915: Use trace_printk to provide a death rattle for GEM
2017-11-09 14:30 ` [PATCH v3] drm/i915: Use trace_printk to provide a death rattle for GEM Chris Wilson
2017-11-09 14:32 ` Chris Wilson
@ 2017-11-09 15:03 ` Chris Wilson
1 sibling, 0 replies; 12+ messages in thread
From: Chris Wilson @ 2017-11-09 15:03 UTC (permalink / raw)
To: intel-gfx
Quoting Chris Wilson (2017-11-09 14:30:19)
> Trying to enable printk debugging for GEM is fraught with the issue of
> spam; interactions with HW are very frequent and often boring. However,
> one instance where they are not so boring is just before a BUG; here
> ftrace provides a facility to dump its ringbuffer on an oops. So for CI
> let's enable trace_printk() to capture the last exchanges with HW as a
> death rattle.
Something worth mentioning is that using trace_printk, generates
[ 5.112689] **********************************************************
[ 5.112693] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE **
[ 5.112698] ** **
[ 5.112701] ** trace_printk() being used. Allocating extra memory. **
[ 5.112705] ** **
[ 5.112709] ** This means that this is a DEBUG kernel and it is **
[ 5.112713] ** unsafe for production use. **
[ 5.112716] ** **
[ 5.112720] ** If you see this message and you are not debugging **
[ 5.112724] ** the kernel, report this immediately to your vendor! **
[ 5.112728] ** **
[ 5.112732] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE **
[ 5.112735] **********************************************************
Hiding it behind a CI Kconfig option is essential.
-Chris
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx
^ permalink raw reply [flat|nested] 12+ messages in thread
* ✗ Fi.CI.BAT: warning for drm/i915: Use trace_printk to provide a death rattle for GEM (rev3)
2017-11-08 12:20 [PATCH] drm/i915: Use trace_printk to provide a death rattle for GEM Chris Wilson
` (5 preceding siblings ...)
2017-11-09 14:30 ` [PATCH v3] drm/i915: Use trace_printk to provide a death rattle for GEM Chris Wilson
@ 2017-11-09 15:06 ` Patchwork
6 siblings, 0 replies; 12+ messages in thread
From: Patchwork @ 2017-11-09 15:06 UTC (permalink / raw)
To: Chris Wilson; +Cc: intel-gfx
== Series Details ==
Series: drm/i915: Use trace_printk to provide a death rattle for GEM (rev3)
URL : https://patchwork.freedesktop.org/series/33421/
State : warning
== Summary ==
Series 33421v3 drm/i915: Use trace_printk to provide a death rattle for GEM
https://patchwork.freedesktop.org/api/1.0/series/33421/revisions/3/mbox/
Test chamelium:
Subgroup dp-crc-fast:
pass -> FAIL (fi-kbl-7500u) fdo#102514
Test gem_sync:
Subgroup basic-store-all:
fail -> PASS (fi-ivb-3520m) fdo#100007
Test drv_module_reload:
Subgroup basic-reload-inject:
pass -> DMESG-WARN (fi-bsw-n3050)
fdo#102514 https://bugs.freedesktop.org/show_bug.cgi?id=102514
fdo#100007 https://bugs.freedesktop.org/show_bug.cgi?id=100007
fi-bdw-5557u total:289 pass:268 dwarn:0 dfail:0 fail:0 skip:21 time:443s
fi-blb-e6850 total:289 pass:223 dwarn:1 dfail:0 fail:0 skip:65 time:381s
fi-bsw-n3050 total:289 pass:242 dwarn:1 dfail:0 fail:0 skip:46 time:546s
fi-bwr-2160 total:289 pass:183 dwarn:0 dfail:0 fail:0 skip:106 time:273s
fi-bxt-dsi total:289 pass:259 dwarn:0 dfail:0 fail:0 skip:30 time:502s
fi-bxt-j4205 total:289 pass:260 dwarn:0 dfail:0 fail:0 skip:29 time:505s
fi-byt-j1900 total:289 pass:254 dwarn:0 dfail:0 fail:0 skip:35 time:497s
fi-byt-n2820 total:289 pass:250 dwarn:0 dfail:0 fail:0 skip:39 time:492s
fi-elk-e7500 total:289 pass:229 dwarn:0 dfail:0 fail:0 skip:60 time:431s
fi-gdg-551 total:289 pass:178 dwarn:1 dfail:0 fail:1 skip:109 time:261s
fi-glk-1 total:289 pass:261 dwarn:0 dfail:0 fail:0 skip:28 time:541s
fi-hsw-4770 total:289 pass:262 dwarn:0 dfail:0 fail:0 skip:27 time:424s
fi-hsw-4770r total:289 pass:262 dwarn:0 dfail:0 fail:0 skip:27 time:443s
fi-ilk-650 total:289 pass:228 dwarn:0 dfail:0 fail:0 skip:61 time:425s
fi-ivb-3520m total:289 pass:260 dwarn:0 dfail:0 fail:0 skip:29 time:484s
fi-ivb-3770 total:289 pass:260 dwarn:0 dfail:0 fail:0 skip:29 time:468s
fi-kbl-7500u total:289 pass:263 dwarn:1 dfail:0 fail:1 skip:24 time:475s
fi-kbl-7560u total:289 pass:270 dwarn:0 dfail:0 fail:0 skip:19 time:527s
fi-kbl-7567u total:289 pass:269 dwarn:0 dfail:0 fail:0 skip:20 time:482s
fi-kbl-r total:289 pass:262 dwarn:0 dfail:0 fail:0 skip:27 time:532s
fi-pnv-d510 total:289 pass:222 dwarn:1 dfail:0 fail:0 skip:66 time:572s
fi-skl-6260u total:289 pass:269 dwarn:0 dfail:0 fail:0 skip:20 time:461s
fi-skl-6600u total:289 pass:262 dwarn:0 dfail:0 fail:0 skip:27 time:544s
fi-skl-6700hq total:289 pass:263 dwarn:0 dfail:0 fail:0 skip:26 time:568s
fi-skl-6700k total:289 pass:265 dwarn:0 dfail:0 fail:0 skip:24 time:519s
fi-skl-6770hq total:289 pass:269 dwarn:0 dfail:0 fail:0 skip:20 time:502s
fi-skl-gvtdvm total:289 pass:266 dwarn:0 dfail:0 fail:0 skip:23 time:463s
fi-snb-2520m total:289 pass:250 dwarn:0 dfail:0 fail:0 skip:39 time:556s
fi-snb-2600 total:289 pass:249 dwarn:0 dfail:0 fail:0 skip:40 time:418s
Blacklisted hosts:
fi-cfl-s total:288 pass:254 dwarn:2 dfail:0 fail:0 skip:31
fi-cnl-y total:212 pass:191 dwarn:0 dfail:0 fail:0 skip:20
fi-glk-dsi total:289 pass:259 dwarn:0 dfail:0 fail:0 skip:30 time:492s
fi-bdw-gvtdvm failed to connect after reboot
65dc54b704d3ee0486f9f5b11f00c28973f783a2 drm-tip: 2017y-11m-09d-08h-53m-46s UTC integration manifest
058392a74f2d drm/i915: Use trace_printk to provide a death rattle for GEM
== Logs ==
For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/Patchwork_7039/
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx
^ permalink raw reply [flat|nested] 12+ messages in thread
end of thread, other threads:[~2017-11-09 15:06 UTC | newest]
Thread overview: 12+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-11-08 12:20 [PATCH] drm/i915: Use trace_printk to provide a death rattle for GEM Chris Wilson
2017-11-08 14:57 ` ✓ Fi.CI.BAT: success for " Patchwork
2017-11-08 15:40 ` ✗ Fi.CI.IGT: warning " Patchwork
2017-11-09 11:15 ` [PATCH v2] " Chris Wilson
2017-11-09 11:53 ` Joonas Lahtinen
2017-11-09 11:58 ` Chris Wilson
2017-11-09 12:19 ` ✓ Fi.CI.BAT: success for drm/i915: Use trace_printk to provide a death rattle for GEM (rev2) Patchwork
2017-11-09 14:23 ` ✗ Fi.CI.IGT: failure " Patchwork
2017-11-09 14:30 ` [PATCH v3] drm/i915: Use trace_printk to provide a death rattle for GEM Chris Wilson
2017-11-09 14:32 ` Chris Wilson
2017-11-09 15:03 ` Chris Wilson
2017-11-09 15:06 ` ✗ Fi.CI.BAT: warning for drm/i915: Use trace_printk to provide a death rattle for GEM (rev3) Patchwork
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.