Re: [Intel-gfx] [PATCH 2/2] drm/i915: Embellish wait_end trace
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 b...@bwidawsk.net Other than the debate in the earlier patch, this looks fine. -Chris -- Chris Wilson, Intel Open Source Technology Centre ___ Intel-gfx mailing list Intel-gfx@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/intel-gfx
Re: [Intel-gfx] [PATCH 2/2] drm/i915: Embellish wait_end trace
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 b...@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 ___ Intel-gfx mailing list Intel-gfx@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/intel-gfx
Re: [Intel-gfx] [PATCH 2/2] drm/i915: Embellish wait_end trace
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 b...@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 ___ Intel-gfx mailing list Intel-gfx@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/intel-gfx
[Intel-gfx] [PATCH 2/2] drm/i915: Embellish wait_end trace
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 b...@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
___
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/intel-gfx
