Massive power regression going 3.4->3.5

Commit Message

James Bottomley Aug. 1, 2012, 8:06 a.m. UTC

On Tue, 2012-07-31 at 20:24 +0100, Chris Wilson wrote:
> On Tue, 31 Jul 2012 11:14:17 +0100, Chris Wilson <[e-mail]> wrote:
> > On Tue, 31 Jul 2012 10:57:10 +0100, James Bottomley <[e-mail]> wrote:
> > > > When did you inspect the debug files? One effect I can imagine is that
> > > > if your system was previously stuck at RPn and never upclocking the GPU
> > > > when X starts. The question would then be what is preventing the GPU
> > > > from reaching its lowest power state again.
> > > 
> > > After I logged into an xfce4 session and powertop showed idle had been
> > > reached.
> 
> That you are using xfce4 makes the use of semaphores for pageflips as
> being the root cause even more suspect. Pageflips are only used for a
> fullscreen DRI client caalling SwapBuffers, to my knowledge xfce4 does
> not use DRI at all - its compositing manager is XRender based if you
> happen to be using it.
> 
> Please can you try the small patch to disable the use of semaphores for
> pageflips and see if the regression remains (which I judge it will...):
> 
> diff --git a/drivers/gpu/drm/i915/i915_gem.c
> b/drivers/gpu/drm/i915/i915_gem.c
> index 5c4657a..f301f2f 100644
> --- a/drivers/gpu/drm/i915/i915_gem.c
> +++ b/drivers/gpu/drm/i915/i915_gem.c
> @@ -3067,7 +3067,7 @@ i915_gem_object_pin_to_display_plane(struct drm_i915_gem_o
>                 return ret;
>  
>         if (pipelined != obj->ring) {
> -               ret = i915_gem_object_sync(obj, pipelined);
> +               ret = i915_gem_object_wait_rendering(obj);
>                 if (ret)
>                         return ret;
>         }

Your patch doesn't apply ... I think because in v3.5 this line is
displaced by about 200 lines in the file.

patching file drivers/gpu/drm/i915/i915_gem.c
Hunk #1 FAILED at 3067.
1 out of 1 hunk FAILED -- saving rejects to file
drivers/gpu/drm/i915/i915_gem.c.rej

I got the attached to apply and it doesn't really improve the idle power
much (12.5W).

James

---

Comments

Chris Wilson Aug. 1, 2012, 8:16 a.m. UTC | #1

On Wed, 01 Aug 2012 09:06:12 +0100, James Bottomley <[e-mail]> 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?
-Chris

James Bottomley Aug. 1, 2012, 8:45 a.m. UTC | #2

On Wed, 2012-08-01 at 09:16 +0100, Chris Wilson wrote:
> On Wed, 01 Aug 2012 09:06:12 +0100, James Bottomley <[e-mail]> 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

James

Chris Wilson Aug. 1, 2012, 8:58 a.m. UTC | #3

On Wed, 01 Aug 2012 09:45:04 +0100, James Bottomley <[e-mail]> wrote:
> On Wed, 2012-08-01 at 09:16 +0100, Chris Wilson wrote:
> > On Wed, 01 Aug 2012 09:06:12 +0100, James Bottomley <[e-mail]> 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.
-Chris

James Bottomley Aug. 1, 2012, 9:07 a.m. UTC | #4

On Wed, 2012-08-01 at 09:58 +0100, Chris Wilson wrote:
> On Wed, 01 Aug 2012 09:45:04 +0100, James Bottomley <[e-mail]> wrote:
> > On Wed, 2012-08-01 at 09:16 +0100, Chris Wilson wrote:
> > > On Wed, 01 Aug 2012 09:06:12 +0100, James Bottomley <[e-mail]> 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.

Sandybridge mobile doesn't have an iommu (or at least, if it does, the
kernel doesn't detect it).

> 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.

With or without i915_semaphore=0?

James

Chris Wilson Aug. 1, 2012, 9:14 a.m. UTC | #5

On Wed, 01 Aug 2012 10:07:23 +0100, James Bottomley <[e-mail]> wrote:
> > 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.
> 
> With or without i915_semaphore=0?

With semaphores enabled so that we can see if they are active during the
idle period or if merely having used them at some point is enough to
trigger the issue. And to see if the pm counters bear any relation to
reality.
-Chris

James Bottomley Aug. 1, 2012, 9:38 a.m. UTC | #6

On Wed, 2012-08-01 at 09:58 +0100, Chris Wilson wrote:
> On Wed, 01 Aug 2012 09:45:04 +0100, James Bottomley <[e-mail]> wrote:
> > On Wed, 2012-08-01 at 09:16 +0100, Chris Wilson wrote:
> > > On Wed, 01 Aug 2012 09:06:12 +0100, James Bottomley <[e-mail]> 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,

OK, what is trace-cmd?  It looks similar to perf tools ... is that it?

James


>  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.
> -Chris
>

Chris Wilson Aug. 1, 2012, 10:06 a.m. UTC | #7

On Wed, 01 Aug 2012 10:38:36 +0100, James Bottomley <[e-mail]> wrote:
> On Wed, 2012-08-01 at 09:58 +0100, Chris Wilson wrote:
> > On Wed, 01 Aug 2012 09:45:04 +0100, James Bottomley <[e-mail]> wrote:
> > > On Wed, 2012-08-01 at 09:16 +0100, Chris Wilson wrote:
> > > > On Wed, 01 Aug 2012 09:06:12 +0100, James Bottomley <[e-mail]> 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,
> 
> OK, what is trace-cmd?  It looks similar to perf tools ... is that it?

Yes, it is roughly equivalent and you should be able to achieve the same
with perf trace - except I haven't done it before so I don't have quick
advice on how to drive it. :)
-Chris

