[Intel-gfx] [PATCH] drm/i915/execlists: Consistent seqno reporting in GEM_TRACE

[Chris Wilson]

Quoting Tvrtko Ursulin (2018-03-28 18:39:59)
> From: Tvrtko Ursulin <tvrtko.ursulin at intel.com>
> 
> 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.
> 
> Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin at intel.com>
> ---
> 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(-)
> 
> diff --git a/drivers/gpu/drm/i915/intel_lrc.c b/drivers/gpu/drm/i915/intel_lrc.c
> index fe520c4dd999..c5e8526a2025 100644
> --- a/drivers/gpu/drm/i915/intel_lrc.c
> +++ b/drivers/gpu/drm/i915/intel_lrc.c
> @@ -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));

I've been suggesting switching over to current=%d for hws global.

Maybe "breadcrumb=%d"? Just something that is unambiguous.

>          * 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