drm/i915/execlists: Consistent seqno reporting in GEM_TRACE
Subsystems (2)
Tvrtko Ursulin
maintainerPATCH 1/1 drm/i915/execlists: Consistent seqno reporting in GEM_TRACE
From: Tvrtko Ursulin <[email protected]>
Some messages are using %d and some %x which creates confusion while reading the traces.
I also added:
1. Fence context/seqno to elsp traces - so it is easier to correlate events.
2. New GEM_TRACE logging to port and request cancellation sites.
---
Crystal ball says I'll be removing everything other than the seqno format consolidation in v2. :)
--- drivers/gpu/drm/i915/intel_lrc.c | 27 ++++++++++++++++++++++----- 1 file changed, 22 insertions(+), 5 deletions(-)
drivers/gpu/drm/i915/intel_lrc.c +22 -5
@@ -454,10 +454,12 @@ static void execlists_submit_ports(struct intel_engine_cs *engine) 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, prio=%d\n" , +GEM_TRACE ("%s in[%d]: ctx=%d.%d, seqno=%d (fence %llx:%d), prio=%d\n" , engine->name, n, port[n].context_id, count, rq->global_seqno, + rq->fence.context, + rq->fence.seqno,rq_prio (rq)); }else {GEM_BUG_ON (!n);
@@ -727,6 +729,10 @@ execlists_cancel_port_requests(struct intel_engine_execlists * const execlists)while (num_ports-- &&port_isset (port)) {struct i915_request *rq =port_request (port); +GEM_TRACE ("%s:port%lu cancel %llx:%d [global %d]\n" , + rq->engine->name, port - execlists->port, + rq->fence.context, rq->fence.seqno, rq->global_seqno); +GEM_BUG_ON (!execlists->active);intel_engine_context_out (rq->engine);
@@ -802,7 +808,8 @@ static void execlists_cancel_requests(struct intel_engine_cs *engine)struct rb_node *rb;unsigned long flags; -GEM_TRACE ("%s\n" , engine->name); +GEM_TRACE ("%s, hws global %d\n" , + engine->name,intel_engine_get_seqno (engine));/* * Before we call engine->cancel_requests(), we should have exclusive
@@ -829,8 +836,12 @@ static void execlists_cancel_requests(struct intel_engine_cs *engine)/* Mark all executing requests as skipped. */ list_for_each_entry (rq, &engine->timeline->requests, link) {GEM_BUG_ON (!rq->global_seqno); -if (!i915_request_completed (rq)) +if (!i915_request_completed (rq)) { +GEM_TRACE ("%s eio %llx:%d [global %d]\n" , + rq->engine->name, rq->fence.context, + rq->fence.seqno, rq->global_seqno);dma_fence_set_error (&rq->fence, -EIO ); + } }/* Flush the queued requests to the timeline list (for retiring). */
@@ -839,6 +850,10 @@ static void execlists_cancel_requests(struct intel_engine_cs *engine)struct i915_priolist *p =to_priolist (rb);list_for_each_entry_safe (rq, rn, &p->requests, priotree.link) { +GEM_TRACE ("%s submit-eio %llx:%d [global %d]\n" , + rq->engine->name, rq->fence.context, + rq->fence.seqno, rq->global_seqno); +INIT_LIST_HEAD (&rq->priotree.link);dma_fence_set_error (&rq->fence, -EIO );
@@ -999,10 +1014,12 @@ static void execlists_submission_tasklet(unsigned long data) EXECLISTS_ACTIVE_USER)); rq =port_unpack (port, &count); -GEM_TRACE ("%s out[0]: ctx=%d.%d, seqno=%x, prio=%d\n" , +GEM_TRACE ("%s out[0]: ctx=%d.%d, seqno=%d (fence %llx:%d), prio=%d\n" , engine->name, port->context_id, count, rq ? rq->global_seqno :0 , + rq ? rq->fence.context :0 , + rq ? rq->fence.seqno :0 , rq ?rq_prio (rq) :0 );/* Check the context/desc id for this event matches */
@@ -1706,7 +1723,7 @@ static void reset_common_ring(struct intel_engine_cs *engine,struct intel_context *ce;unsigned long flags; -GEM_TRACE ("%s seqno=%x\n" , +GEM_TRACE ("%s seqno=%d\n" , engine->name, request ? request->global_seqno :0 );/* See execlists_cancel_requests() for the irq/spinlock split. */
Signature · 6 lines
2.14.1 _______________________________________________ Intel-gfx mailing list [email protected] https://lists.freedesktop.org/mailman/listinfo/intel-gfx
Quoting Tvrtko Ursulin (2018-03-28 18:39:59)
Quoted 50 lines
From: Tvrtko Ursulin <[email protected]>
Some messages are using %d and some %x which creates confusion while reading the traces.
I also added:
1. Fence context/seqno to elsp traces - so it is easier to correlate events.
2. New
GEM_TRACElogging to port and request cancellation sites.Signed-off-by Tvrtko Ursulin <[email protected]>---
Crystal ball says I'll be removing everything other than the seqno format consolidation in v2. :)--- drivers/gpu/drm/i915/intel_lrc.c | 27 ++++++++++++++++++++++----- 1 file changed, 22 insertions(+), 5 deletions(-)drivers/gpu/drm/i915/intel_lrc.c +7
-1@@ -454,10 +454,12 @@ static void execlists_submit_ports(struct intel_engine_cs *engine) 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, prio=%d\n" , +GEM_TRACE ("%s in[%d]: ctx=%d.%d, seqno=%d (fence %llx:%d), prio=%d\n" , engine->name, n, port[n].context_id, count, rq->global_seqno, + rq->fence.context, + rq->fence.seqno,rq_prio (rq)); }else {GEM_BUG_ON (!n);@@ -727,6 +729,10 @@ execlists_cancel_port_requests(struct intel_engine_execlists * const execlists)while (num_ports-- &&port_isset (port)) {struct i915_request *rq =port_request (port); +GEM_TRACE ("%s:port%lu cancel %llx:%d [global %d]\n" , + rq->engine->name, port - execlists->port, + rq->fence.context, rq->fence.seqno, rq->global_seqno); +GEM_BUG_ON (!execlists->active);intel_engine_context_out (rq->engine);
drivers/gpu/drm/i915/intel_lrc.c static void execlists_cancel_requests(struct intel_engine_cs *engine) · line 812
Quoted 6 lines
drivers/gpu/drm/i915/intel_lrc.c +2
-1@@ -802,7 +808,8 @@ static void execlists_cancel_requests(struct intel_engine_cs *engine)struct rb_node *rb;unsigned long flags; -GEM_TRACE ("%s\n" , engine->name); +GEM_TRACE ("%s, hws global %d\n" , + engine->name,intel_engine_get_seqno (engine));
I've been suggesting switching over to current=%d for hws global.
Maybe "breadcrumb=%d"? Just something that is unambiguous.
drivers/gpu/drm/i915/intel_lrc.c static void execlists_cancel_requests(struct intel_engine_cs *engine) · line 845
Quoted 13 lines
drivers/gpu/drm/i915/intel_lrc.c +5
-1* Before we call engine->cancel_requests(), we should have exclusive @@ -829,8 +836,12 @@ static void execlists_cancel_requests(struct intel_engine_cs *engine)/* Mark all executing requests as skipped. */ list_for_each_entry (rq, &engine->timeline->requests, link) {GEM_BUG_ON (!rq->global_seqno); -if (!i915_request_completed (rq)) +if (!i915_request_completed (rq)) { +GEM_TRACE ("%s eio %llx:%d [global %d]\n" , + rq->engine->name, rq->fence.context, + rq->fence.seqno, rq->global_seqno);dma_fence_set_error (&rq->fence, -EIO ); + } }
I've been using global_seqno=%d elsewhere. So pick one, and we'll be consistent! I promise this time. Well, at least until I forget in the morning.
So "fence=%llx:%d, global_seqno=%d (current=%d)" e.g.
https://patchwork.freedesktop.org/patch/213307/
-Chris
_______________________________________________
Intel-gfx mailing list [email protected]
https://lists.freedesktop.org/mailman/listinfo/intel-gfx
Patchwork
CI✓ Fi.CI.BAT: success for drm/i915/execlists: Consistent seqno reporting in GEM_TRACE
In reply to Tvrtko Ursulin== Series Details ==
== Series Details ==
Series: drm/i915/execlists: Consistent seqno reporting in GEM_TRACE
URL : https://patchwork.freedesktop.org/series/40821/
State : success
== Summary ==
Series 40821v1 drm/i915/execlists: Consistent seqno reporting in GEM_TRACE
https://patchwork.freedesktop.org/api/1.0/series/40821/revisions/1/mbox/
Warning: Kernel 32bit buildtest failed
https://intel-gfx-ci.01.org/tree/drm-tip/Patchwork_8518/build_32bit.log
---- Known issues:
Test drv_module_reload:
Subgroup basic-reload-inject:
pass -> INCOMPLETE (fi-cnl-y3) fdo#105777
Test kms_pipe_crc_basic:
Subgroup suspend-read-crc-pipe-c:
pass -> DMESG-WARN (fi-cnl-y3) fdo#104951fdo#105777 https://bugs.freedesktop.org/show_bug.cgi?id=105777
fdo#104951 https://bugs.freedesktop.org/show_bug.cgi?id=104951
fi-bdw-5557u total:285 pass:264 dwarn:0 dfail:0 fail:0 skip:21 time:432s fi-bdw-gvtdvm total:285 pass:261 dwarn:0 dfail:0 fail:0 skip:24 time:444s fi-blb-e6850 total:285 pass:220 dwarn:1 dfail:0 fail:0 skip:64 time:383s fi-bsw-n3050 total:285 pass:239 dwarn:0 dfail:0 fail:0 skip:46 time:536s fi-bwr-2160 total:285 pass:180 dwarn:0 dfail:0 fail:0 skip:105 time:296s fi-bxt-dsi total:285 pass:255 dwarn:0 dfail:0 fail:0 skip:30 time:521s fi-bxt-j4205 total:285 pass:256 dwarn:0 dfail:0 fail:0 skip:29 time:511s fi-byt-j1900 total:285 pass:250 dwarn:0 dfail:0 fail:0 skip:35 time:518s fi-byt-n2820 total:285 pass:246 dwarn:0 dfail:0 fail:0 skip:39 time:504s fi-cfl-8700k total:285 pass:257 dwarn:0 dfail:0 fail:0 skip:28 time:411s fi-cfl-s3 total:285 pass:259 dwarn:0 dfail:0 fail:0 skip:26 time:564s fi-cfl-u total:285 pass:259 dwarn:0 dfail:0 fail:0 skip:26 time:510s fi-cnl-y3 total:284 pass:257 dwarn:1 dfail:0 fail:0 skip:25 fi-elk-e7500 total:285 pass:225 dwarn:1 dfail:0 fail:0 skip:59 time:419s fi-gdg-551 total:285 pass:176 dwarn:0 dfail:0 fail:1 skip:108 time:314s fi-glk-1 total:285 pass:257 dwarn:0 dfail:0 fail:0 skip:28 time:539s fi-hsw-4770 total:285 pass:258 dwarn:0 dfail:0 fail:0 skip:27 time:406s fi-ilk-650 total:285 pass:225 dwarn:0 dfail:0 fail:0 skip:60 time:422s fi-ivb-3520m total:285 pass:256 dwarn:0 dfail:0 fail:0 skip:29 time:469s fi-ivb-3770 total:285 pass:252 dwarn:0 dfail:0 fail:0 skip:33 time:435s fi-kbl-7500u total:285 pass:260 dwarn:1 dfail:0 fail:0 skip:24 time:469s fi-kbl-7567u total:285 pass:265 dwarn:0 dfail:0 fail:0 skip:20 time:464s fi-kbl-r total:285 pass:258 dwarn:0 dfail:0 fail:0 skip:27 time:509s fi-pnv-d510 total:285 pass:219 dwarn:1 dfail:0 fail:0 skip:65 time:666s fi-skl-6260u total:285 pass:265 dwarn:0 dfail:0 fail:0 skip:20 time:440s fi-skl-6600u total:285 pass:258 dwarn:0 dfail:0 fail:0 skip:27 time:540s fi-skl-6700k2 total:285 pass:261 dwarn:0 dfail:0 fail:0 skip:24 time:505s fi-skl-6770hq total:285 pass:265 dwarn:0 dfail:0 fail:0 skip:20 time:506s fi-skl-guc total:285 pass:257 dwarn:0 dfail:0 fail:0 skip:28 time:426s fi-skl-gvtdvm total:285 pass:262 dwarn:0 dfail:0 fail:0 skip:23 time:445s fi-snb-2520m total:285 pass:245 dwarn:0 dfail:0 fail:0 skip:40 time:577s fi-snb-2600 total:285 pass:245 dwarn:0 dfail:0 fail:0 skip:40 time:396s
Blacklisted hosts:
fi-cnl-psr total:285 pass:256 dwarn:3 dfail:0 fail:0 skip:26 time:519s
fi-glk-j4005 failed to collect. IGT log at Patchwork_8518/fi-glk-j4005/run0.log
1a854db0e982d1d8caaaaec519ab789bd6ca28ea drm-tip: 2018y-03m-28d-16h-19m-39s UTC integration manifest ec687c517727 drm/i915/execlists: Consistent seqno reporting in GEM_TRACE
== Logs ==
For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/Patchwork_8518/issues.html
_______________________________________________
Intel-gfx mailing list
[email protected]
https://lists.freedesktop.org/mailman/listinfo/intel-gfx
Patchwork
CI✗ Fi.CI.IGT: failure for drm/i915/execlists: Consistent seqno reporting in GEM_TRACE
In reply to Tvrtko Ursulin== Series Details ==
== Series Details ==
Series: drm/i915/execlists: Consistent seqno reporting in GEM_TRACE
URL : https://patchwork.freedesktop.org/series/40821/
State : failure
== Summary ==
---- Possible new issues:
Test drv_selftest:
Subgroup live_hangcheck:
pass -> DMESG-FAIL (shard-apl)
Test kms_draw_crc:
Subgroup draw-method-xrgb8888-mmap-wc-xtiled:
skip -> PASS (shard-snb)---- Known issues:
Test kms_flip:
Subgroup 2x-dpms-vs-vblank-race:
pass -> FAIL (shard-hsw) fdo#103060
Subgroup 2x-flip-vs-expired-vblank-interruptible:
fail -> PASS (shard-hsw) fdo#102887
Subgroup 2x-plain-flip-ts-check-interruptible:
pass -> FAIL (shard-hsw) fdo#100368 +1
Test kms_sysfs_edid_timing:
warn -> PASS (shard-apl) fdo#100047fdo#103060 https://bugs.freedesktop.org/show_bug.cgi?id=103060
fdo#102887 https://bugs.freedesktop.org/show_bug.cgi?id=102887
fdo#100368 https://bugs.freedesktop.org/show_bug.cgi?id=100368
fdo#100047 https://bugs.freedesktop.org/show_bug.cgi?id=100047
shard-apl total:3495 pass:1831 dwarn:1 dfail:1 fail:7 skip:1655 time:12801s shard-hsw total:3495 pass:1781 dwarn:1 dfail:0 fail:3 skip:1709 time:11425s shard-snb total:3495 pass:1375 dwarn:1 dfail:0 fail:2 skip:2117 time:6955s
Blacklisted hosts:
shard-kbl total:3495 pass:1940 dwarn:17 dfail:1 fail:7 skip:1530 time:9233s
== Logs ==
For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/Patchwork_8518/shards.html
_______________________________________________
Intel-gfx mailing list
[email protected]
https://lists.freedesktop.org/mailman/listinfo/intel-gfx
kbuild test robot
build botThank you for the patch! Yet something to improve:
Hi Tvrtko,
Thank you for the patch! Yet something to improve:
[auto build test ERROR on drm-intel/for-linux-next]
[also build test ERROR on next-20180329]
[cannot apply to v4.16-rc7]
[if your patch is applied to the wrong git tree, please drop us a note to help improve the system]
url: https://github.com/0day-ci/linux/commits/Tvrtko-Ursulin/drm-i915-execlists-Consistent-seqno-reporting-in-GEM_TRACE/20180330-120802 base: git://anongit.freedesktop.org/drm-intel for-linux-next config: i386-randconfig-x0-03302126 (attached as .config) compiler: gcc-5 (Debian 5.5.0-3) 5.4.1 20171010 reproduce: # save the attached .config to linux build tree make ARCH=i386
All errors (new ones prefixed by >>):
In file included from include/linux/interrupt.h:6:0,
from drivers/gpu//drm/i915/intel_lrc.c:134:
drivers/gpu//drm/i915/intel_lrc.c: In function 'execlists_cancel_port_requests':
>> drivers/gpu//drm/i915/intel_lrc.c:730:13: error: format '%lu' expects argument of type 'long unsigned int', but argument 3 has type 'int' [-Werror=format=]
GEM_TRACE("%s:port%lu cancel %llx:%d [global %d]\n",
^
include/linux/kernel.h:635:33: note: in definition of macro '__trace_printk_check_format'
____trace_printk_check_format(fmt, ##args); \
^
include/linux/kernel.h:672:3: note: in expansion of macro 'do_trace_printk'
do_trace_printk(fmt, ##__VA_ARGS__); \
^
drivers/gpu//drm/i915/i915_gem.h:55:24: note: in expansion of macro 'trace_printk'
#define GEM_TRACE(...) trace_printk(__VA_ARGS__)
^
drivers/gpu//drm/i915/intel_lrc.c:730:3: note: in expansion of macro 'GEM_TRACE'
GEM_TRACE("%s:port%lu cancel %llx:%d [global %d]\n",
^
drivers/gpu//drm/i915/intel_lrc.c:730:13: error: format '%lu' expects argument of type 'long unsigned int', but argument 4 has type 'int' [-Werror=format=]
GEM_TRACE("%s:port%lu cancel %llx:%d [global %d]\n",
^
include/linux/kernel.h:688:29: note: in definition of macro 'do_trace_printk'
__trace_printk(_THIS_IP_, fmt, ##args); \
^
drivers/gpu//drm/i915/i915_gem.h:55:24: note: in expansion of macro 'trace_printk'
#define GEM_TRACE(...) trace_printk(__VA_ARGS__)
^
drivers/gpu//drm/i915/intel_lrc.c:730:3: note: in expansion of macro 'GEM_TRACE'
GEM_TRACE("%s:port%lu cancel %llx:%d [global %d]\n",
^cc1: all warnings being treated as errors
vim +730 drivers/gpu//drm/i915/intel_lrc.c
720
721 void
722 execlists_cancel_port_requests(struct intel_engine_execlists * const execlists)
723 {
724 struct execlist_port *port = execlists->port;
725 unsigned int num_ports = execlists_num_ports(execlists);
726
727 while (num_ports-- && port_isset(port)) {
728 struct i915_request *rq = port_request(port);
729
> 730 GEM_TRACE("%s:port%lu cancel %llx:%d [global %d]\n", 731 rq->engine->name, port - execlists->port,
732 rq->fence.context, rq->fence.seqno, rq->global_seqno);
733
734 GEM_BUG_ON(!execlists->active);
735 intel_engine_context_out(rq->engine);
736
737 execlists_context_status_change(rq,
738 i915_request_completed(rq) ?
739 INTEL_CONTEXT_SCHEDULE_OUT :
740 INTEL_CONTEXT_SCHEDULE_PREEMPTED);
741
742 i915_request_put(rq);
743
744 memset(port, 0, sizeof(*port));
745 port++;
746 }
747 }
748
---
0-DAY kernel test infrastructure Open Source Technology Center
https://lists.01.org/pipermail/kbuild-all Intel Corporation
_______________________________________________
Intel-gfx mailing list
[email protected]
https://lists.freedesktop.org/mailman/listinfo/intel-gfx