* [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 a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox