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

[Ben Widawsky <ben@bwidawsk.net>]

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