James Bottomley Aug. 1, 2012, 10:08 a.m. UTC | #8

On Wed, 2012-08-01 at 09:58 +0100, Chris Wilson wrote:
> On Wed, 01 Aug 2012 09:45:04 +0100, James Bottomley <[e-mail]> wrote:
> > On Wed, 2012-08-01 at 09:16 +0100, Chris Wilson wrote:
> > > On Wed, 01 Aug 2012 09:06:12 +0100, James Bottomley <[e-mail]> 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

---

jejb@dabdike> cat /sys/kernel/debug/dri/0/i915_cur_delayinfo
GT_PERF_STATUS: 0x000016c7
RPSTAT1: 0x0004160d
Render p-state ratio: 22
Render p-state VID: 199
Render p-state limit: 255
CAGF: 1100MHz
RP CUR UP EI: 96491us
RP CUR UP: 252us
RP PREV UP: 0us
RP CUR DOWN EI: 0us
RP CUR DOWN: 513us
RP PREV DOWN: 0us
Lowest (RPN) frequency: 650MHz
Nominal (RP1) frequency: 650MHz
Max non-overclocked (RP0) frequency: 1100MHz
jejb@dabdike> cat /sys/kernel/debug/dri/0/i915_drpc_info
RC information inaccurate because somebody holds a forcewake reference 
Video Turbo Mode: yes
HW control enabled: yes
SW control enabled: no
RC1e Enabled: no
RC6 Enabled: yes
Deep RC6 Enabled: no
Deepest RC6 Enabled: no
Current RC state: on
Core Power Down: no
RC6 "Locked to RPn" residency since boot: 0
RC6 residency since boot: 360123443
RC6+ residency since boot: 0
RC6++ residency since boot: 0
jejb@dabdike> ./git/trace-cmd/trace-cmd record -e i915 sleep 10s
trace-cmd: Permission denied
  opening '/sys/kernel/debug/tracing/tracing_on'
