[RFC 33/44] drm/i915: Added trace points to scheduler

[John.C.Harrison@Intel.com]

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.
---
 drivers/gpu/drm/i915/i915_gem_execbuffer.c |    2 +
 drivers/gpu/drm/i915/i915_scheduler.c      |   31 ++++-
 drivers/gpu/drm/i915/i915_trace.h          |  194 ++++++++++++++++++++++++++++
 3 files changed, 226 insertions(+), 1 deletion(-)

diff --git a/drivers/gpu/drm/i915/i915_gem_execbuffer.c b/drivers/gpu/drm/i915/i915_gem_execbuffer.c
index 98cc95e..bf19e02 100644
--- a/drivers/gpu/drm/i915/i915_gem_execbuffer.c
+++ b/drivers/gpu/drm/i915/i915_gem_execbuffer.c
@@ -1413,6 +1413,8 @@ i915_gem_do_execbuffer(struct drm_device *dev, void *data,
 	ring->outstanding_lazy_seqno    = 0;
 	ring->preallocated_lazy_request = NULL;
 
+	trace_i915_gem_ring_queue(ring, &qe);
+
 	ret = i915_scheduler_queue_execbuffer(&qe);
 	if (ret)
 		goto err;
diff --git a/drivers/gpu/drm/i915/i915_scheduler.c b/drivers/gpu/drm/i915/i915_scheduler.c
index 71d8db4..6d0f4cb 100644
--- a/drivers/gpu/drm/i915/i915_scheduler.c
+++ b/drivers/gpu/drm/i915/i915_scheduler.c
@@ -87,6 +87,8 @@ int i915_scheduler_queue_execbuffer(struct i915_scheduler_queue_entry *qe)
 
 		qe->params.scheduler_index = scheduler->index++;
 
+		trace_i915_scheduler_queue(qe->params.ring, qe);
+
 		scheduler->flags[qe->params.ring->id] |= i915_sf_submitting;
 		ret = i915_gem_do_execbuffer_final(&qe->params);
 		scheduler->flags[qe->params.ring->id] &= ~i915_sf_submitting;
@@ -215,6 +217,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_irqrestore(&scheduler->lock, flags);
 
 	if (not_flying)
@@ -253,6 +258,8 @@ int i915_scheduler_fly_seqno(struct intel_engine_cs *ring, uint32_t seqno)
 	node->stamp        = stamp;
 	node->status       = i915_sqs_none;
 
+	trace_i915_scheduler_node_state_change(ring, node);
+
 	spin_lock_irqsave(&scheduler->lock, flags);
 	ret = i915_scheduler_fly_node(node);
 	spin_unlock_irqrestore(&scheduler->lock, flags);
@@ -279,6 +286,9 @@ int i915_scheduler_fly_node(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;
 
@@ -343,6 +353,8 @@ static void i915_scheduler_node_requeue(struct i915_scheduler_queue_entry *node)
 	BUG_ON(!I915_SQS_IS_FLYING(node));
 
 	node->status = i915_sqs_queued;
+	trace_i915_scheduler_unfly(node->params.ring, node);
+	trace_i915_scheduler_node_state_change(node->params.ring, node);
 }
 
 /* Give up on a popped node completely. For example, because it is causing the
@@ -353,6 +365,8 @@ static void i915_scheduler_node_kill(struct i915_scheduler_queue_entry *node)
 	BUG_ON(!I915_SQS_IS_FLYING(node));
 
 	node->status = i915_sqs_complete;
+	trace_i915_scheduler_unfly(node->params.ring, node);
+	trace_i915_scheduler_node_state_change(node->params.ring, node);
 }
 
 /*
@@ -377,13 +391,17 @@ static int i915_scheduler_seqno_complete(struct intel_engine_cs *ring, uint32_t
 	 * if a completed entry is found then there is no need to scan further.
 	 */
 	list_for_each_entry(node, &scheduler->node_queue[ring->id], link) {
-		if (I915_SQS_IS_COMPLETE(node))
+		if (I915_SQS_IS_COMPLETE(node)) {
+			trace_i915_scheduler_landing(ring, seqno, node);
 			goto done;
+		}
 
 		if (seqno == node->params.seqno)
 			break;
 	}
 
+	trace_i915_scheduler_landing(ring, seqno, node);
+
 	/*
 	 * NB: Lots of extra seqnos get added to the ring to track things
 	 * like cache flushes and page flips. So don't complain about if
@@ -405,6 +423,7 @@ static int i915_scheduler_seqno_complete(struct intel_engine_cs *ring, uint32_t
 
 		/* Node was in flight so mark it as complete. */
 		node->status = i915_sqs_complete;
+		trace_i915_scheduler_node_state_change(ring, node);
 	}
 
 	/* Should submit new work here if flight list is empty but the DRM
@@ -425,6 +444,8 @@ int i915_scheduler_handle_IRQ(struct intel_engine_cs *ring)
 
 	seqno = ring->get_seqno(ring, false);
 
+	trace_i915_scheduler_irq(ring, seqno);
+
 	if (i915.scheduler_override & i915_so_direct_submit)
 		return 0;
 
@@ -526,6 +547,8 @@ int i915_scheduler_remove(struct intel_engine_cs *ring)
 	/* Launch more packets now? */
 	do_submit = (queued > 0) && (flying < scheduler->min_flying);
 
