[PATCH 1/8] drm/i915/tracepoints: Tidy request event class

[PATCH 1/8] drm/i915/tracepoints: Tidy request event class

[Tvrtko Ursulin]

From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

At the moment only the global seqno is logged which is not set
until the request is ready for submission.

Add the per-contex seqno and the context hardware id which are
both interesting data points.

Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
---
 drivers/gpu/drm/i915/i915_trace.h | 11 ++++++++---
 1 file changed, 8 insertions(+), 3 deletions(-)

diff --git a/drivers/gpu/drm/i915/i915_trace.h b/drivers/gpu/drm/i915/i915_trace.h
index 7a547cdfc381..4454872d487f 100644
--- a/drivers/gpu/drm/i915/i915_trace.h
+++ b/drivers/gpu/drm/i915/i915_trace.h
@@ -451,18 +451,23 @@ DECLARE_EVENT_CLASS(i915_gem_request,
 
 	    TP_STRUCT__entry(
 			     __field(u32, dev)
+			     __field(u32, ctx)
 			     __field(u32, ring)
 			     __field(u32, seqno)
+			     __field(u32, global)
 			     ),
 
 	    TP_fast_assign(
 			   __entry->dev = req->i915->drm.primary->index;
+			   __entry->ctx = req->ctx->hw_id;
 			   __entry->ring = req->engine->id;
-			   __entry->seqno = req->global_seqno;
+			   __entry->seqno = req->fence.seqno;
+			   __entry->global = req->global_seqno;
 			   ),
 
-	    TP_printk("dev=%u, ring=%u, seqno=%u",
-		      __entry->dev, __entry->ring, __entry->seqno)
+	    TP_printk("dev=%u, ring=%u, ctx=%u, seqno=%u, global=%u",
+		      __entry->dev, __entry->ring, __entry->ctx, __entry->seqno,
+		      __entry->global)
 );
 
 DEFINE_EVENT(i915_gem_request, i915_gem_request_add,
-- 
2.9.3

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

[PATCH 2/8] drm/i915/tracepoints: Adjust i915_gem_ring_dispatch

[Tvrtko Ursulin]

From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

Rename it to i915_gem_request_queue and fix the logged info
equivalent to the i915_gem_request even class. Also moved it
a bit further apart from the i915_gem_request_add tracepoint
since they otherwise provide similar information too close in
time.

v2: Remove sw fence singalling. We will rely on the soon to
    come GuC scheduling backend to enable that. (Chris Wilson)

v3: Log hex with 0x prefix for clarity.

Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
---
 drivers/gpu/drm/i915/i915_gem_execbuffer.c |  4 ++--
 drivers/gpu/drm/i915/i915_trace.h          | 12 +++++++-----
 2 files changed, 9 insertions(+), 7 deletions(-)

diff --git a/drivers/gpu/drm/i915/i915_gem_execbuffer.c b/drivers/gpu/drm/i915/i915_gem_execbuffer.c
index da0846fe2ad6..9c35746f35fe 100644
--- a/drivers/gpu/drm/i915/i915_gem_execbuffer.c
+++ b/drivers/gpu/drm/i915/i915_gem_execbuffer.c
@@ -1493,8 +1493,6 @@ execbuf_submit(struct i915_execbuffer_params *params,
 	if (ret)
 		return ret;
 
-	trace_i915_gem_ring_dispatch(params->request, params->dispatch_flags);
-
 	i915_gem_execbuffer_move_to_active(vmas, params->request);
 
 	return 0;
@@ -1836,6 +1834,8 @@ i915_gem_do_execbuffer(struct drm_device *dev, void *data,
 	params->dispatch_flags          = dispatch_flags;
 	params->ctx                     = ctx;
 
+	trace_i915_gem_request_queue(params->request, dispatch_flags);
+
 	ret = execbuf_submit(params, args, &eb->vmas);
 err_request:
 	__i915_add_request(params->request, ret == 0);
diff --git a/drivers/gpu/drm/i915/i915_trace.h b/drivers/gpu/drm/i915/i915_trace.h
index 4454872d487f..d9ade8c38f92 100644
--- a/drivers/gpu/drm/i915/i915_trace.h
+++ b/drivers/gpu/drm/i915/i915_trace.h
@@ -399,13 +399,14 @@ TRACE_EVENT(i915_gem_ring_sync_to,
 		      __entry->seqno)
 );
 
-TRACE_EVENT(i915_gem_ring_dispatch,
+TRACE_EVENT(i915_gem_request_queue,
 	    TP_PROTO(struct drm_i915_gem_request *req, u32 flags),
 	    TP_ARGS(req, flags),
 
 	    TP_STRUCT__entry(
 			     __field(u32, dev)
 			     __field(u32, ring)
+			     __field(u32, ctx)
 			     __field(u32, seqno)
 			     __field(u32, flags)
 			     ),
@@ -413,13 +414,14 @@ TRACE_EVENT(i915_gem_ring_dispatch,
 	    TP_fast_assign(
 			   __entry->dev = req->i915->drm.primary->index;
 			   __entry->ring = req->engine->id;
-			   __entry->seqno = req->global_seqno;
+			   __entry->ctx = req->ctx->hw_id;
+			   __entry->seqno = req->fence.seqno;
 			   __entry->flags = flags;
-			   dma_fence_enable_sw_signaling(&req->fence);
 			   ),
 
-	    TP_printk("dev=%u, ring=%u, seqno=%u, flags=%x",
-		      __entry->dev, __entry->ring, __entry->seqno, __entry->flags)
+	    TP_printk("dev=%u, ring=%u, ctx=%u, seqno=%u, flags=0x%x",
+		      __entry->dev, __entry->ring, __entry->ctx, __entry->seqno,
+		      __entry->flags)
 );
 
 TRACE_EVENT(i915_gem_ring_flush,
-- 
2.9.3

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

[PATCH 3/8] drm/i915/tracepoints: Tidy i915_gem_request_wait_begin

[Tvrtko Ursulin]

From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

Provide the same information as the other request event classes.

v2: Pass in flags so we can properly report the blocking status.
    (Chris Wilson)

v3: Log hex with 0x prefix for clarity.

Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
---
 drivers/gpu/drm/i915/i915_gem_request.c |  2 +-
 drivers/gpu/drm/i915/i915_trace.h       | 21 +++++++++++++--------
 2 files changed, 14 insertions(+), 9 deletions(-)

diff --git a/drivers/gpu/drm/i915/i915_gem_request.c b/drivers/gpu/drm/i915/i915_gem_request.c
index a5fac40d2a4f..543cef57972b 100644
--- a/drivers/gpu/drm/i915/i915_gem_request.c
+++ b/drivers/gpu/drm/i915/i915_gem_request.c
@@ -1092,7 +1092,7 @@ long i915_wait_request(struct drm_i915_gem_request *req,
 	if (!timeout)
 		return -ETIME;
 
-	trace_i915_gem_request_wait_begin(req);
+	trace_i915_gem_request_wait_begin(req, flags);
 
 	if (!i915_sw_fence_done(&req->execute)) {
 		timeout = __i915_request_wait_for_execute(req, flags, timeout);
diff --git a/drivers/gpu/drm/i915/i915_trace.h b/drivers/gpu/drm/i915/i915_trace.h
index d9ade8c38f92..916aadbb5389 100644
--- a/drivers/gpu/drm/i915/i915_trace.h
+++ b/drivers/gpu/drm/i915/i915_trace.h
@@ -508,13 +508,16 @@ DEFINE_EVENT(i915_gem_request, i915_gem_request_complete,
 );
 
 TRACE_EVENT(i915_gem_request_wait_begin,
-	    TP_PROTO(struct drm_i915_gem_request *req),
-	    TP_ARGS(req),
+	    TP_PROTO(struct drm_i915_gem_request *req, unsigned int flags),
+	    TP_ARGS(req, flags),
 
 	    TP_STRUCT__entry(
 			     __field(u32, dev)
 			     __field(u32, ring)
+			     __field(u32, ctx)
 			     __field(u32, seqno)
+			     __field(u32, global)
+			     __field(unsigned int, flags)
 			     __field(bool, blocking)
 			     ),
 
@@ -527,14 +530,16 @@ TRACE_EVENT(i915_gem_request_wait_begin,
 	    TP_fast_assign(
 			   __entry->dev = req->i915->drm.primary->index;
 			   __entry->ring = req->engine->id;
-			   __entry->seqno = req->global_seqno;
-			   __entry->blocking =
-				     mutex_is_locked(&req->i915->drm.struct_mutex);
+			   __entry->ctx = req->ctx->hw_id;
+			   __entry->seqno = req->fence.seqno;
+			   __entry->global = req->global_seqno;
+			   __entry->flags = flags;
+			   __entry->blocking = flags & I915_WAIT_LOCKED;
 			   ),
 
-	    TP_printk("dev=%u, ring=%u, seqno=%u, blocking=%s",
-		      __entry->dev, __entry->ring,
-		      __entry->seqno, __entry->blocking ?  "yes (NB)" : "no")
+	    TP_printk("dev=%u, ring=%u, ctx=%u, seqno=%u, global=%u, blocking=%u, flags=0x%x",
+		      __entry->dev, __entry->ring, __entry->ctx, __entry->seqno,
+		      __entry->global, __entry->blocking, __entry->flags)
 );
 
 DEFINE_EVENT(i915_gem_request, i915_gem_request_wait_end,
-- 
2.9.3

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

[PATCH 4/8] drm/i915/tracepoints: Remove unused i915_gem_request_complete

[Tvrtko Ursulin]

From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

Tracepoint is not used and won't be suitable for its replacement.

Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
---
 drivers/gpu/drm/i915/i915_trace.h | 5 -----
 1 file changed, 5 deletions(-)

diff --git a/drivers/gpu/drm/i915/i915_trace.h b/drivers/gpu/drm/i915/i915_trace.h
index 916aadbb5389..7d941ac890b9 100644
--- a/drivers/gpu/drm/i915/i915_trace.h
+++ b/drivers/gpu/drm/i915/i915_trace.h
@@ -502,11 +502,6 @@ DEFINE_EVENT(i915_gem_request, i915_gem_request_retire,
 	    TP_ARGS(req)
 );
 
-DEFINE_EVENT(i915_gem_request, i915_gem_request_complete,
-	    TP_PROTO(struct drm_i915_gem_request *req),
-	    TP_ARGS(req)
-);
-
 TRACE_EVENT(i915_gem_request_wait_begin,
 	    TP_PROTO(struct drm_i915_gem_request *req, unsigned int flags),
 	    TP_ARGS(req, flags),
-- 
2.9.3

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

[PATCH 5/8] drm/i915/tracepoints: Add request submit and execute tracepoints

[Tvrtko Ursulin]

From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

These new tracepoints are emitted once the request is ready to
be submitted to the GPU and once the request is about to
be submitted to the GPU, respectively.

Former condition triggers as soon as all the fences and
dependencies have been resolved, and the latter once the
backend is about to submit it to the GPU.

New tracepoint are enabled via the new
DRM_I915_LOW_LEVEL_TRACEPOINTS Kconfig option which is disabled
by default to alleviate the performance impact concerns.

Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
---
 drivers/gpu/drm/i915/Kconfig.debug      | 11 +++++++++++
 drivers/gpu/drm/i915/i915_gem_request.c |  2 ++
 drivers/gpu/drm/i915/i915_trace.h       | 24 ++++++++++++++++++++++++
 3 files changed, 37 insertions(+)

diff --git a/drivers/gpu/drm/i915/Kconfig.debug b/drivers/gpu/drm/i915/Kconfig.debug
index 68ff072f8b76..e091809a9a9e 100644
--- a/drivers/gpu/drm/i915/Kconfig.debug
+++ b/drivers/gpu/drm/i915/Kconfig.debug
@@ -76,3 +76,14 @@ config DRM_I915_SELFTEST
 	  Recommended for driver developers only.
 
 	  If in doubt, say "N".
+
+config DRM_I915_LOW_LEVEL_TRACEPOINTS
+        bool "Enable low level request tracing events"
+        depends on DRM_I915
+        default n
+        help
+          Choose this option to turn on low level request tracing events.
+          This provides the ability to precisely monitor engine utilisation
+          and also analyze the request dependency resolving timeline.
+
+          If in doubt, say "N".
diff --git a/drivers/gpu/drm/i915/i915_gem_request.c b/drivers/gpu/drm/i915/i915_gem_request.c
index 543cef57972b..9a2b5c544c9d 100644
--- a/drivers/gpu/drm/i915/i915_gem_request.c
+++ b/drivers/gpu/drm/i915/i915_gem_request.c
@@ -449,6 +449,7 @@ submit_notify(struct i915_sw_fence *fence, enum i915_sw_fence_notify state)
 
 	switch (state) {
 	case FENCE_COMPLETE:
+		trace_i915_gem_request_submit(request);
 		request->engine->submit_request(request);
 		break;
 
@@ -468,6 +469,7 @@ execute_notify(struct i915_sw_fence *fence, enum i915_sw_fence_notify state)
 
 	switch (state) {
 	case FENCE_COMPLETE:
+		trace_i915_gem_request_execute(request);
 		break;
 
 	case FENCE_FREE:
diff --git a/drivers/gpu/drm/i915/i915_trace.h b/drivers/gpu/drm/i915/i915_trace.h
index 7d941ac890b9..ec523fdde01b 100644
--- a/drivers/gpu/drm/i915/i915_trace.h
+++ b/drivers/gpu/drm/i915/i915_trace.h
@@ -477,6 +477,30 @@ DEFINE_EVENT(i915_gem_request, i915_gem_request_add,
 	    TP_ARGS(req)
 );
 
+#if defined(CONFIG_DRM_I915_LOW_LEVEL_TRACEPOINTS)
+DEFINE_EVENT(i915_gem_request, i915_gem_request_submit,
+	     TP_PROTO(struct drm_i915_gem_request *req),
+	     TP_ARGS(req)
+);
+
+DEFINE_EVENT(i915_gem_request, i915_gem_request_execute,
+	     TP_PROTO(struct drm_i915_gem_request *req),
+	     TP_ARGS(req)
+);
+#else
+#if !defined(TRACE_HEADER_MULTI_READ)
+static inline void
+trace_i915_gem_request_submit(struct drm_i915_gem_request *req)
+{
+}
+
+static inline void
+trace_i915_gem_request_execute(struct drm_i915_gem_request *req)
+{
+}
+#endif
+#endif
+
 TRACE_EVENT(i915_gem_request_notify,
 	    TP_PROTO(struct intel_engine_cs *engine),
 	    TP_ARGS(engine),
-- 
2.9.3

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

[PATCH 6/8] drm/i915/tracepoints: Rename i915_gem_request_notify

[Tvrtko Ursulin]

From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

i915_gem_ring_notify is more appropriate since we do not have
the request information at this point, but it is simply a
signal from the engine that some request has been completed.

v2:
  * Always trace and log if there were any waiters.
  * Rename to intel_engine_notify. (Chris Wilson)

Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
---
 drivers/gpu/drm/i915/i915_irq.c   |  6 ++++--
 drivers/gpu/drm/i915/i915_trace.h | 13 ++++++++-----
 2 files changed, 12 insertions(+), 7 deletions(-)

diff --git a/drivers/gpu/drm/i915/i915_irq.c b/drivers/gpu/drm/i915/i915_irq.c
index 57fa1bf78a85..bc70e2c451b2 100644
--- a/drivers/gpu/drm/i915/i915_irq.c
+++ b/drivers/gpu/drm/i915/i915_irq.c
@@ -1033,10 +1033,12 @@ static void ironlake_rps_change_irq_handler(struct drm_i915_private *dev_priv)
 
 static void notify_ring(struct intel_engine_cs *engine)
 {
+	bool waiters;
+
 	atomic_inc(&engine->irq_count);
 	set_bit(ENGINE_IRQ_BREADCRUMB, &engine->irq_posted);
-	if (intel_engine_wakeup(engine))
-		trace_i915_gem_request_notify(engine);
+	waiters = intel_engine_wakeup(engine);
+	trace_intel_engine_notify(engine, waiters);
 }
 
 static void vlv_c0_read(struct drm_i915_private *dev_priv,
diff --git a/drivers/gpu/drm/i915/i915_trace.h b/drivers/gpu/drm/i915/i915_trace.h
index ec523fdde01b..e6bb342a8c60 100644
--- a/drivers/gpu/drm/i915/i915_trace.h
+++ b/drivers/gpu/drm/i915/i915_trace.h
@@ -501,24 +501,27 @@ trace_i915_gem_request_execute(struct drm_i915_gem_request *req)
 #endif
 #endif
 
-TRACE_EVENT(i915_gem_request_notify,
-	    TP_PROTO(struct intel_engine_cs *engine),
-	    TP_ARGS(engine),
+TRACE_EVENT(intel_engine_notify,
+	    TP_PROTO(struct intel_engine_cs *engine, bool waiters),
+	    TP_ARGS(engine, waiters),
 
 	    TP_STRUCT__entry(
 			     __field(u32, dev)
 			     __field(u32, ring)
 			     __field(u32, seqno)
+			     __field(bool, waiters)
 			     ),
 
 	    TP_fast_assign(
 			   __entry->dev = engine->i915->drm.primary->index;
 			   __entry->ring = engine->id;
 			   __entry->seqno = intel_engine_get_seqno(engine);
+			   __entry->waiters = waiters;
 			   ),
 
-	    TP_printk("dev=%u, ring=%u, seqno=%u",
-		      __entry->dev, __entry->ring, __entry->seqno)
+	    TP_printk("dev=%u, ring=%u, seqno=%u, waiters=%u",
+		      __entry->dev, __entry->ring, __entry->seqno,
+		      __entry->waiters)
 );
 
 DEFINE_EVENT(i915_gem_request, i915_gem_request_retire,
-- 
2.9.3

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

[PATCH 7/8] drm/i915/tracepoints: Add backend level request in and out tracepoints

[Tvrtko Ursulin]

From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

Two new tracepoints placed at the call sites where requests are
actually passed to the GPU enable userspace to track engine
utilisation.

These tracepoints are only enabled when the
DRM_I915_LOW_LEVEL_TRACEPOINTS Kconfig option is enabled.

v2: Fix compilation with !CONFIG_DRM_I915_LOW_LEVEL_TRACEPOINTS.

v3: Name global seqno consistently across tracepoints.

Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
---
 drivers/gpu/drm/i915/i915_guc_submission.c |  2 ++
 drivers/gpu/drm/i915/i915_trace.h          | 49 ++++++++++++++++++++++++++++++
 drivers/gpu/drm/i915/intel_lrc.c           |  4 +++
 3 files changed, 55 insertions(+)

diff --git a/drivers/gpu/drm/i915/i915_guc_submission.c b/drivers/gpu/drm/i915/i915_guc_submission.c
index 8ced9e26f075..beec88a30347 100644
--- a/drivers/gpu/drm/i915/i915_guc_submission.c
+++ b/drivers/gpu/drm/i915/i915_guc_submission.c
@@ -518,6 +518,8 @@ static void __i915_guc_submit(struct drm_i915_gem_request *rq)
 	if (i915_vma_is_map_and_fenceable(rq->ring->vma))
 		POSTING_READ_FW(GUC_STATUS);
 
+	trace_i915_gem_request_in(rq, 0);
+
 	b_ret = guc_ring_doorbell(client);
 
 	client->submissions[engine_id] += 1;
diff --git a/drivers/gpu/drm/i915/i915_trace.h b/drivers/gpu/drm/i915/i915_trace.h
index e6bb342a8c60..f730d9fe3d5e 100644
--- a/drivers/gpu/drm/i915/i915_trace.h
+++ b/drivers/gpu/drm/i915/i915_trace.h
@@ -487,6 +487,45 @@ DEFINE_EVENT(i915_gem_request, i915_gem_request_execute,
 	     TP_PROTO(struct drm_i915_gem_request *req),
 	     TP_ARGS(req)
 );
+
+DECLARE_EVENT_CLASS(i915_gem_request_hw,
+		    TP_PROTO(struct drm_i915_gem_request *req,
+			     unsigned int port),
+		    TP_ARGS(req, port),
+
+		    TP_STRUCT__entry(
+				     __field(u32, dev)
+				     __field(u32, ring)
+				     __field(u32, seqno)
+				     __field(u32, global_seqno)
+				     __field(u32, ctx)
+				     __field(u32, port)
+				    ),
+
+		    TP_fast_assign(
+			           __entry->dev = req->i915->drm.primary->index;
+			           __entry->ring = req->engine->id;
+			           __entry->ctx = req->ctx->hw_id;
+			           __entry->seqno = req->fence.seqno;
+			           __entry->global_seqno = req->global_seqno;
+			           __entry->port = port;
+			          ),
+
+		    TP_printk("dev=%u, ring=%u, ctx=%u, seqno=%u, global=%u, port=%u",
+			      __entry->dev, __entry->ring, __entry->ctx,
+			      __entry->seqno, __entry->global_seqno,
+			      __entry->port)
+);
+
+DEFINE_EVENT(i915_gem_request_hw, i915_gem_request_in,
+	     TP_PROTO(struct drm_i915_gem_request *req, unsigned int port),
+	     TP_ARGS(req, port)
+);
+
+DEFINE_EVENT(i915_gem_request_hw, i915_gem_request_out,
+	     TP_PROTO(struct drm_i915_gem_request *req, unsigned int port),
+	     TP_ARGS(req, port)
+);
 #else
 #if !defined(TRACE_HEADER_MULTI_READ)
 static inline void
@@ -498,6 +537,16 @@ static inline void
 trace_i915_gem_request_execute(struct drm_i915_gem_request *req)
 {
 }
+
+static inline void
+trace_i915_gem_request_in(struct drm_i915_gem_request *req, unsigned int port)
+{
+}
+
+static inline void
+trace_i915_gem_request_out(struct drm_i915_gem_request *req, unsigned int port)
+{
+}
 #endif
 #endif
 
diff --git a/drivers/gpu/drm/i915/intel_lrc.c b/drivers/gpu/drm/i915/intel_lrc.c
index d6b67be4715d..32cf93087e93 100644
--- a/drivers/gpu/drm/i915/intel_lrc.c
+++ b/drivers/gpu/drm/i915/intel_lrc.c
@@ -479,6 +479,7 @@ static void execlists_dequeue(struct intel_engine_cs *engine)
 		cursor->priotree.priority = INT_MAX;
 
 		__i915_gem_request_submit(cursor);
+		trace_i915_gem_request_in(cursor, port - engine->execlist_port);
 		last = cursor;
 		submit = true;
 	}
@@ -541,6 +542,7 @@ static void intel_lrc_irq_handler(unsigned long data)
 	struct intel_engine_cs *engine = (struct intel_engine_cs *)data;
 	struct execlist_port *port = engine->execlist_port;
 	struct drm_i915_private *dev_priv = engine->i915;
+	unsigned int portidx = 0;
 
 	intel_uncore_forcewake_get(dev_priv, engine->fw_domains);
 
@@ -593,6 +595,8 @@ static void intel_lrc_irq_handler(unsigned long data)
 				execlists_context_status_change(port[0].request,
 								INTEL_CONTEXT_SCHEDULE_OUT);
 
+				trace_i915_gem_request_out(port[0].request,
+							   portidx++);
 				i915_gem_request_put(port[0].request);
 				port[0] = port[1];
 				memset(&port[1], 0, sizeof(port[1]));
-- 
2.9.3

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

[PATCH 8/8] drm/i915/tracepoints: Add hw_id to context tracepoints

[Tvrtko Ursulin]

From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

It is useful to provide this info to match the one provided
in the request tracepoints.

Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
---
 drivers/gpu/drm/i915/i915_trace.h | 8 +++++---
 1 file changed, 5 insertions(+), 3 deletions(-)

diff --git a/drivers/gpu/drm/i915/i915_trace.h b/drivers/gpu/drm/i915/i915_trace.h
index f730d9fe3d5e..1fb5116dd3b7 100644
--- a/drivers/gpu/drm/i915/i915_trace.h
+++ b/drivers/gpu/drm/i915/i915_trace.h
@@ -748,17 +748,19 @@ DECLARE_EVENT_CLASS(i915_context,
 	TP_STRUCT__entry(
 			__field(u32, dev)
 			__field(struct i915_gem_context *, ctx)
+			__field(u32, hw_id)
 			__field(struct i915_address_space *, vm)
 	),
 
 	TP_fast_assign(
+			__entry->dev = ctx->i915->drm.primary->index;
 			__entry->ctx = ctx;
+			__entry->hw_id = ctx->hw_id;
 			__entry->vm = ctx->ppgtt ? &ctx->ppgtt->base : NULL;
-			__entry->dev = ctx->i915->drm.primary->index;
 	),
 
-	TP_printk("dev=%u, ctx=%p, ctx_vm=%p",
-		  __entry->dev, __entry->ctx, __entry->vm)
+	TP_printk("dev=%u, ctx=%p, ctx_vm=%p, hw_id=%u",
+		  __entry->dev, __entry->ctx, __entry->vm, __entry->hw_id)
 )
 
 DEFINE_EVENT(i915_context, i915_context_create,
-- 
2.9.3

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

Re: [PATCH 5/8] drm/i915/tracepoints: Add request submit and execute tracepoints

[Chris Wilson]

On Tue, Feb 21, 2017 at 09:13:47AM +0000, Tvrtko Ursulin wrote:
> @@ -468,6 +469,7 @@ execute_notify(struct i915_sw_fence *fence, enum i915_sw_fence_notify state)
>  
>  	switch (state) {
>  	case FENCE_COMPLETE:
> +		trace_i915_gem_request_execute(request);
>  		break;

Move to __i915_gem_request_submit(). (One less complication for me).
I guess you are thinking of changing its name to
__i915_gem_request_execute().
-Chris

-- 
Chris Wilson, Intel Open Source Technology Centre
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [PATCH 6/8] drm/i915/tracepoints: Rename i915_gem_request_notify

[Chris Wilson]

On Tue, Feb 21, 2017 at 09:13:48AM +0000, Tvrtko Ursulin wrote:
> From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> 
> i915_gem_ring_notify is more appropriate since we do not have
> the request information at this point, but it is simply a
> signal from the engine that some request has been completed.
> 
> v2:
>   * Always trace and log if there were any waiters.
>   * Rename to intel_engine_notify. (Chris Wilson)
> 
> Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> ---
>  drivers/gpu/drm/i915/i915_irq.c   |  6 ++++--
>  drivers/gpu/drm/i915/i915_trace.h | 13 ++++++++-----
>  2 files changed, 12 insertions(+), 7 deletions(-)
> 
> diff --git a/drivers/gpu/drm/i915/i915_irq.c b/drivers/gpu/drm/i915/i915_irq.c
> index 57fa1bf78a85..bc70e2c451b2 100644
> --- a/drivers/gpu/drm/i915/i915_irq.c
> +++ b/drivers/gpu/drm/i915/i915_irq.c
> @@ -1033,10 +1033,12 @@ static void ironlake_rps_change_irq_handler(struct drm_i915_private *dev_priv)
>  
>  static void notify_ring(struct intel_engine_cs *engine)
>  {
> +	bool waiters;
> +
>  	atomic_inc(&engine->irq_count);
>  	set_bit(ENGINE_IRQ_BREADCRUMB, &engine->irq_posted);
> -	if (intel_engine_wakeup(engine))
> -		trace_i915_gem_request_notify(engine);
> +	waiters = intel_engine_wakeup(engine);
> +	trace_intel_engine_notify(engine, waiters);

Close enough! (Here the waiters are sleepers, but that will change
shortly).
-Chris

-- 
Chris Wilson, Intel Open Source Technology Centre
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [PATCH 7/8] drm/i915/tracepoints: Add backend level request in and out tracepoints

[Chris Wilson]

On Tue, Feb 21, 2017 at 09:13:49AM +0000, Tvrtko Ursulin wrote:
> @@ -593,6 +595,8 @@ static void intel_lrc_irq_handler(unsigned long data)
>  				execlists_context_status_change(port[0].request,
>  								INTEL_CONTEXT_SCHEDULE_OUT);
>  
> +				trace_i915_gem_request_out(port[0].request,
> +							   portidx++);

Not seeing the value in portidx here, since if we process this as two
seperate interrupts, it always comes out as 0. And 0 is what we expect.
Knowing that we processed more than one completion event inside a single
tasklet?
-Chris

-- 
Chris Wilson, Intel Open Source Technology Centre
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [PATCH 3/8] drm/i915/tracepoints: Tidy i915_gem_request_wait_begin

[Chris Wilson]

On Tue, Feb 21, 2017 at 09:13:45AM +0000, Tvrtko Ursulin wrote:
> From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> 
> Provide the same information as the other request event classes.
> 
> v2: Pass in flags so we can properly report the blocking status.
>     (Chris Wilson)
> 
> v3: Log hex with 0x prefix for clarity.
> 
> Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> ---
>  drivers/gpu/drm/i915/i915_gem_request.c |  2 +-
>  drivers/gpu/drm/i915/i915_trace.h       | 21 +++++++++++++--------
>  2 files changed, 14 insertions(+), 9 deletions(-)
> 
> diff --git a/drivers/gpu/drm/i915/i915_gem_request.c b/drivers/gpu/drm/i915/i915_gem_request.c
> index a5fac40d2a4f..543cef57972b 100644
> --- a/drivers/gpu/drm/i915/i915_gem_request.c
> +++ b/drivers/gpu/drm/i915/i915_gem_request.c
> @@ -1092,7 +1092,7 @@ long i915_wait_request(struct drm_i915_gem_request *req,
>  	if (!timeout)
>  		return -ETIME;
>  
> -	trace_i915_gem_request_wait_begin(req);
> +	trace_i915_gem_request_wait_begin(req, flags);
>  
>  	if (!i915_sw_fence_done(&req->execute)) {
>  		timeout = __i915_request_wait_for_execute(req, flags, timeout);
> diff --git a/drivers/gpu/drm/i915/i915_trace.h b/drivers/gpu/drm/i915/i915_trace.h
> index d9ade8c38f92..916aadbb5389 100644
> --- a/drivers/gpu/drm/i915/i915_trace.h
> +++ b/drivers/gpu/drm/i915/i915_trace.h
> @@ -508,13 +508,16 @@ DEFINE_EVENT(i915_gem_request, i915_gem_request_complete,
>  );
>  
>  TRACE_EVENT(i915_gem_request_wait_begin,
> -	    TP_PROTO(struct drm_i915_gem_request *req),
> -	    TP_ARGS(req),
> +	    TP_PROTO(struct drm_i915_gem_request *req, unsigned int flags),
> +	    TP_ARGS(req, flags),
>  
>  	    TP_STRUCT__entry(
>  			     __field(u32, dev)
>  			     __field(u32, ring)
> +			     __field(u32, ctx)
>  			     __field(u32, seqno)
> +			     __field(u32, global)
> +			     __field(unsigned int, flags)
>  			     __field(bool, blocking)
>  			     ),
>  
> @@ -527,14 +530,16 @@ TRACE_EVENT(i915_gem_request_wait_begin,
>  	    TP_fast_assign(
>  			   __entry->dev = req->i915->drm.primary->index;
>  			   __entry->ring = req->engine->id;
> -			   __entry->seqno = req->global_seqno;
> -			   __entry->blocking =
> -				     mutex_is_locked(&req->i915->drm.struct_mutex);
> +			   __entry->ctx = req->ctx->hw_id;
> +			   __entry->seqno = req->fence.seqno;
> +			   __entry->global = req->global_seqno;
> +			   __entry->flags = flags;
> +			   __entry->blocking = flags & I915_WAIT_LOCKED;
>  			   ),
>  
> -	    TP_printk("dev=%u, ring=%u, seqno=%u, blocking=%s",
> -		      __entry->dev, __entry->ring,
> -		      __entry->seqno, __entry->blocking ?  "yes (NB)" : "no")
> +	    TP_printk("dev=%u, ring=%u, ctx=%u, seqno=%u, global=%u, blocking=%u, flags=0x%x",
> +		      __entry->dev, __entry->ring, __entry->ctx, __entry->seqno,
> +		      __entry->global, __entry->blocking, __entry->flags)

We don't need to store bool blocking, we can just pluck it out of flags
in the printk.

Hmm. How should we handle global changing value in the course of the
wait?
-Chris

-- 
Chris Wilson, Intel Open Source Technology Centre
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [PATCH 1/8] drm/i915/tracepoints: Tidy request event class

[Chris Wilson]

On Tue, Feb 21, 2017 at 09:13:43AM +0000, Tvrtko Ursulin wrote:
> From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> 
> At the moment only the global seqno is logged which is not set
> until the request is ready for submission.
> 
> Add the per-contex seqno and the context hardware id which are
> both interesting data points.
> 
> Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

Some minor conversation pieces, but on the whole, the series is
Reviewed-by: Chris Wilson <chris@chris-wilson.co.uk>
-Chris

-- 
Chris Wilson, Intel Open Source Technology Centre
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

✓ Fi.CI.BAT: success for series starting with [1/8] drm/i915/tracepoints: Tidy request event class

[Patchwork]

== Series Details ==

Series: series starting with [1/8] drm/i915/tracepoints: Tidy request event class
URL   : https://patchwork.freedesktop.org/series/19994/
State : success

== Summary ==

Series 19994v1 Series without cover letter
https://patchwork.freedesktop.org/api/1.0/series/19994/revisions/1/mbox/

fi-bdw-5557u     total:253  pass:242  dwarn:0   dfail:0   fail:0   skip:11 
fi-bsw-n3050     total:253  pass:214  dwarn:0   dfail:0   fail:0   skip:39 
fi-bxt-j4205     total:253  pass:234  dwarn:0   dfail:0   fail:0   skip:19 
fi-bxt-t5700     total:83   pass:70   dwarn:0   dfail:0   fail:0   skip:12 
fi-byt-j1900     total:253  pass:226  dwarn:0   dfail:0   fail:0   skip:27 
fi-byt-n2820     total:253  pass:222  dwarn:0   dfail:0   fail:0   skip:31 
fi-hsw-4770      total:253  pass:237  dwarn:0   dfail:0   fail:0   skip:16 
fi-hsw-4770r     total:253  pass:237  dwarn:0   dfail:0   fail:0   skip:16 
fi-ilk-650       total:253  pass:203  dwarn:0   dfail:0   fail:0   skip:50 
fi-ivb-3520m     total:253  pass:235  dwarn:0   dfail:0   fail:0   skip:18 
fi-ivb-3770      total:253  pass:235  dwarn:0   dfail:0   fail:0   skip:18 
fi-kbl-7500u     total:253  pass:235  dwarn:0   dfail:0   fail:0   skip:18 
fi-skl-6260u     total:253  pass:243  dwarn:0   dfail:0   fail:0   skip:10 
fi-skl-6700hq    total:253  pass:236  dwarn:0   dfail:0   fail:0   skip:17 
fi-skl-6700k     total:253  pass:231  dwarn:4   dfail:0   fail:0   skip:18 
fi-skl-6770hq    total:253  pass:243  dwarn:0   dfail:0   fail:0   skip:10 
fi-snb-2520m     total:253  pass:225  dwarn:0   dfail:0   fail:0   skip:28 
fi-snb-2600      total:253  pass:224  dwarn:0   dfail:0   fail:0   skip:29 

0a03ea9496b49746b4964d05cc1f483385d1df8a drm-tip: 2017y-02m-20d-17h-19m-56s UTC integration manifest
ccaaf31 drm/i915/tracepoints: Add hw_id to context tracepoints
f9c512c drm/i915/tracepoints: Add backend level request in and out tracepoints
213162b drm/i915/tracepoints: Rename i915_gem_request_notify
9af3ce4 drm/i915/tracepoints: Add request submit and execute tracepoints
d5d8820 drm/i915/tracepoints: Remove unused i915_gem_request_complete
4925b43 drm/i915/tracepoints: Tidy i915_gem_request_wait_begin
78983bb drm/i915/tracepoints: Adjust i915_gem_ring_dispatch
05219be drm/i915/tracepoints: Tidy request event class

== Logs ==

For more details see: https://intel-gfx-ci.01.org/CI/Patchwork_3906/
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [PATCH 3/8] drm/i915/tracepoints: Tidy i915_gem_request_wait_begin

[Tvrtko Ursulin]

On 21/02/2017 09:50, Chris Wilson wrote:
> On Tue, Feb 21, 2017 at 09:13:45AM +0000, Tvrtko Ursulin wrote:
>> From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>>
>> Provide the same information as the other request event classes.
>>
>> v2: Pass in flags so we can properly report the blocking status.
>>     (Chris Wilson)
>>
>> v3: Log hex with 0x prefix for clarity.
>>
>> Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>> ---
>>  drivers/gpu/drm/i915/i915_gem_request.c |  2 +-
>>  drivers/gpu/drm/i915/i915_trace.h       | 21 ++++++++++++--------
>>  2 files changed, 14 insertions(+), 9 deletions(-)
>>
>> diff --git a/drivers/gpu/drm/i915/i915_gem_request.c b/drivers/gpu/drm/i915/i915_gem_request.c
>> index a5fac40d2a4f..543cef57972b 100644
>> --- a/drivers/gpu/drm/i915/i915_gem_request.c
>> +++ b/drivers/gpu/drm/i915/i915_gem_request.c
>> @@ -1092,7 +1092,7 @@ long i915_wait_request(struct drm_i915_gem_request *req,
>>  	if (!timeout)
>>  		return -ETIME;
>>
>> -	trace_i915_gem_request_wait_begin(req);
>> +	trace_i915_gem_request_wait_begin(req, flags);
>>
>>  	if (!i915_sw_fence_done(&req->execute)) {
>>  		timeout = __i915_request_wait_for_execute(req, flags, timeout);
>> diff --git a/drivers/gpu/drm/i915/i915_trace.h b/drivers/gpu/drm/i915/i915_trace.h
>> index d9ade8c38f92..916aadbb5389 100644
>> --- a/drivers/gpu/drm/i915/i915_trace.h
>> +++ b/drivers/gpu/drm/i915/i915_trace.h
>> @@ -508,13 +508,16 @@ DEFINE_EVENT(i915_gem_request, i915_gem_request_complete,
>>  );
>>
>>  TRACE_EVENT(i915_gem_request_wait_begin,
>> -	    TP_PROTO(struct drm_i915_gem_request *req),
>> -	    TP_ARGS(req),
>> +	    TP_PROTO(struct drm_i915_gem_request *req, unsigned int flags),
>> +	    TP_ARGS(req, flags),
>>
>>  	    TP_STRUCT__entry(
>>  			     __field(u32, dev)
>>  			     __field(u32, ring)
>> +			     __field(u32, ctx)
>>  			     __field(u32, seqno)
>> +			     __field(u32, global)
>> +			     __field(unsigned int, flags)
>>  			     __field(bool, blocking)
>>  			     ),
>>
>> @@ -527,14 +530,16 @@ TRACE_EVENT(i915_gem_request_wait_begin,
>>  	    TP_fast_assign(
>>  			   __entry->dev = req->i915->drm.primary->index;
>>  			   __entry->ring = req->engine->id;
>> -			   __entry->seqno = req->global_seqno;
>> -			   __entry->blocking =
>> -				     mutex_is_locked(&req->i915->drm.struct_mutex);
>> +			   __entry->ctx = req->ctx->hw_id;
>> +			   __entry->seqno = req->fence.seqno;
>> +			   __entry->global = req->global_seqno;
>> +			   __entry->flags = flags;
>> +			   __entry->blocking = flags & I915_WAIT_LOCKED;
>>  			   ),
>>
>> -	    TP_printk("dev=%u, ring=%u, seqno=%u, blocking=%s",
>> -		      __entry->dev, __entry->ring,
>> -		      __entry->seqno, __entry->blocking ?  "yes (NB)" : "no")
>> +	    TP_printk("dev=%u, ring=%u, ctx=%u, seqno=%u, global=%u, blocking=%u, flags=0x%x",
>> +		      __entry->dev, __entry->ring, __entry->ctx, __entry->seqno,
>> +		      __entry->global, __entry->blocking, __entry->flags)
>
> We don't need to store bool blocking, we can just pluck it out of flags
> in the printk.

Ok.

> Hmm. How should we handle global changing value in the course of the
> wait?

How would you do that? It will get logged at the end of the wait and 
ctx/ring/seqno can be used as an unique identifier to match the two ends.

Regards,

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

Re: [PATCH 5/8] drm/i915/tracepoints: Add request submit and execute tracepoints

[Tvrtko Ursulin]

On 21/02/2017 09:41, Chris Wilson wrote:
> On Tue, Feb 21, 2017 at 09:13:47AM +0000, Tvrtko Ursulin wrote:
>> @@ -468,6 +469,7 @@ execute_notify(struct i915_sw_fence *fence, enum i915_sw_fence_notify state)
>>
>>  	switch (state) {
>>  	case FENCE_COMPLETE:
>> +		trace_i915_gem_request_execute(request);
>>  		break;
>
> Move to __i915_gem_request_submit(). (One less complication for me).

Ack.

> I guess you are thinking of changing its name to
> __i915_gem_request_execute().

No, why? The idea is i915_gem_request_submit -> "ready for execution / 
dependencies resolved" and i915_gem_request_execute -> "about to be 
submitted to execution backend".

Regards,

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

Re: [PATCH 3/8] drm/i915/tracepoints: Tidy i915_gem_request_wait_begin

[Chris Wilson]

On Tue, Feb 21, 2017 at 10:10:09AM +0000, Tvrtko Ursulin wrote:
> 
> On 21/02/2017 09:50, Chris Wilson wrote:
> >Hmm. How should we handle global changing value in the course of the
> >wait?
> 
> How would you do that? It will get logged at the end of the wait and
> ctx/ring/seqno can be used as an unique identifier to match the two
> ends.

I was wondering what value global had in the early tracepoint. It tells
us if the wait begins before the request was executed. Then at the end,
you can see if it was interrupted by seeing if global changed.

It will definitely help in the trivial cases of reading through the logs
and tieing the waits to the execution - I just forsee some confusion
occasionally :)
-Chris

-- 
Chris Wilson, Intel Open Source Technology Centre
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [PATCH 7/8] drm/i915/tracepoints: Add backend level request in and out tracepoints

[Tvrtko Ursulin]

On 21/02/2017 09:47, Chris Wilson wrote:
> On Tue, Feb 21, 2017 at 09:13:49AM +0000, Tvrtko Ursulin wrote:
>> @@ -593,6 +595,8 @@ static void intel_lrc_irq_handler(unsigned long data)
>>  				execlists_context_status_change(port[0].request,
>>  								INTEL_CONTEXT_SCHEDULE_OUT);
>>
>> +				trace_i915_gem_request_out(port[0].request,
>> +							   portidx++);
>
> Not seeing the value in portidx here, since if we process this as two
> seperate interrupts, it always comes out as 0. And 0 is what we expect.
> Knowing that we processed more than one completion event inside a single
> tasklet?

Yes, but I know that is very unlikely. In all the traces I have laying 
around here is is 546921 to 3 for port being zero. :)

Perhaps the fact can also be derived from the timestamps on trace events 
but it would be a bit of a heuristics. Sounds safer to just report the 
fact at source, but I can also remove it if you want.

Regards,

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

Re: [PATCH 5/8] drm/i915/tracepoints: Add request submit and execute tracepoints

[Chris Wilson]

On Tue, Feb 21, 2017 at 10:14:12AM +0000, Tvrtko Ursulin wrote:
> 
> 
> On 21/02/2017 09:41, Chris Wilson wrote:
> >On Tue, Feb 21, 2017 at 09:13:47AM +0000, Tvrtko Ursulin wrote:
> >>@@ -468,6 +469,7 @@ execute_notify(struct i915_sw_fence *fence, enum i915_sw_fence_notify state)
> >>
> >> 	switch (state) {
> >> 	case FENCE_COMPLETE:
> >>+		trace_i915_gem_request_execute(request);
> >> 		break;
> >
> >Move to __i915_gem_request_submit(). (One less complication for me).
> 
> Ack.
> 
> >I guess you are thinking of changing its name to
> >__i915_gem_request_execute().
> 
> No, why? The idea is i915_gem_request_submit -> "ready for execution
> / dependencies resolved" and i915_gem_request_execute -> "about to
> be submitted to execution backend".

Right. Only "i915_gem_request_execute" is currently called
__i915_gem_request_submit().

add_request ->
  [deps complete] ->
    submit_notify ->
      backend->submit() ->
	[some time passes] ->
	  __i915_gem_request_submit() 

You've convinced me that __i915_gem_request_execute is a step forward
from __i915_gem_request_submit.
-Chris

-- 
Chris Wilson, Intel Open Source Technology Centre
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [PATCH 7/8] drm/i915/tracepoints: Add backend level request in and out tracepoints

[Chris Wilson]

On Tue, Feb 21, 2017 at 10:22:40AM +0000, Tvrtko Ursulin wrote:
> 
> On 21/02/2017 09:47, Chris Wilson wrote:
> >On Tue, Feb 21, 2017 at 09:13:49AM +0000, Tvrtko Ursulin wrote:
> >>@@ -593,6 +595,8 @@ static void intel_lrc_irq_handler(unsigned long data)
> >> 				execlists_context_status_change(port[0].request,
> >> 								INTEL_CONTEXT_SCHEDULE_OUT);
> >>
> >>+				trace_i915_gem_request_out(port[0].request,
> >>+							   portidx++);
> >
> >Not seeing the value in portidx here, since if we process this as two
> >seperate interrupts, it always comes out as 0. And 0 is what we expect.
> >Knowing that we processed more than one completion event inside a single
> >tasklet?
> 
> Yes, but I know that is very unlikely. In all the traces I have
> laying around here is is 546921 to 3 for port being zero. :)
> 
> Perhaps the fact can also be derived from the timestamps on trace
> events but it would be a bit of a heuristics. Sounds safer to just
> report the fact at source, but I can also remove it if you want.

I think I'd prefer it without portidx++. I just am not seeing the value
in it, whereas in[0] or in[1] clearly does have value. I also don't
think we are limiting ourselves to never adding extra information here.
-Chris

-- 
Chris Wilson, Intel Open Source Technology Centre
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

[PATCH v4 3/8] drm/i915/tracepoints: Tidy i915_gem_request_wait_begin

[Tvrtko Ursulin]

From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

Provide the same information as the other request event classes.

v2: Pass in flags so we can properly report the blocking status.
    (Chris Wilson)

v3: Log hex with 0x prefix for clarity.

v4: Derive blocking status from flags. (Chris Wilson)

Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
---
 drivers/gpu/drm/i915/i915_gem_request.c |  2 +-
 drivers/gpu/drm/i915/i915_trace.h       | 22 +++++++++++++---------
 2 files changed, 14 insertions(+), 10 deletions(-)

diff --git a/drivers/gpu/drm/i915/i915_gem_request.c b/drivers/gpu/drm/i915/i915_gem_request.c
index a5fac40d2a4f..543cef57972b 100644
--- a/drivers/gpu/drm/i915/i915_gem_request.c
+++ b/drivers/gpu/drm/i915/i915_gem_request.c
@@ -1092,7 +1092,7 @@ long i915_wait_request(struct drm_i915_gem_request *req,
 	if (!timeout)
 		return -ETIME;
 
-	trace_i915_gem_request_wait_begin(req);
+	trace_i915_gem_request_wait_begin(req, flags);
 
 	if (!i915_sw_fence_done(&req->execute)) {
 		timeout = __i915_request_wait_for_execute(req, flags, timeout);
diff --git a/drivers/gpu/drm/i915/i915_trace.h b/drivers/gpu/drm/i915/i915_trace.h
index d9ade8c38f92..557195b56087 100644
--- a/drivers/gpu/drm/i915/i915_trace.h
+++ b/drivers/gpu/drm/i915/i915_trace.h
@@ -508,14 +508,16 @@ DEFINE_EVENT(i915_gem_request, i915_gem_request_complete,
 );
 
 TRACE_EVENT(i915_gem_request_wait_begin,
-	    TP_PROTO(struct drm_i915_gem_request *req),
-	    TP_ARGS(req),
+	    TP_PROTO(struct drm_i915_gem_request *req, unsigned int flags),
+	    TP_ARGS(req, flags),
 
 	    TP_STRUCT__entry(
 			     __field(u32, dev)
 			     __field(u32, ring)
+			     __field(u32, ctx)
 			     __field(u32, seqno)
-			     __field(bool, blocking)
+			     __field(u32, global)
+			     __field(unsigned int, flags)
 			     ),
 
 	    /* NB: the blocking information is racy since mutex_is_locked
@@ -527,14 +529,16 @@ TRACE_EVENT(i915_gem_request_wait_begin,
 	    TP_fast_assign(
 			   __entry->dev = req->i915->drm.primary->index;
 			   __entry->ring = req->engine->id;
-			   __entry->seqno = req->global_seqno;
-			   __entry->blocking =
-				     mutex_is_locked(&req->i915->drm.struct_mutex);
+			   __entry->ctx = req->ctx->hw_id;
+			   __entry->seqno = req->fence.seqno;
+			   __entry->global = req->global_seqno;
+			   __entry->flags = flags;
 			   ),
 
-	    TP_printk("dev=%u, ring=%u, seqno=%u, blocking=%s",
-		      __entry->dev, __entry->ring,
-		      __entry->seqno, __entry->blocking ?  "yes (NB)" : "no")
+	    TP_printk("dev=%u, ring=%u, ctx=%u, seqno=%u, global=%u, blocking=%u, flags=0x%x",
+		      __entry->dev, __entry->ring, __entry->ctx, __entry->seqno,
+		      __entry->global, !!(__entry->flags & I915_WAIT_LOCKED),
+		      __entry->flags)
 );
 
 DEFINE_EVENT(i915_gem_request, i915_gem_request_wait_end,
-- 
2.9.3

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

[PATCH v2 5/8] drm/i915/tracepoints: Add request submit and execute tracepoints

[Tvrtko Ursulin]

From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

These new tracepoints are emitted once the request is ready to
be submitted to the GPU and once the request is about to
be submitted to the GPU, respectively.

Former condition triggers as soon as all the fences and
dependencies have been resolved, and the latter once the
backend is about to submit it to the GPU.

New tracepoint are enabled via the new
DRM_I915_LOW_LEVEL_TRACEPOINTS Kconfig option which is disabled
by default to alleviate the performance impact concerns.

v2: Move execute tracepoint to __i915_gem_request_submit.
    (Chris Wilson)

Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
---
 drivers/gpu/drm/i915/Kconfig.debug      | 11 +++++++++++
 drivers/gpu/drm/i915/i915_gem_request.c |  2 ++
 drivers/gpu/drm/i915/i915_trace.h       | 24 ++++++++++++++++++++++++
 3 files changed, 37 insertions(+)

diff --git a/drivers/gpu/drm/i915/Kconfig.debug b/drivers/gpu/drm/i915/Kconfig.debug
index 68ff072f8b76..e091809a9a9e 100644
--- a/drivers/gpu/drm/i915/Kconfig.debug
+++ b/drivers/gpu/drm/i915/Kconfig.debug
@@ -76,3 +76,14 @@ config DRM_I915_SELFTEST
 	  Recommended for driver developers only.
 
 	  If in doubt, say "N".
+
+config DRM_I915_LOW_LEVEL_TRACEPOINTS
+        bool "Enable low level request tracing events"
+        depends on DRM_I915
+        default n
+        help
+          Choose this option to turn on low level request tracing events.
+          This provides the ability to precisely monitor engine utilisation
+          and also analyze the request dependency resolving timeline.
+
+          If in doubt, say "N".
diff --git a/drivers/gpu/drm/i915/i915_gem_request.c b/drivers/gpu/drm/i915/i915_gem_request.c
index 543cef57972b..12b06e055490 100644
--- a/drivers/gpu/drm/i915/i915_gem_request.c
+++ b/drivers/gpu/drm/i915/i915_gem_request.c
@@ -426,6 +426,7 @@ void __i915_gem_request_submit(struct drm_i915_gem_request *request)
 	spin_unlock(&request->timeline->lock);
 
 	i915_sw_fence_commit(&request->execute);
+	trace_i915_gem_request_execute(request);
 }
 
 void i915_gem_request_submit(struct drm_i915_gem_request *request)
@@ -449,6 +450,7 @@ submit_notify(struct i915_sw_fence *fence, enum i915_sw_fence_notify state)
 
 	switch (state) {
 	case FENCE_COMPLETE:
+		trace_i915_gem_request_submit(request);
 		request->engine->submit_request(request);
 		break;
 
diff --git a/drivers/gpu/drm/i915/i915_trace.h b/drivers/gpu/drm/i915/i915_trace.h
index 85accea70b4d..e3c0f9e94488 100644
--- a/drivers/gpu/drm/i915/i915_trace.h
+++ b/drivers/gpu/drm/i915/i915_trace.h
@@ -477,6 +477,30 @@ DEFINE_EVENT(i915_gem_request, i915_gem_request_add,
 	    TP_ARGS(req)
 );
 
+#if defined(CONFIG_DRM_I915_LOW_LEVEL_TRACEPOINTS)
+DEFINE_EVENT(i915_gem_request, i915_gem_request_submit,
+	     TP_PROTO(struct drm_i915_gem_request *req),
+	     TP_ARGS(req)
+);
+
+DEFINE_EVENT(i915_gem_request, i915_gem_request_execute,
+	     TP_PROTO(struct drm_i915_gem_request *req),
+	     TP_ARGS(req)
+);
+#else
+#if !defined(TRACE_HEADER_MULTI_READ)
+static inline void
+trace_i915_gem_request_submit(struct drm_i915_gem_request *req)
+{
+}
+
+static inline void
+trace_i915_gem_request_execute(struct drm_i915_gem_request *req)
+{
+}
+#endif
+#endif
+
 TRACE_EVENT(i915_gem_request_notify,
 	    TP_PROTO(struct intel_engine_cs *engine),
 	    TP_ARGS(engine),
-- 
2.9.3

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

[PATCH v4 7/8] drm/i915/tracepoints: Add backend level request in and out tracepoints

[Tvrtko Ursulin]

From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

Two new tracepoints placed at the call sites where requests are
actually passed to the GPU enable userspace to track engine
utilisation.

These tracepoints are only enabled when the
DRM_I915_LOW_LEVEL_TRACEPOINTS Kconfig option is enabled.

v2: Fix compilation with !CONFIG_DRM_I915_LOW_LEVEL_TRACEPOINTS.

v3: Name global seqno consistently across tracepoints.

v4: Remove port info from request out tracepoint. (Chris Wilson)

Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
---
 drivers/gpu/drm/i915/i915_guc_submission.c |  2 ++
 drivers/gpu/drm/i915/i915_trace.h          | 49 ++++++++++++++++++++++++++++++
 drivers/gpu/drm/i915/intel_lrc.c           |  2 ++
 3 files changed, 53 insertions(+)

diff --git a/drivers/gpu/drm/i915/i915_guc_submission.c b/drivers/gpu/drm/i915/i915_guc_submission.c
index 8ced9e26f075..beec88a30347 100644
--- a/drivers/gpu/drm/i915/i915_guc_submission.c
+++ b/drivers/gpu/drm/i915/i915_guc_submission.c
@@ -518,6 +518,8 @@ static void __i915_guc_submit(struct drm_i915_gem_request *rq)
 	if (i915_vma_is_map_and_fenceable(rq->ring->vma))
 		POSTING_READ_FW(GUC_STATUS);
 
+	trace_i915_gem_request_in(rq, 0);
+
 	b_ret = guc_ring_doorbell(client);
 
 	client->submissions[engine_id] += 1;
diff --git a/drivers/gpu/drm/i915/i915_trace.h b/drivers/gpu/drm/i915/i915_trace.h
index ca2facac4bca..0a5f27b34a77 100644
--- a/drivers/gpu/drm/i915/i915_trace.h
+++ b/drivers/gpu/drm/i915/i915_trace.h
@@ -487,6 +487,45 @@ DEFINE_EVENT(i915_gem_request, i915_gem_request_execute,
 	     TP_PROTO(struct drm_i915_gem_request *req),
 	     TP_ARGS(req)
 );
+
+DECLARE_EVENT_CLASS(i915_gem_request_hw,
+		    TP_PROTO(struct drm_i915_gem_request *req,
+			     unsigned int port),
+		    TP_ARGS(req, port),
+
+		    TP_STRUCT__entry(
+				     __field(u32, dev)
+				     __field(u32, ring)
+				     __field(u32, seqno)
+				     __field(u32, global_seqno)
+				     __field(u32, ctx)
+				     __field(u32, port)
+				    ),
+
+		    TP_fast_assign(
+			           __entry->dev = req->i915->drm.primary->index;
+			           __entry->ring = req->engine->id;
+			           __entry->ctx = req->ctx->hw_id;
+			           __entry->seqno = req->fence.seqno;
+			           __entry->global_seqno = req->global_seqno;
+			           __entry->port = port;
+			          ),
+
+		    TP_printk("dev=%u, ring=%u, ctx=%u, seqno=%u, global=%u, port=%u",
+			      __entry->dev, __entry->ring, __entry->ctx,
+			      __entry->seqno, __entry->global_seqno,
+			      __entry->port)
+);
+
+DEFINE_EVENT(i915_gem_request_hw, i915_gem_request_in,
+	     TP_PROTO(struct drm_i915_gem_request *req, unsigned int port),
+	     TP_ARGS(req, port)
+);
+
+DEFINE_EVENT(i915_gem_request, i915_gem_request_out,
+	     TP_PROTO(struct drm_i915_gem_request *req),
+	     TP_ARGS(req)
+);
 #else
 #if !defined(TRACE_HEADER_MULTI_READ)
 static inline void
@@ -498,6 +537,16 @@ static inline void
 trace_i915_gem_request_execute(struct drm_i915_gem_request *req)
 {
 }
+
+static inline void
+trace_i915_gem_request_in(struct drm_i915_gem_request *req, unsigned int port)
+{
+}
+
+static inline void
+trace_i915_gem_request_out(struct drm_i915_gem_request *req)
+{
+}
 #endif
 #endif
 
diff --git a/drivers/gpu/drm/i915/intel_lrc.c b/drivers/gpu/drm/i915/intel_lrc.c
index d6b67be4715d..cec140127dfe 100644
--- a/drivers/gpu/drm/i915/intel_lrc.c
+++ b/drivers/gpu/drm/i915/intel_lrc.c
@@ -479,6 +479,7 @@ static void execlists_dequeue(struct intel_engine_cs *engine)
 		cursor->priotree.priority = INT_MAX;
 
 		__i915_gem_request_submit(cursor);
+		trace_i915_gem_request_in(cursor, port - engine->execlist_port);
 		last = cursor;
 		submit = true;
 	}
@@ -593,6 +594,7 @@ static void intel_lrc_irq_handler(unsigned long data)
 				execlists_context_status_change(port[0].request,
 								INTEL_CONTEXT_SCHEDULE_OUT);
 
+				trace_i915_gem_request_out(port[0].request);
 				i915_gem_request_put(port[0].request);
 				port[0] = port[1];
 				memset(&port[1], 0, sizeof(port[1]));
-- 
2.9.3

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

✓ Fi.CI.BAT: success for series starting with [1/8] drm/i915/tracepoints: Tidy request event class (rev4)

[Patchwork]

== Series Details ==

Series: series starting with [1/8] drm/i915/tracepoints: Tidy request event class (rev4)
URL   : https://patchwork.freedesktop.org/series/19994/
State : success

== Summary ==

Series 19994v4 Series without cover letter
https://patchwork.freedesktop.org/api/1.0/series/19994/revisions/4/mbox/

fi-bdw-5557u     total:253  pass:242  dwarn:0   dfail:0   fail:0   skip:11 
fi-bsw-n3050     total:253  pass:214  dwarn:0   dfail:0   fail:0   skip:39 
fi-bxt-j4205     total:253  pass:234  dwarn:0   dfail:0   fail:0   skip:19 
fi-bxt-t5700     total:83   pass:70   dwarn:0   dfail:0   fail:0   skip:12 
fi-byt-j1900     total:253  pass:226  dwarn:0   dfail:0   fail:0   skip:27 
fi-byt-n2820     total:253  pass:222  dwarn:0   dfail:0   fail:0   skip:31 
fi-hsw-4770      total:253  pass:237  dwarn:0   dfail:0   fail:0   skip:16 
fi-hsw-4770r     total:253  pass:237  dwarn:0   dfail:0   fail:0   skip:16 
fi-ilk-650       total:253  pass:203  dwarn:0   dfail:0   fail:0   skip:50 
fi-ivb-3520m     total:253  pass:235  dwarn:0   dfail:0   fail:0   skip:18 
fi-ivb-3770      total:253  pass:235  dwarn:0   dfail:0   fail:0   skip:18 
fi-kbl-7500u     total:253  pass:235  dwarn:0   dfail:0   fail:0   skip:18 
fi-skl-6260u     total:253  pass:243  dwarn:0   dfail:0   fail:0   skip:10 
fi-skl-6700hq    total:253  pass:236  dwarn:0   dfail:0   fail:0   skip:17 
fi-skl-6700k     total:253  pass:231  dwarn:4   dfail:0   fail:0   skip:18 
fi-skl-6770hq    total:253  pass:243  dwarn:0   dfail:0   fail:0   skip:10 
fi-snb-2520m     total:253  pass:225  dwarn:0   dfail:0   fail:0   skip:28 
fi-snb-2600      total:253  pass:224  dwarn:0   dfail:0   fail:0   skip:29 

0a03ea9496b49746b4964d05cc1f483385d1df8a drm-tip: 2017y-02m-20d-17h-19m-56s UTC integration manifest
fdf3bad drm/i915/tracepoints: Add hw_id to context tracepoints
6d071e3 drm/i915/tracepoints: Add backend level request in and out tracepoints
ef730d9 drm/i915/tracepoints: Rename i915_gem_request_notify
8091bc4 drm/i915/tracepoints: Add request submit and execute tracepoints
ef253f3 drm/i915/tracepoints: Remove unused i915_gem_request_complete
7430dbb drm/i915/tracepoints: Tidy i915_gem_request_wait_begin
fd9296e drm/i915/tracepoints: Adjust i915_gem_ring_dispatch
db2870b drm/i915/tracepoints: Tidy request event class

== Logs ==

For more details see: https://intel-gfx-ci.01.org/CI/Patchwork_3910/
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [PATCH 1/8] drm/i915/tracepoints: Tidy request event class

[Chris Wilson]

On Tue, Feb 21, 2017 at 09:51:51AM +0000, Chris Wilson wrote:
> On Tue, Feb 21, 2017 at 09:13:43AM +0000, Tvrtko Ursulin wrote:
> > From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> > 
> > At the moment only the global seqno is logged which is not set
> > until the request is ready for submission.
> > 
> > Add the per-contex seqno and the context hardware id which are
> > both interesting data points.
> > 
> > Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> 
> Some minor conversation pieces, but on the whole, the series is
> Reviewed-by: Chris Wilson <chris@chris-wilson.co.uk>

And the updates lgtm, so
Reviewed-by: Chris Wilson <chris@chris-wilson.co.uk>
for all
-Chris

-- 
Chris Wilson, Intel Open Source Technology Centre
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: ✓ Fi.CI.BAT: success for series starting with [1/8] drm/i915/tracepoints: Tidy request event class (rev4)

[Tvrtko Ursulin]

On 21/02/2017 11:52, Patchwork wrote:
> == Series Details ==
>
> Series: series starting with [1/8] drm/i915/tracepoints: Tidy request event class (rev4)
> URL   : https://patchwork.freedesktop.org/series/19994/
> State : success
>
> == Summary ==
>
> Series 19994v4 Series without cover letter
> https://patchwork.freedesktop.org/api/1.0/series/19994/revisions/4/mbox/
>
> fi-bdw-5557u     total:253  pass:242  dwarn:0   dfail:0   fail:0   skip:11
> fi-bsw-n3050     total:253  pass:214  dwarn:0   dfail:0   fail:0   skip:39
> fi-bxt-j4205     total:253  pass:234  dwarn:0   dfail:0   fail:0   skip:19
> fi-bxt-t5700     total:83   pass:70   dwarn:0   dfail:0   fail:0   skip:12
> fi-byt-j1900     total:253  pass:226  dwarn:0   dfail:0   fail:0   skip:27
> fi-byt-n2820     total:253  pass:222  dwarn:0   dfail:0   fail:0   skip:31
> fi-hsw-4770      total:253  pass:237  dwarn:0   dfail:0   fail:0   skip:16
> fi-hsw-4770r     total:253  pass:237  dwarn:0   dfail:0   fail:0   skip:16
> fi-ilk-650       total:253  pass:203  dwarn:0   dfail:0   fail:0   skip:50
> fi-ivb-3520m     total:253  pass:235  dwarn:0   dfail:0   fail:0   skip:18
> fi-ivb-3770      total:253  pass:235  dwarn:0   dfail:0   fail:0   skip:18
> fi-kbl-7500u     total:253  pass:235  dwarn:0   dfail:0   fail:0   skip:18
> fi-skl-6260u     total:253  pass:243  dwarn:0   dfail:0   fail:0   skip:10
> fi-skl-6700hq    total:253  pass:236  dwarn:0   dfail:0   fail:0   skip:17
> fi-skl-6700k     total:253  pass:231  dwarn:4   dfail:0   fail:0   skip:18
> fi-skl-6770hq    total:253  pass:243  dwarn:0   dfail:0   fail:0   skip:10
> fi-snb-2520m     total:253  pass:225  dwarn:0   dfail:0   fail:0   skip:28
> fi-snb-2600      total:253  pass:224  dwarn:0   dfail:0   fail:0   skip:29
>
> 0a03ea9496b49746b4964d05cc1f483385d1df8a drm-tip: 2017y-02m-20d-17h-19m-56s UTC integration manifest
> fdf3bad drm/i915/tracepoints: Add hw_id to context tracepoints
> 6d071e3 drm/i915/tracepoints: Add backend level request in and out tracepoints
> ef730d9 drm/i915/tracepoints: Rename i915_gem_request_notify
> 8091bc4 drm/i915/tracepoints: Add request submit and execute tracepoints
> ef253f3 drm/i915/tracepoints: Remove unused i915_gem_request_complete
> 7430dbb drm/i915/tracepoints: Tidy i915_gem_request_wait_begin
> fd9296e drm/i915/tracepoints: Adjust i915_gem_ring_dispatch
> db2870b drm/i915/tracepoints: Tidy request event class

Pushed, thanks for the review.

Regards,

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