jejb@dabdike> sudo ./git/trace-cmd/trace-cmd record -e i915 sleep 10s
/sys/kernel/debug/tracing/events/i915/filter
/sys/kernel/debug/tracing/events/*/i915/filter
Kernel buffer statistics:
  Note: "entries" are the entries left in the kernel ring buffer and are not
        recorded in the trace data. They should all be zero.

CPU: 0
entries: 0
overrun: 0
commit overrun: 0
bytes: 1080
oldest event ts:  1076.352744
now ts:  1076.651396

CPU: 1
entries: 0
overrun: 0
commit overrun: 0
bytes: 932
oldest event ts:  1067.676405
now ts:  1076.651452

CPU: 2
entries: 0
overrun: 0
commit overrun: 0
bytes: 3784
oldest event ts:  1076.090225
now ts:  1076.651501

CPU: 3
entries: 0
overrun: 0
commit overrun: 0
bytes: 0
oldest event ts: 15281105439.050279
now ts:  1076.651550

CPU0 data recorded at offset=0x39a000
    221184 bytes in size
CPU1 data recorded at offset=0x3d0000
    16384 bytes in size
CPU2 data recorded at offset=0x3d4000
    32768 bytes in size
CPU3 data recorded at offset=0x3dc000
    0 bytes in size
jejb@dabdike> cat /sys/kernel/debug/dri/0/i915_cur_delayinfo
GT_PERF_STATUS: 0x000016c7
RPSTAT1: 0x0004160d
Render p-state ratio: 22
Render p-state VID: 199
Render p-state limit: 255
CAGF: 1100MHz
RP CUR UP EI: 49171us
RP CUR UP: 122us
RP PREV UP: 0us
RP CUR DOWN EI: 0us
RP CUR DOWN: 562us
RP PREV DOWN: 0us
Lowest (RPN) frequency: 650MHz
Nominal (RP1) frequency: 650MHz
Max non-overclocked (RP0) frequency: 1100MHz
jejb@dabdike> cat /sys/kernel/debug/dri/0/i915_drpc_info
RC information accurate: yes
Video Turbo Mode: yes
HW control enabled: yes
SW control enabled: no
RC1e Enabled: no
RC6 Enabled: yes
Deep RC6 Enabled: no
Deepest RC6 Enabled: no
Current RC state: RC6
Core Power Down: no
RC6 "Locked to RPn" residency since boot: 0
RC6 residency since boot: 362653127
RC6+ residency since boot: 0
RC6++ residency since boot: 0

bwidawsk Aug. 2, 2012, 5:08 a.m. UTC | #9

On 2012-08-01 03:06, Chris Wilson wrote:
> On Wed, 01 Aug 2012 10:38:36 +0100, James Bottomley
> <[e-mail]> wrote:
>> On Wed, 2012-08-01 at 09:58 +0100, Chris Wilson wrote:
>> > On Wed, 01 Aug 2012 09:45:04 +0100, James Bottomley 
>> <[e-mail]> wrote:
>> > > On Wed, 2012-08-01 at 09:16 +0100, Chris Wilson wrote:
>> > > > On Wed, 01 Aug 2012 09:06:12 +0100, James Bottomley 
>> <[e-mail]> 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,
>>
>> OK, what is trace-cmd?  It looks similar to perf tools ... is that 
>> it?
>
> Yes, it is roughly equivalent and you should be able to achieve the 
> same
> with perf trace - except I haven't done it before so I don't have 
> quick
> advice on how to drive it. :)
> -Chris

Should be something like:
perf record -f -g -e i915:* -a

James Bottomley Aug. 2, 2012, 7:20 a.m. UTC | #10

On Wed, 2012-08-01 at 22:08 -0700, bwidawsk wrote:
> On 2012-08-01 03:06, Chris Wilson wrote:
> > On Wed, 01 Aug 2012 10:38:36 +0100, James Bottomley
> > <[e-mail]> wrote:
> >> On Wed, 2012-08-01 at 09:58 +0100, Chris Wilson wrote:
> >> > On Wed, 01 Aug 2012 09:45:04 +0100, James Bottomley 
> >> <[e-mail]> wrote:
> >> > > On Wed, 2012-08-01 at 09:16 +0100, Chris Wilson wrote:
> >> > > > On Wed, 01 Aug 2012 09:06:12 +0100, James Bottomley 
> >> <[e-mail]> 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,
> >>
> >> OK, what is trace-cmd?  It looks similar to perf tools ... is that 
> >> it?
> >
> > Yes, it is roughly equivalent and you should be able to achieve the 
> > same
> > with perf trace - except I haven't done it before so I don't have 
> > quick
> > advice on how to drive it. :)
> > -Chris
> 
> Should be something like:
> perf record -f -g -e i915:* -a

I already sent the output of trace-cmd ... is that enough?

James

Ben Widawsky Aug. 2, 2012, 12:07 p.m. UTC | #11

On 2012-08-02 00:20, James Bottomley wrote:
> On Wed, 2012-08-01 at 22:08 -0700, bwidawsk wrote:
>> On 2012-08-01 03:06, Chris Wilson wrote:
>> > On Wed, 01 Aug 2012 10:38:36 +0100, James Bottomley
>> > <[e-mail]> wrote:
>> >> On Wed, 2012-08-01 at 09:58 +0100, Chris Wilson wrote:
>> >> > On Wed, 01 Aug 2012 09:45:04 +0100, James Bottomley
>> >> <[e-mail]> wrote:
>> >> > > On Wed, 2012-08-01 at 09:16 +0100, Chris Wilson wrote:
>> >> > > > On Wed, 01 Aug 2012 09:06:12 +0100, James Bottomley
>> >> <[e-mail]> 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,
>> >>
>> >> OK, what is trace-cmd?  It looks similar to perf tools ... is 
>> that
>> >> it?
>> >
>> > Yes, it is roughly equivalent and you should be able to achieve 
>> the
>> > same
>> > with perf trace - except I haven't done it before so I don't have
>> > quick
>> > advice on how to drive it. :)
>> > -Chris
>>
>> Should be something like:
>> perf record -f -g -e i915:* -a
>
> I already sent the output of trace-cmd ... is that enough?
>
> James

Yes, should do. Have we already eliminated the obvious? GPU semaphores 
will
give time back to the GPU clients normally waiting on such things, X, 
XFCE,
whatever else. It'd probably be handy to begin investigating what those 
guys
are doing with their new extra time. Chris, this is what I was getting 
at on
IRC the other day. What do you think?

Daniel Vetter Aug. 5, 2012, 8:36 p.m. UTC | #12

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 <[e-mail]> wrote:
> > > On Wed, 2012-08-01 at 09:16 +0100, Chris Wilson wrote:
> > > > On Wed, 01 Aug 2012 09:06:12 +0100, James Bottomley <[e-mail]> 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 ...)

Also, you need to attach the output of trace-cmd report (like with perf),
so that we see the tracepoints in detail.

Another quick thing to confirm: What is the power consumption on the old
kernel when booting with i915.i915_semaphores=1?

Thanks, Daniel

James Bottomley Aug. 7, 2012, 8:43 p.m. UTC | #13

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 <[e-mail]> wrote:
> > > > On Wed, 2012-08-01 at 09:16 +0100, Chris Wilson wrote:
> > > > > On Wed, 01 Aug 2012 09:06:12 +0100, James Bottomley <[e-mail]> 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.

> 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.

> 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 <[e-mail]>
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 <[e-mail]>
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.

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.

James

Ben Widawsky Aug. 8, 2012, 2:44 a.m. UTC | #14

On 2012-08-07 13:43, 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 
>> <[e-mail]> wrote:
>> > > > On Wed, 2012-08-01 at 09:16 +0100, Chris Wilson wrote:
>> > > > > On Wed, 01 Aug 2012 09:06:12 +0100, James Bottomley 
>> <[e-mail]> 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.
>
>> 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.
>
>> 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 <[e-mail]>
> 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 <[e-mail]>
> 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.
>
> 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.
>
> James

Hi James. Would you mind filing a bug on this? In trying to reproduce 
this issue, I ran into another similar, but different issue ie. not 
resolved with semaphores=0. The issue I see can be reproduced with 
intel-gpu-tools/tests/sysfs_rc6_residency. That test is basically the 
same thing as what Chris/Daniel was asking for earlier with the drpc 
debugfs file info. In any case, it would be good to centralize all the 
data we've collected somewhere other than a mailing list/attachments.

http://intellinuxgraphics.org/how_to_report_bug.html

P.S. sorry if you already filed a bug somewhere earlier in the thread. 
I've been having mail problems.

Daniel Vetter Aug. 8, 2012, 7:22 a.m. UTC | #15

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 <[e-mail]> wrote:
> > > > > On Wed, 2012-08-01 at 09:16 +0100, Chris Wilson wrote:
> > > > > > On Wed, 01 Aug 2012 09:06:12 +0100, James Bottomley <[e-mail]> 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 <[e-mail]>
> 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 <[e-mail]>
> 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

Patch

diff --git a/drivers/gpu/drm/i915/i915_gem.c b/drivers/gpu/drm/i915/i915_gem.c
index 288d7b8..2f3f279 100644
--- a/drivers/gpu/drm/i915/i915_gem.c
+++ b/drivers/gpu/drm/i915/i915_gem.c
@@ -2869,7 +2869,7 @@  i915_gem_object_pin_to_display_plane(struct drm_i915_gem_object *obj,
 		return ret;
 
 	if (pipelined != obj->ring) {
-		ret = i915_gem_object_sync(obj, pipelined);
+		ret = i915_gem_object_wait_rendering(obj);
 		if (ret)
 			return ret;
 	}