[PATCH 1/2] drm/i915: timespec_sub should already be normalized

[PATCH 1/2] drm/i915: timespec_sub should already be normalized

[Ben Widawsky]

So don't bother checking it again.
This was introduced:
commit b361237bcc7cea1d99f770490120d8bc2aed7777
Author: Chris Wilson <chris@chris-wilson.co.uk>
Date:   Fri Aug 24 09:35:08 2012 +0100

    drm/i915: Juggle code order to ease flow of the next patch

Cc: Chris Wilson <chris@chris-wilson.co.uk>
Signed-off-by: Ben Widawsky <ben@bwidawsk.net>
---
 drivers/gpu/drm/i915/i915_gem.c | 2 --
 1 file changed, 2 deletions(-)

diff --git a/drivers/gpu/drm/i915/i915_gem.c b/drivers/gpu/drm/i915/i915_gem.c
index ac349ff..17f7ac9 100644
--- a/drivers/gpu/drm/i915/i915_gem.c
+++ b/drivers/gpu/drm/i915/i915_gem.c
@@ -1243,8 +1243,6 @@ static int __wait_seqno(struct intel_engine_cs *ring, u32 seqno,
 	if (timeout) {
 		struct timespec sleep_time = timespec_sub(now, before);
 		*timeout = timespec_sub(*timeout, sleep_time);
-		if (!timespec_valid(timeout)) /* i.e. negative time remains */
-			set_normalized_timespec(timeout, 0, 0);
 	}
 
 	return ret;
-- 
2.0.2

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

[Ben Widawsky]

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

Re: [PATCH 1/2] drm/i915: timespec_sub should already be normalized

[Chris Wilson]

On Tue, Jul 29, 2014 at 01:14:29PM -0700, Ben Widawsky wrote:
> So don't bother checking it again.
> This was introduced:
> commit b361237bcc7cea1d99f770490120d8bc2aed7777
> Author: Chris Wilson <chris@chris-wilson.co.uk>
> Date:   Fri Aug 24 09:35:08 2012 +0100
> 
>     drm/i915: Juggle code order to ease flow of the next patch
> 
> Cc: Chris Wilson <chris@chris-wilson.co.uk>
> Signed-off-by: Ben Widawsky <ben@bwidawsk.net>

Ah, it is not so much that the timeout may be unnormalized, but that it
*may* be negative.
-Chris

-- 
Chris Wilson, Intel Open Source Technology Centre

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

[Chris Wilson]

On Tue, Jul 29, 2014 at 01:14:30PM -0700, Ben Widawsky wrote:
> 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.

Right, the key point is that since the advent of the wait_begin/_end
pair is that we now allow concurrent non-blocking waits.
 
> 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>

Other than the debate in the earlier patch, this looks fine.
-Chris

-- 
Chris Wilson, Intel Open Source Technology Centre

Re: [PATCH 1/2] drm/i915: timespec_sub should already be normalized

[Ben Widawsky]

On Wed, Jul 30, 2014 at 07:15:05AM +0100, Chris Wilson wrote:
> On Tue, Jul 29, 2014 at 01:14:29PM -0700, Ben Widawsky wrote:
> > So don't bother checking it again.
> > This was introduced:
> > commit b361237bcc7cea1d99f770490120d8bc2aed7777
> > Author: Chris Wilson <chris@chris-wilson.co.uk>
> > Date:   Fri Aug 24 09:35:08 2012 +0100
> > 
> >     drm/i915: Juggle code order to ease flow of the next patch
> > 
> > Cc: Chris Wilson <chris@chris-wilson.co.uk>
> > Signed-off-by: Ben Widawsky <ben@bwidawsk.net>
> 
> Ah, it is not so much that the timeout may be unnormalized, but that it
> *may* be negative.
> -Chris
> 
> -- 
> Chris Wilson, Intel Open Source Technology Centre

>From looking at the code, I thought it didn't matter (ie. I thought it
dtrt regardless of negative). However, I just wrote a little test, and
you are correct. It is needed. Sorry about that.

-- 
Ben Widawsky, Intel Open Source Technology Center

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

[Ben Widawsky]

On Wed, Jul 30, 2014 at 07:19:26AM +0100, Chris Wilson wrote:
> On Tue, Jul 29, 2014 at 01:14:30PM -0700, Ben Widawsky wrote:
> > 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.
> 
> Right, the key point is that since the advent of the wait_begin/_end
> pair is that we now allow concurrent non-blocking waits.
>  
> > 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>
> 
> Other than the debate in the earlier patch, this looks fine.
> -Chris
> 

I actually don't think wait_begin is a terribly interesting event after
this patch BTW, but I didn't want to rock the boat too much. If you
agree, I can send that one as well.

-- 
Ben Widawsky, Intel Open Source Technology Center

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

[Chris Wilson]

On Tue, Jul 29, 2014 at 11:33:43PM -0700, Ben Widawsky wrote:
> On Wed, Jul 30, 2014 at 07:19:26AM +0100, Chris Wilson wrote:
> > On Tue, Jul 29, 2014 at 01:14:30PM -0700, Ben Widawsky wrote:
> > > 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.
> > 
> > Right, the key point is that since the advent of the wait_begin/_end
> > pair is that we now allow concurrent non-blocking waits.
> >  
> > > 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>
> > 
> > Other than the debate in the earlier patch, this looks fine.
> > -Chris
> > 
> 
> I actually don't think wait_begin is a terribly interesting event after
> this patch BTW, but I didn't want to rock the boat too much. If you
> agree, I can send that one as well.

The only advantage is that wait_begin is before the wait, which may be
significant - espcially in a time based profile.
-Chris

-- 
Chris Wilson, Intel Open Source Technology Centre