+	trace_i915_scheduler_remove(ring, min_seqno, do_submit);
+
 	spin_unlock_irqrestore(&scheduler->lock, flags);
 
 	if (do_submit)
@@ -535,6 +558,8 @@ int i915_scheduler_remove(struct intel_engine_cs *ring)
 		node = list_first_entry(&remove, typeof(*node), link);
 		list_del(&node->link);
 
+		trace_i915_scheduler_destroy(ring, node);
+
 		/* Release the locked buffers: */
 		for (i = 0; i < node->num_objs; i++) {
 			drm_gem_object_unreference(
@@ -793,6 +818,8 @@ static int i915_scheduler_pop_from_queue_locked(struct intel_engine_cs *ring,
 		INIT_LIST_HEAD(&best->link);
 		best->status  = i915_sqs_none;
 
+		trace_i915_scheduler_node_state_change(ring, best);
+
 		ret = 0;
 	} else {
 		/* Can only get here if:
@@ -812,6 +839,8 @@ static int i915_scheduler_pop_from_queue_locked(struct intel_engine_cs *ring,
 
 	/* i915_scheduler_dump_queue_pop(ring, best); */
 
+	trace_i915_scheduler_pop_from_queue(ring, best);
+
 	*pop_node = best;
 	return ret;
 }
diff --git a/drivers/gpu/drm/i915/i915_trace.h b/drivers/gpu/drm/i915/i915_trace.h
index f5aa006..bea2a49 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
@@ -587,6 +588,199 @@ TRACE_EVENT(intel_gpu_freq_change,
 	    TP_printk("new_freq=%u", __entry->freq)
 );
 
+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, seqno)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->ring      = ring->id;
+			   __entry->seqno     = node ? node->params.seqno : 0;
+			   ),
+
+	    TP_printk("ring=%d, seqno=%d",
+		      __entry->ring, __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, seqno)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->ring      = ring->id;
+			   __entry->seqno     = node ? node->params.seqno : 0;
+			   ),
+
+	    TP_printk("ring=%d, seqno=%d",
+		      __entry->ring, __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, seqno)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->ring      = ring->id;
+			   __entry->seqno     = node ? node->params.seqno : 0;
+			   ),
+
+	    TP_printk("ring=%d, seqno=%d",
+		      __entry->ring, __entry->seqno)
+);
+
+TRACE_EVENT(i915_scheduler_landing,
+	    TP_PROTO(struct intel_engine_cs *ring, u32 seqno,
+		     struct i915_scheduler_queue_entry *node),
+	    TP_ARGS(ring, seqno, node),
+
+	    TP_STRUCT__entry(
+			     __field(u32, ring)
+			     __field(u32, seqno)
+			     __field(u32, status)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->ring   = ring->id;
+			   __entry->seqno  = seqno;
+			   __entry->status = node ? node->status : ~0U;
+			   ),
+
+	    TP_printk("ring=%d, seqno=%d, status=%d",
+		      __entry->ring, __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, seqno)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->ring      = ring->id;
+			   __entry->seqno     = node ? node->params.seqno : 0;
+			   ),
+
+	    TP_printk("ring=%d, seqno=%d",
+		      __entry->ring, __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, seqno)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->ring   = ring->id;
+			   __entry->seqno  = node ? node->params.seqno : 0;
+			   ),
+
+	    TP_printk("ring=%d, seqno=%d",
+		      __entry->ring, __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, seqno)
+			     __field(u32, status)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->ring   = ring->id;
+			   __entry->seqno  = node->params.seqno;
+			   __entry->status = node->status;
+			   ),
+
+	    TP_printk("ring=%d, seqno=%d, status=%d",
+		      __entry->ring, __entry->seqno, __entry->status)
+);
+
+TRACE_EVENT(i915_scheduler_irq,
+	    TP_PROTO(struct intel_engine_cs *ring, uint32_t seqno),
+	    TP_ARGS(ring, seqno),
+
+	    TP_STRUCT__entry(
+			     __field(u32, ring)
+			     __field(u32, seqno)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->ring   = ring->id;
+			   __entry->seqno  = seqno;
+			   ),
+
+	    TP_printk("ring=%d, seqno=%d", __entry->ring, __entry->seqno)
+);
+
+TRACE_EVENT(i915_gem_ring_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, seqno)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->ring   = ring->id;
+			   __entry->seqno  = node->params.seqno;
+			   ),
+
+	    TP_printk("ring=%d, seqno=%d", __entry->ring, __entry->seqno)
+);
+
 #endif /* _I915_TRACE_H_ */
 
 /* This part must be outside protection */
-- 
1.7.9.5