Massive power regression going 3.4->3.5

[Daniel Vetter]

On Tue, Aug 07, 2012 at 09:43:48PM +0100, James Bottomley wrote:
> On Sun, 2012-08-05 at 22:36 +0200, Daniel Vetter wrote:
> > On Wed, Aug 01, 2012 at 11:08:19AM +0100, James Bottomley wrote:
> > > On Wed, 2012-08-01 at 09:58 +0100, Chris Wilson wrote:
> > > > On Wed, 01 Aug 2012 09:45:04 +0100, James Bottomley <James.Bottomley at HansenPartnership.com> wrote:
> > > > > On Wed, 2012-08-01 at 09:16 +0100, Chris Wilson wrote:
> > > > > > On Wed, 01 Aug 2012 09:06:12 +0100, James Bottomley <James.Bottomley at HansenPartnership.com> wrote:
> > > > > > > I got the attached to apply and it doesn't really improve the idle power
> > > > > > > much (12.5W).
> > > > > > 
> > > > > > That's good to know. Next step is to try overriding i915.semaphores.
> > > > > > Can you please test with i915.semaphores=0 and i915.semaphores=1?
> > > > > 
> > > > > There's not much point doing i915_semaphores=1 since that's the default
> > > > > on gen 6 hardware, but i915_semaphores=0 recovers and idle power of
> > > > > ~6.5W
> > > > 
> > > > It is only the default if iommu is off, and changing the default
> > > > was one of the side-effects of the patch you bisected.
> > > > 
> > > > Can you please login to the desktop, let it idle, record
> > > > /sys/kernel/debug/dri/0/i915_cur_delayinfo and .../i915_drpc_info.
> > > > Then trace-cmd record -e i915 sleep 10s, and follow up with a new pair
> > > > of /sys/kernel/debug/dri/0/i915_cur_delayinfo and .../i915_drpc_info.
> > > > 
> > > > This will let us see whether the pm counters are truly advancing and
> > > > what activity the driver is performing whilst idle.
> > > 
> > > OK, so here it is
> > > 
> > > James
> > 
> > Hm, if I haven't botched the math, you have a rc6 residency of about 320
> > seconds between the two cats of drpc_info. Can you please script this so
> > that we have exactly 10s in between? (Aside: 3.6 has a neat interface for
> > rc6 residency in sysfs ...)
> 
> You botched the maths, I think.  The three cats after the sleep was
> three up arrows ... if it went over 11s I'd be surprised.

Oops, indeed I've botched it. Redoing it you have an rc6 residency of
3.2s. Which is clearly not enough :(
> 
> > Also, you need to attach the output of trace-cmd report (like with perf),
> > so that we see the tracepoints in detail.
> 
> You mean you want the full trace.dat file rather than what the output
> summary says?  I can, but it's 800k compressed which is probably over
> the list limit ... I can upload it somewhere when I get back from
> holiday next Monday.

Well, I need the decoded stuff from trace report, but yeah, the entire
thing, please.

> > Another quick thing to confirm: What is the power consumption on the old
> > kernel when booting with i915.i915_semaphores=1?
> 
> It idles at around 13W, which means the history of the problem must be
> this:
> 
> What looks to have happened seems to be because of a merge failure in
> drm:
> 
> In 3.2 Keith Packard disabled semaphores on sandybridge with
> 
> commit ebbd857e6b9a92c0aff4aacd1b1d2361d888633e
> Author: Keith Packard <keithp at keithp.com>
> Date:   Mon Dec 26 17:02:10 2011 -0800
> 
>     drm/i915: Disable semaphores by default on SNB
> 
> Because of an apparent bug causing a GPU hang.
> 
> I think this is what gave me the power savings in 3.4 when the PCI layer
> was ready for it.
> 
> It got re-enabled accidentally in 3.5 by a mismerge of 
> 
> commit 2911a35b2e4eb87ec48d03aeb11f019e51ae3c0d
> Author: Ben Widawsky <ben at bwidawsk.net>
> Date:   Thu Apr 5 14:47:36 2012 -0700
> 
>     drm/i915: use semaphores for the display plane
> 
> Because that puts back the pre ebbd857e6b9a92c0aff4aacd1b1d2361d888633e
> semaphore enabling code, but in a different place, which is probably why
> it wasn't spotted, so semaphores got re-enabled on sandybridge.

Well, I wanted to enable semaphores by default for 3.5 anyway since we've
tracked down the root-cause of these hangs. So it got enabled in that
commit by accident due to a rebase goof-up, but it's not enabled by
accident in 3.5.

> Perhaps what we should be doing is verifying that semaphores aren't
> sucking the same 6W of power on ivybridge and if not, just re-disable
> them on sandybridge, since we'll have to do that anyway to re-apply the
> bug fix.

Ben has already been running around with a killawatt and we don't see any
additional power consumption and we can't even reproduce your results on
snb. The thing is we have two ways to synchronize the gpu engines:
- blocking the thread that submits the rendering for a new engine until
  all dependencies have completed rendering on other engines.
- not blocking the submitting process, but using hw semaphores.

In both cases (assuming userspace submits equal amounts of gpu rendering)
we keep the gpu out of rc6 while doing so, but without semaphores we also
wake up the cpu (we get tons of interrupts from the gpu when blocking,
which we otherwise disable) and generally stall userspace. So there's
something fishy going on your system.

To avoid botching up the math we have neat rc6 residency counters in
sysfs at /sys/class/drm/card0/power/ (should be in 3.5). To check that the
issue is really that the gpu doesn't go into rc6 often enough can you
please check what percentage of rc6 residency at idle you get with
- no X (iirc that worked powerconsumption-wise in both cases)
- xfce running with semaphores=0 and semsphores=1
- maybe a different desktop (or just X running with xterm and no blinking
  cursor) to see whether it's some funny side-effect of using xfce.

Thanks, Daniel
-- 
Daniel Vetter
Mail: daniel at ffwll.ch
Mobile: +41 (0)79 365 57 48