[PATCH 2/2] drm/i915: Embellish wait_end trace

[Ben Widawsky <benjamin.widawsky@intel.com>]

This adds two new data points to the trace event, wait time, and whether
or not the event slept. Both of these should already be obtainable
through various means. This patch just makes the data more accessible.

Wait is obtainable with the current code by matching seqnos in
begin/end. In simple cases where begin/ends are always paired, this is
trivial. However, if you queue up multiple begins/ends, it can get
confusing. We're already calculating wait time, so it's trivially added
here. This patch also provides the slightly more accurate wait_time as
opposed to the timestamps from the tracepoint. It's observable, but just
noise.

The second bit of information, whether or not the operation slept is
helpful in determining where time went. This is probably also obtainable
through the scheduler events. However, we have the information easily at
our fingertips, we may as well give it out.

This results in an event which looks like:
gem_gtt_hog   409 [000]    32.012641: i915:i915_gem_request_wait_end: dev=0, ring=3, seqno=4294963203, duration=0.000368225 (slept=yes)

While here, rename sleep_time to wait_time since the verb sleep hasn't
been true for a long time (several conditions exist where it won't
sleep).

Signed-off-by: Ben Widawsky <ben@bwidawsk.net>
---
 drivers/gpu/drm/i915/i915_gem.c   | 12 +++++++-----
 drivers/gpu/drm/i915/i915_trace.h | 29 ++++++++++++++++++++++++++---
 2 files changed, 33 insertions(+), 8 deletions(-)

diff --git a/drivers/gpu/drm/i915/i915_gem.c b/drivers/gpu/drm/i915/i915_gem.c
index 17f7ac9..bb7fed6 100644
--- a/drivers/gpu/drm/i915/i915_gem.c
+++ b/drivers/gpu/drm/i915/i915_gem.c
@@ -1161,6 +1161,8 @@ static int __wait_seqno(struct intel_engine_cs *ring, u32 seqno,
 	struct timespec before, now;
 	DEFINE_WAIT(wait);
 	unsigned long timeout_expire;
+	struct timespec wait_time;
+	bool slept = false;
 	int ret;
 
 	WARN(!intel_irqs_enabled(dev_priv), "IRQs disabled");
@@ -1216,6 +1218,7 @@ static int __wait_seqno(struct intel_engine_cs *ring, u32 seqno,
 			break;
 		}
 
+		slept = true;
 		timer.function = NULL;
 		if (timeout || missed_irq(dev_priv, ring)) {
 			unsigned long expire;
@@ -1233,17 +1236,16 @@ static int __wait_seqno(struct intel_engine_cs *ring, u32 seqno,
 		}
 	}
 	getrawmonotonic(&now);
-	trace_i915_gem_request_wait_end(ring, seqno);
 
 	if (!irq_test_in_progress)
 		ring->irq_put(ring);
 
 	finish_wait(&ring->irq_queue, &wait);
+	wait_time = timespec_sub(now, before);
+	trace_i915_gem_request_wait_end(ring, seqno, wait_time, slept);
 
-	if (timeout) {
-		struct timespec sleep_time = timespec_sub(now, before);
-		*timeout = timespec_sub(*timeout, sleep_time);
-	}
+	if (timeout)
+		*timeout = timespec_sub(*timeout, wait_time);
 
 	return ret;
 }
diff --git a/drivers/gpu/drm/i915/i915_trace.h b/drivers/gpu/drm/i915/i915_trace.h
index f5aa006..0936066 100644
--- a/drivers/gpu/drm/i915/i915_trace.h
+++ b/drivers/gpu/drm/i915/i915_trace.h
@@ -476,9 +476,32 @@ TRACE_EVENT(i915_gem_request_wait_begin,
 		      __entry->blocking ?  "yes (NB)" : "no")
 );
 
-DEFINE_EVENT(i915_gem_request, i915_gem_request_wait_end,
-	    TP_PROTO(struct intel_engine_cs *ring, u32 seqno),
-	    TP_ARGS(ring, seqno)
+TRACE_EVENT(i915_gem_request_wait_end,
+	    TP_PROTO(struct intel_engine_cs *ring, u32 seqno, struct timespec delta, bool slept),
+	    TP_ARGS(ring, seqno, delta, slept),
+
+	    TP_STRUCT__entry(
+			     __field(u32, dev)
+			     __field(u32, ring)
+			     __field(u32, seqno)
+			     __field(long long, s)
+			     __field(long, ns)
+			     __field(bool, slept)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->dev = ring->dev->primary->index;
+			   __entry->ring = ring->id;
+			   __entry->seqno = seqno;
+			   __entry->s = (long long)delta.tv_sec;
+			   __entry->ns = delta.tv_nsec;
+			   __entry->slept = slept;
+			   ),
+
+	    TP_printk("dev=%u, ring=%u, seqno=%u, duration=%lld.%.9ld (slept=%s)",
+		      __entry->dev, __entry->ring, __entry->seqno,
+		      __entry->s, __entry->ns,
+		      __entry->slept ?  "yes" : "no")
 );
 
 DECLARE_EVENT_CLASS(i915_ring,
-- 
2.0.2