Re: [PATCH v5 24/35] drm/i915: Added trace points to scheduler

From: Jesse Barnes <jbarnes@virtuousgeek.org>
To: John Harrison <John.C.Harrison@Intel.com>,
	Intel-GFX@Lists.FreeDesktop.Org
Subject: Re: [PATCH v5 24/35] drm/i915: Added trace points to scheduler
Date: Fri, 26 Feb 2016 09:12:42 -0800	[thread overview]
Message-ID: <56D0878A.707@virtuousgeek.org> (raw)
In-Reply-To: <56D07572.9090807@Intel.com>

On 02/26/2016 07:55 AM, John Harrison wrote:
> On 23/02/2016 20:42, Jesse Barnes wrote:
>> On 02/18/2016 06:27 AM, John.C.Harrison@Intel.com wrote:
>>> From: John Harrison <John.C.Harrison@Intel.com>
>>>
>>> Added trace points to the scheduler to track all the various events,
>>> node state transitions and other interesting things that occur.
>>>
>>> v2: Updated for new request completion tracking implementation.
>>>
>>> v3: Updated for changes to node kill code.
>>>
>>> v4: Wrapped some long lines to keep the style checker happy.
>>>
>>> For: VIZ-1587
>>> Signed-off-by: John Harrison <John.C.Harrison@Intel.com>
>>> ---
>>>   drivers/gpu/drm/i915/i915_gem_execbuffer.c |   2 +
>>>   drivers/gpu/drm/i915/i915_scheduler.c      |  26 ++++
>>>   drivers/gpu/drm/i915/i915_trace.h          | 196 +++++++++++++++++++++++++++++
>>>   drivers/gpu/drm/i915/intel_lrc.c           |   2 +
>>>   4 files changed, 226 insertions(+)
>>>
>>> diff --git a/drivers/gpu/drm/i915/i915_gem_execbuffer.c b/drivers/gpu/drm/i915/i915_gem_execbuffer.c
>>> index b9ad0fd..d4de8c7 100644
>>> --- a/drivers/gpu/drm/i915/i915_gem_execbuffer.c
>>> +++ b/drivers/gpu/drm/i915/i915_gem_execbuffer.c
>>> @@ -1272,6 +1272,8 @@ i915_gem_ringbuffer_submission(struct i915_execbuffer_params *params,
>>>         i915_gem_execbuffer_move_to_active(vmas, params->request);
>>>   +    trace_i915_gem_ring_queue(ring, params);
>>> +
>>>       qe = container_of(params, typeof(*qe), params);
>>>       ret = i915_scheduler_queue_execbuffer(qe);
>>>       if (ret)
>>> diff --git a/drivers/gpu/drm/i915/i915_scheduler.c b/drivers/gpu/drm/i915/i915_scheduler.c
>>> index 47d7de4..e56ce08 100644
>>> --- a/drivers/gpu/drm/i915/i915_scheduler.c
>>> +++ b/drivers/gpu/drm/i915/i915_scheduler.c
>>> @@ -88,6 +88,8 @@ static void i915_scheduler_node_requeue(struct i915_scheduler_queue_entry *node)
>>>       /* Seqno will be reassigned on relaunch */
>>>       node->params.request->seqno = 0;
>>>       node->status = i915_sqs_queued;
>>> +    trace_i915_scheduler_unfly(node->params.ring, node);
>>> +    trace_i915_scheduler_node_state_change(node->params.ring, node);
>>>   }
>>>     /*
>>> @@ -99,7 +101,11 @@ static void i915_scheduler_node_kill(struct i915_scheduler_queue_entry *node)
>>>       WARN_ON(!node);
>>>       WARN_ON(I915_SQS_IS_COMPLETE(node));
>>>   +    if (I915_SQS_IS_FLYING(node))
>>> +        trace_i915_scheduler_unfly(node->params.ring, node);
>>> +
>>>       node->status = i915_sqs_dead;
>>> +    trace_i915_scheduler_node_state_change(node->params.ring, node);
>>>   }
>>>     /* Mark a node as in flight on the hardware. */
>>> @@ -124,6 +130,9 @@ static int i915_scheduler_node_fly(struct i915_scheduler_queue_entry *node)
>>>         node->status = i915_sqs_flying;
>>>   +    trace_i915_scheduler_fly(ring, node);
>>> +    trace_i915_scheduler_node_state_change(ring, node);
>>> +
>>>       if (!(scheduler->flags[ring->id] & i915_sf_interrupts_enabled)) {
>>>           bool success = true;
>>>   @@ -280,6 +289,8 @@ static int i915_scheduler_pop_from_queue_locked(struct intel_engine_cs *ring,
>>>           INIT_LIST_HEAD(&best->link);
>>>           best->status  = i915_sqs_popped;
>>>   +        trace_i915_scheduler_node_state_change(ring, best);
>>> +
>>>           ret = 0;
>>>       } else {
>>>           /* Can only get here if:
>>> @@ -297,6 +308,8 @@ static int i915_scheduler_pop_from_queue_locked(struct intel_engine_cs *ring,
>>>           }
>>>       }
>>>   +    trace_i915_scheduler_pop_from_queue(ring, best);
>>> +
>>>       *pop_node = best;
>>>       return ret;
>>>   }
>>> @@ -506,6 +519,8 @@ static int i915_scheduler_queue_execbuffer_bypass(struct i915_scheduler_queue_en
>>>       struct i915_scheduler *scheduler = dev_priv->scheduler;
>>>       int ret;
>>>   +    trace_i915_scheduler_queue(qe->params.ring, qe);
>>> +
>>>       intel_ring_reserved_space_cancel(qe->params.request->ringbuf);
>>>         scheduler->flags[qe->params.ring->id] |= i915_sf_submitting;
>>> @@ -628,6 +643,9 @@ int i915_scheduler_queue_execbuffer(struct i915_scheduler_queue_entry *qe)
>>>       not_flying = i915_scheduler_count_flying(scheduler, ring) <
>>>                            scheduler->min_flying;
>>>   +    trace_i915_scheduler_queue(ring, node);
>>> +    trace_i915_scheduler_node_state_change(ring, node);
>>> +
>>>       spin_unlock_irq(&scheduler->lock);
>>>         if (not_flying)
>>> @@ -657,6 +675,8 @@ bool i915_scheduler_notify_request(struct drm_i915_gem_request *req)
>>>       struct i915_scheduler_queue_entry *node = req->scheduler_qe;
>>>       unsigned long flags;
>>>   +    trace_i915_scheduler_landing(req);
>>> +
>>>       if (!node)
>>>           return false;
>>>   @@ -670,6 +690,8 @@ bool i915_scheduler_notify_request(struct drm_i915_gem_request *req)
>>>       else
>>>           node->status = i915_sqs_complete;
>>>   +    trace_i915_scheduler_node_state_change(req->ring, node);
>>> +
>>>       spin_unlock_irqrestore(&scheduler->lock, flags);
>>>         return true;
>>> @@ -877,6 +899,8 @@ static bool i915_scheduler_remove(struct i915_scheduler *scheduler,
>>>       /* Launch more packets now? */
>>>       do_submit = (queued > 0) && (flying < scheduler->min_flying);
>>>   +    trace_i915_scheduler_remove(ring, min_seqno, do_submit);
>>> +
>>>       spin_unlock_irq(&scheduler->lock);
>>>         return do_submit;
>>> @@ -912,6 +936,8 @@ static void i915_scheduler_process_work(struct intel_engine_cs *ring)
>>>           node = list_first_entry(&remove, typeof(*node), link);
>>>           list_del(&node->link);
>>>   +        trace_i915_scheduler_destroy(ring, node);
>>> +
>>>           /* Free up all the DRM references */
>>>           i915_scheduler_clean_node(node);
>>>   diff --git a/drivers/gpu/drm/i915/i915_trace.h b/drivers/gpu/drm/i915/i915_trace.h
>>> index 455c215..c3c4e58 100644
>>> --- a/drivers/gpu/drm/i915/i915_trace.h
>>> +++ b/drivers/gpu/drm/i915/i915_trace.h
>>> @@ -9,6 +9,7 @@
>>>   #include "i915_drv.h"
>>>   #include "intel_drv.h"
>>>   #include "intel_ringbuffer.h"
>>> +#include "i915_scheduler.h"
>>>     #undef TRACE_SYSTEM
>>>   #define TRACE_SYSTEM i915
>>> @@ -826,6 +827,201 @@ TRACE_EVENT(switch_mm,
>>>             __entry->dev, __entry->ring, __entry->to, __entry->vm)
>>>   );
>>>   +TRACE_EVENT(i915_scheduler_queue,
>>> +        TP_PROTO(struct intel_engine_cs *ring,
>>> +             struct i915_scheduler_queue_entry *node),
>>> +        TP_ARGS(ring, node),
>>> +
>>> +        TP_STRUCT__entry(
>>> +                 __field(u32, ring)
>>> +                 __field(u32, uniq)
>>> +                 __field(u32, seqno)
>>> +                 ),
>>> +
>>> +        TP_fast_assign(
>>> +               __entry->ring  = ring->id;
>>> +               __entry->uniq  = node ? node->params.request->uniq  : 0;
>>> +               __entry->seqno = node ? node->params.request->seqno : 0;
>>> +               ),
>>> +
>>> +        TP_printk("ring=%d, uniq=%d, seqno=%d",
>>> +              __entry->ring, __entry->uniq, __entry->seqno)
>>> +);
>>> +
>>> +TRACE_EVENT(i915_scheduler_fly,
>>> +        TP_PROTO(struct intel_engine_cs *ring,
>>> +             struct i915_scheduler_queue_entry *node),
>>> +        TP_ARGS(ring, node),
>>> +
>>> +        TP_STRUCT__entry(
>>> +                 __field(u32, ring)
>>> +                 __field(u32, uniq)
>>> +                 __field(u32, seqno)
>>> +                 ),
>>> +
>>> +        TP_fast_assign(
>>> +               __entry->ring  = ring->id;
>>> +               __entry->uniq  = node ? node->params.request->uniq  : 0;
>>> +               __entry->seqno = node ? node->params.request->seqno : 0;
>>> +               ),
>>> +
>>> +        TP_printk("ring=%d, uniq=%d, seqno=%d",
>>> +              __entry->ring, __entry->uniq, __entry->seqno)
>>> +);
>>> +
>>> +TRACE_EVENT(i915_scheduler_unfly,
>>> +        TP_PROTO(struct intel_engine_cs *ring,
>>> +             struct i915_scheduler_queue_entry *node),
>>> +        TP_ARGS(ring, node),
>>> +
>>> +        TP_STRUCT__entry(
>>> +                 __field(u32, ring)
>>> +                 __field(u32, uniq)
>>> +                 __field(u32, seqno)
>>> +                 ),
>>> +
>>> +        TP_fast_assign(
>>> +               __entry->ring  = ring->id;
>>> +               __entry->uniq  = node ? node->params.request->uniq  : 0;
>>> +               __entry->seqno = node ? node->params.request->seqno : 0;
>>> +               ),
>>> +
>>> +        TP_printk("ring=%d, uniq=%d, seqno=%d",
>>> +              __entry->ring, __entry->uniq, __entry->seqno)
>>> +);
>>> +
>>> +TRACE_EVENT(i915_scheduler_landing,
>>> +        TP_PROTO(struct drm_i915_gem_request *req),
>>> +        TP_ARGS(req),
>>> +
>>> +        TP_STRUCT__entry(
>>> +                 __field(u32, ring)
>>> +                 __field(u32, uniq)
>>> +                 __field(u32, seqno)
>>> +                 __field(u32, status)
>>> +                 ),
>>> +
>>> +        TP_fast_assign(
>>> +               __entry->ring   = req->ring->id;
>>> +               __entry->uniq   = req->uniq;
>>> +               __entry->seqno  = req->seqno;
>>> +               __entry->status = req->scheduler_qe ?
>>> +                        req->scheduler_qe->status : ~0U;
>>> +               ),
>>> +
>>> +        TP_printk("ring=%d, uniq=%d, seqno=%d, status=%d",
>>> +              __entry->ring, __entry->uniq, __entry->seqno,
>>> +              __entry->status)
>>> +);
>>> +
>>> +TRACE_EVENT(i915_scheduler_remove,
>>> +        TP_PROTO(struct intel_engine_cs *ring,
>>> +             u32 min_seqno, bool do_submit),
>>> +        TP_ARGS(ring, min_seqno, do_submit),
>>> +
>>> +        TP_STRUCT__entry(
>>> +                 __field(u32, ring)
>>> +                 __field(u32, min_seqno)
>>> +                 __field(bool, do_submit)
>>> +                 ),
>>> +
>>> +        TP_fast_assign(
>>> +               __entry->ring      = ring->id;
>>> +               __entry->min_seqno = min_seqno;
>>> +               __entry->do_submit = do_submit;
>>> +               ),
>>> +
>>> +        TP_printk("ring=%d, min_seqno = %d, do_submit=%d",
>>> +              __entry->ring, __entry->min_seqno, __entry->do_submit)
>>> +);
>>> +
>>> +TRACE_EVENT(i915_scheduler_destroy,
>>> +        TP_PROTO(struct intel_engine_cs *ring,
>>> +             struct i915_scheduler_queue_entry *node),
>>> +        TP_ARGS(ring, node),
>>> +
>>> +        TP_STRUCT__entry(
>>> +                 __field(u32, ring)
>>> +                 __field(u32, uniq)
>>> +                 __field(u32, seqno)
>>> +                 ),
>>> +
>>> +        TP_fast_assign(
>>> +               __entry->ring  = ring->id;
>>> +               __entry->uniq  = node ? node->params.request->uniq  : 0;
>>> +               __entry->seqno = node ? node->params.request->seqno : 0;
>>> +               ),
>>> +
>>> +        TP_printk("ring=%d, uniq=%d, seqno=%d",
>>> +              __entry->ring, __entry->uniq, __entry->seqno)
>>> +);
>>> +
>>> +TRACE_EVENT(i915_scheduler_pop_from_queue,
>>> +        TP_PROTO(struct intel_engine_cs *ring,
>>> +             struct i915_scheduler_queue_entry *node),
>>> +        TP_ARGS(ring, node),
>>> +
>>> +        TP_STRUCT__entry(
>>> +                 __field(u32, ring)
>>> +                 __field(u32, uniq)
>>> +                 __field(u32, seqno)
>>> +                 ),
>>> +
>>> +        TP_fast_assign(
>>> +               __entry->ring  = ring->id;
>>> +               __entry->uniq  = node ? node->params.request->uniq  : 0;
>>> +               __entry->seqno = node ? node->params.request->seqno : 0;
>>> +               ),
>>> +
>>> +        TP_printk("ring=%d, uniq=%d, seqno=%d",
>>> +              __entry->ring, __entry->uniq, __entry->seqno)
>>> +);
>>> +
>>> +TRACE_EVENT(i915_scheduler_node_state_change,
>>> +        TP_PROTO(struct intel_engine_cs *ring,
>>> +             struct i915_scheduler_queue_entry *node),
>>> +        TP_ARGS(ring, node),
>>> +
>>> +        TP_STRUCT__entry(
>>> +                 __field(u32, ring)
>>> +                 __field(u32, uniq)
>>> +                 __field(u32, seqno)
>>> +                 __field(u32, status)
>>> +                 ),
>>> +
>>> +        TP_fast_assign(
>>> +               __entry->ring   = ring->id;
>>> +               __entry->uniq   = node ? node->params.request->uniq  : 0;
>>> +               __entry->seqno  = node->params.request->seqno;
>>> +               __entry->status = node->status;
>>> +               ),
>>> +
>>> +        TP_printk("ring=%d, uniq=%d, seqno=%d, status=%d",
>>> +              __entry->ring, __entry->uniq, __entry->seqno,
>>> +              __entry->status)
>>> +);
>>> +
>>> +TRACE_EVENT(i915_gem_ring_queue,
>>> +        TP_PROTO(struct intel_engine_cs *ring,
>>> +             struct i915_execbuffer_params *params),
>>> +        TP_ARGS(ring, params),
>>> +
>>> +        TP_STRUCT__entry(
>>> +                 __field(u32, ring)
>>> +                 __field(u32, uniq)
>>> +                 __field(u32, seqno)
>>> +                 ),
>>> +
>>> +        TP_fast_assign(
>>> +               __entry->ring  = ring->id;
>>> +               __entry->uniq  = params->request->uniq;
>>> +               __entry->seqno = params->request->seqno;
>>> +               ),
>>> +
>>> +        TP_printk("ring=%d, uniq=%d, seqno=%d", __entry->ring,
>>> +              __entry->uniq, __entry->seqno)
>>> +);
>>> +
>>>   #endif /* _I915_TRACE_H_ */
>>>     /* This part must be outside protection */
>>> diff --git a/drivers/gpu/drm/i915/intel_lrc.c b/drivers/gpu/drm/i915/intel_lrc.c
>>> index 9c7a79a..2b9f49c 100644
>>> --- a/drivers/gpu/drm/i915/intel_lrc.c
>>> +++ b/drivers/gpu/drm/i915/intel_lrc.c
>>> @@ -954,6 +954,8 @@ int intel_execlists_submission(struct i915_execbuffer_params *params,
>>>         i915_gem_execbuffer_move_to_active(vmas, params->request);
>>>   +    trace_i915_gem_ring_queue(ring, params);
>>> +
>>>       qe = container_of(params, typeof(*qe), params);
>>>       ret = i915_scheduler_queue_execbuffer(qe);
>>>       if (ret)
>>>
>> Oops, forgot to ask if there are any tools for igt that make use of these, e.g. some kind of scheduler top util that looks for bubbles or starved batches or something.
> Nothing at the moment. They have been used to debug issues by looking through trace logs. Also the validation team have tests that hook in to the various trace points to verify the internal operation of the scheduler and other parts of the i915 driver.

Nice.  I wasn't asking because it's a blocker or anything, just curious.

Thanks,
Jesse

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx