| Message ID | 1406664870-29970-2-git-send-email-benjamin.widawsky@intel.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
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
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.
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
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,
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(-)