i915 PSR test results and cursor lag

i915 PSR test results and cursor lag

[Andy Lutomirski]

[-- Attachment #1: Type: text/plain, Size: 1259 bytes --]

Hi-

As requested in your blog post, I tested PSR.  I see something like
2.69W with PSR off and 2.17W with PSR on.  Screen blanking,
suspend/resume, and the contents of the screen all seem okay.  This is
a Dell XPS 13 9350, i.e.:

System Information
        Manufacturer: Dell Inc.
        Product Name: XPS 13 9350

EDID is attached.

*However*, I do see one unfortunate side effect of turning on PSR.  It
seems that, when I move my cursor a little bit after a few seconds of
doing nothing, there seems to be a little bit of lag, as if either a
few frames are dropped at the beginning of the motion or maybe the
entire motion is delayed a bit.  I don't notice a similar delay when
typing, so I'm wondering if maybe there's a minor driver bug in which
the driver doesn't kick the panel out of PSR quite as quickly when the
cursor is updated as it does when the framebuffer is updated.

(A couple of lists are cc'd

BTW, switching PSR on and off using
/sys/module/i915/parameters/enable_psr seems to work fine, although it
seems like I may need to suspend/resume to get it to kick in.  But, if
there's really going to be a blacklist or whitelist of panels in
userspace, shouldn't there be an option in sysfs in
/sys/class/drm/card0-eDP-1/ or similar?


--Andy

[-- Attachment #2: panel-edid --]
[-- Type: application/octet-stream, Size: 128 bytes --]

[-- Attachment #3: Type: text/plain, Size: 160 bytes --]

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: i915 PSR test results and cursor lag

[Andy Lutomirski]

On Thu, Feb 1, 2018 at 9:40 AM, Andy Lutomirski <luto@kernel.org> wrote:
> Hi-
>
> As requested in your blog post, I tested PSR.  I see something like
> 2.69W with PSR off and 2.17W with PSR on.  Screen blanking,
> suspend/resume, and the contents of the screen all seem okay.  This is
> a Dell XPS 13 9350, i.e.:
>
> System Information
>         Manufacturer: Dell Inc.
>         Product Name: XPS 13 9350
>
> EDID is attached.
>
> *However*, I do see one unfortunate side effect of turning on PSR.  It
> seems that, when I move my cursor a little bit after a few seconds of
> doing nothing, there seems to be a little bit of lag, as if either a
> few frames are dropped at the beginning of the motion or maybe the
> entire motion is delayed a bit.  I don't notice a similar delay when
> typing, so I'm wondering if maybe there's a minor driver bug in which
> the driver doesn't kick the panel out of PSR quite as quickly when the
> cursor is updated as it does when the framebuffer is updated.
>

I'm also getting occasional messages like:

[ 2675.574486] [drm:intel_pipe_update_start [i915]] *ERROR* Potential
atomic update failure on pipe A

with PSR on.  But there is nowhere near one of these messages per tiny
lag incident.
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [Intel-gfx] i915 PSR test results and cursor lag

[Chris Wilson]

Quoting Andy Lutomirski (2018-02-01 17:40:22)
> *However*, I do see one unfortunate side effect of turning on PSR.  It
> seems that, when I move my cursor a little bit after a few seconds of
> doing nothing, there seems to be a little bit of lag, as if either a
> few frames are dropped at the beginning of the motion or maybe the
> entire motion is delayed a bit.  I don't notice a similar delay when
> typing, so I'm wondering if maybe there's a minor driver bug in which
> the driver doesn't kick the panel out of PSR quite as quickly when the
> cursor is updated as it does when the framebuffer is updated.

One thing that's important know regarding the cursor is whether the
display server is using a HW cursor or SW cursor. Could you please attach
the log from the display server (or if you are using a stock
distribution that's probably enough to work out what it is using)?
-Chris
_______________________________________________
dri-devel mailing list
dri-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/dri-devel

Re: i915 PSR test results and cursor lag

[Kristian Høgsberg]

On Thu, Feb 1, 2018 at 9:53 AM Chris Wilson <chris@chris-wilson.co.uk>
wrote:

> Quoting Andy Lutomirski (2018-02-01 17:40:22)
> > *However*, I do see one unfortunate side effect of turning on PSR.  It
> > seems that, when I move my cursor a little bit after a few seconds of
> > doing nothing, there seems to be a little bit of lag, as if either a
> > few frames are dropped at the beginning of the motion or maybe the
> > entire motion is delayed a bit.  I don't notice a similar delay when
> > typing, so I'm wondering if maybe there's a min
> or driver bug in which
> > the driver doesn't kick the panel out of PSR quite as quickly when the
> > cursor is updated as it does when the framebuffer is updated.

> One thing that's important know regarding the cursor is whether the
> display server is using a HW cursor or SW cursor. Could you please attach
> the log from the display server (or if you are using a stock
> distribution that's probably enough to work out what it is using)?
> -Chris

We had a similar problem for Rockchip in ChromeOS and ended up using an
input handler to let us start the PSR exit as early as possible:


https://chromium.googlesource.com/chromiumos/third_party/kernel/+/chromeos-4.4/drivers/gpu/drm/rockchip/rockchip_drm_psr.c#345

It's similar in spirit to the interactive cpufreq governor:

   https://lwn.net/Articles/662209/

Kristian
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [Intel-gfx] i915 PSR test results and cursor lag

[Chris Wilson]

Quoting Kristian Høgsberg (2018-02-01 20:22:40)
> On Thu, Feb 1, 2018 at 9:53 AM Chris Wilson <chris@chris-wilson.co.uk>
> wrote:
> 
> > Quoting Andy Lutomirski (2018-02-01 17:40:22)
> > > *However*, I do see one unfortunate side effect of turning on PSR.  It
> > > seems that, when I move my cursor a little bit after a few seconds of
> > > doing nothing, there seems to be a little bit of lag, as if either a
> > > few frames are dropped at the beginning of the motion or maybe the
> > > entire motion is delayed a bit.  I don't notice a similar delay when
> > > typing, so I'm wondering if maybe there's a min
> > or driver bug in which
> > > the driver doesn't kick the panel out of PSR quite as quickly when the
> > > cursor is updated as it does when the framebuffer is updated.
> 
> > One thing that's important know regarding the cursor is whether the
> > display server is using a HW cursor or SW cursor. Could you please attach
> > the log from the display server (or if you are using a stock
> > distribution that's probably enough to work out what it is using)?
> > -Chris
> 
> We had a similar problem for Rockchip in ChromeOS and ended up using an
> input handler to let us start the PSR exit as early as possible:

Reminds me of mutter devs suggesting that we may like to kick the gpu to
max clocks high frequency on any input activity as well. (I'm still not
convinced that's a good idea, for mundane typing we barely need to wake
up the gpu. :) I guess it all depends on expected wakeup latencies, but
I didn't think PSR had multi-frame lag?
-Chris
_______________________________________________
dri-devel mailing list
dri-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/dri-devel

Re: [Intel-gfx] i915 PSR test results and cursor lag

[Andy Lutomirski]

On Thu, Feb 1, 2018 at 9:53 AM, Chris Wilson <chris@chris-wilson.co.uk> wrote:
> Quoting Andy Lutomirski (2018-02-01 17:40:22)
>> *However*, I do see one unfortunate side effect of turning on PSR.  It
>> seems that, when I move my cursor a little bit after a few seconds of
>> doing nothing, there seems to be a little bit of lag, as if either a
>> few frames are dropped at the beginning of the motion or maybe the
>> entire motion is delayed a bit.  I don't notice a similar delay when
>> typing, so I'm wondering if maybe there's a minor driver bug in which
>> the driver doesn't kick the panel out of PSR quite as quickly when the
>> cursor is updated as it does when the framebuffer is updated.
>
> One thing that's important know regarding the cursor is whether the
> display server is using a HW cursor or SW cursor. Could you please attach
> the log from the display server (or if you are using a stock
> distribution that's probably enough to work out what it is using)?
> -Chris

Looking at the logs, I see a few things.  First, I have a few of these:

Feb 01 09:24:24 laptop kernel: [drm:intel_pipe_update_start [i915]]
*ERROR* Potential atomic update failure on pipe A
Feb 01 09:24:48 laptop org.gnome.Shell.desktop[3261]: libinput error:
event15 - libinput error: DLL0704:01 06CB:76AE Touchpad: libinput
error: kernel bug: Touch jump detected and discarded.
Feb 01 09:24:48 laptop org.gnome.Shell.desktop[3261]: See
https://wayland.freedesktop.org/libinput/doc/1.9.3/touchpad_jumping_cursor.html
for details
Feb 01 09:24:50 laptop org.gnome.Shell.desktop[3261]: libinput error:
event15 - libinput error: DLL0704:01 06CB:76AE Touchpad: libinput
error: kernel bug: Touch jump detected and discarded.
Feb 01 09:24:50 laptop org.gnome.Shell.desktop[3261]: See
https://wayland.freedesktop.org/libinput/doc/1.9.3/touchpad_jumping_cursor.html
for details

(Hi, Peter!)

So it's entirely possible that what I'm seeing is actually an input
issue that's exacerbated by PSR for some bizarre reason.

I got this after a recent suspend/resume:

Feb 01 09:44:34 laptop systemd-logind[2412]: Lid closed.
Feb 01 09:44:34 laptop systemd-logind[2412]: device-enumerator: scan all dirs
Feb 01 09:44:34 laptop systemd-logind[2412]:   device-enumerator:
scanning /sys/bus
Feb 01 09:44:34 laptop systemd-logind[2412]:   device-enumerator:
scanning /sys/class
Feb 01 09:44:34 laptop systemd-logind[2412]: Failed to open
configuration file '/etc/systemd/sleep.conf': No such file or
directory
Feb 01 09:44:34 laptop systemd-logind[2412]: Suspending...
Feb 01 09:44:34 laptop systemd-logind[2412]: Sent message type=signal
sender=n/a destination=n/a object=/org/freedesktop/login1
interface=org.freedesktop.login1.Manager member=PrepareForSleep
cookie=570 reply
Feb 01 09:44:34 laptop systemd-logind[2412]: Got message
type=method_call sender=:1.46 destination=:1.1
object=/org/freedesktop/login1/session/_32
interface=org.freedesktop.login1.Session member=ReleaseDevice
Feb 01 09:44:34 laptop systemd-logind[2412]: Sent message type=signal
sender=n/a destination=:1.46
object=/org/freedesktop/login1/session/_32
interface=org.freedesktop.login1.Session member=PauseDevice cookie
Feb 01 09:44:34 laptop gnome-shell[2630]: Failed to apply DRM plane
transform 0: Permission denied
Feb 01 09:44:34 laptop gnome-shell[2630]: drmModeSetCursor2 failed
with (Permission denied), drawing cursor with OpenGL from now on

But I don't see the word "cursor" in my system logs before the first
suspend.  What am I looking for?  This is Fedora 27 running a Gnome
Wayland session, but it hasn't been reinstalled in some time, so it's
possible that there are some weird settings sitting around.  But I did
check and I have no weird i915 parameters.

Also, are these things potentially related:

[ 3067.702527] [drm:intel_pipe_update_start [i915]] *ERROR* Potential
atomic update failure on pipe A

As I'm typing this, I've seen a couple instances of what seems like a
full *second* of cursor latency, but I've only gotten the potential
atomic update failure once.

And is there any straightforward tracing to do to distinguish between
PSR exit latency and other potential sources of latency?
_______________________________________________
dri-devel mailing list
dri-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/dri-devel

Re: i915 PSR test results and cursor lag

[Chris Wilson]

Quoting Andy Lutomirski (2018-02-01 21:04:30)
> I got this after a recent suspend/resume:
> 
> Feb 01 09:44:34 laptop systemd-logind[2412]: Lid closed.
> Feb 01 09:44:34 laptop systemd-logind[2412]: device-enumerator: scan all dirs
> Feb 01 09:44:34 laptop systemd-logind[2412]:   device-enumerator:
> scanning /sys/bus
> Feb 01 09:44:34 laptop systemd-logind[2412]:   device-enumerator:
> scanning /sys/class
> Feb 01 09:44:34 laptop systemd-logind[2412]: Failed to open
> configuration file '/etc/systemd/sleep.conf': No such file or
> directory
> Feb 01 09:44:34 laptop systemd-logind[2412]: Suspending...
> Feb 01 09:44:34 laptop systemd-logind[2412]: Sent message type=signal
> sender=n/a destination=n/a object=/org/freedesktop/login1
> interface=org.freedesktop.login1.Manager member=PrepareForSleep
> cookie=570 reply
> Feb 01 09:44:34 laptop systemd-logind[2412]: Got message
> type=method_call sender=:1.46 destination=:1.1
> object=/org/freedesktop/login1/session/_32
> interface=org.freedesktop.login1.Session member=ReleaseDevice
> Feb 01 09:44:34 laptop systemd-logind[2412]: Sent message type=signal
> sender=n/a destination=:1.46
> object=/org/freedesktop/login1/session/_32
> interface=org.freedesktop.login1.Session member=PauseDevice cookie
> Feb 01 09:44:34 laptop gnome-shell[2630]: Failed to apply DRM plane
> transform 0: Permission denied
> Feb 01 09:44:34 laptop gnome-shell[2630]: drmModeSetCursor2 failed
> with (Permission denied), drawing cursor with OpenGL from now on
> 
> But I don't see the word "cursor" in my system logs before the first
> suspend.  What am I looking for?  This is Fedora 27 running a Gnome
> Wayland session, but it hasn't been reinstalled in some time, so it's
> possible that there are some weird settings sitting around.  But I did
> check and I have no weird i915 parameters.

You are using gnome-shell as the display server. From that it appears to
have started off with a HW cursor and switched to a SW cursor after
suspend. Did you notice a change in behaviour? After rebooting or just
restarting gnome-shell?
 
> Also, are these things potentially related:
> 
> [ 3067.702527] [drm:intel_pipe_update_start [i915]] *ERROR* Potential
> atomic update failure on pipe A

They are just "missed the immediate vblank for the screen update"
messages. Should not be related to PSR, but may cause jitter by delaying
the odd screen update.
 
> As I'm typing this, I've seen a couple instances of what seems like a
> full *second* of cursor latency, but I've only gotten the potential
> atomic update failure once.
> 
> And is there any straightforward tracing to do to distinguish between
> PSR exit latency and other potential sources of latency?

It looks plausible that we could at least report how long it takes the
registers to reflect the change in state (but we don't). The best source
of information atm is /sys/kernel/debug/dri/0/i915_edp_psr_status.
-Chris
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [Intel-gfx] i915 PSR test results and cursor lag

[Andy Lutomirski]

On Thu, Feb 1, 2018 at 9:20 PM, Chris Wilson <chris@chris-wilson.co.uk> wrote:
> Quoting Andy Lutomirski (2018-02-01 21:04:30)
>> I got this after a recent suspend/resume:
>>
>> Feb 01 09:44:34 laptop systemd-logind[2412]: Lid closed.
>> Feb 01 09:44:34 laptop systemd-logind[2412]: device-enumerator: scan all dirs
>> Feb 01 09:44:34 laptop systemd-logind[2412]:   device-enumerator:
>> scanning /sys/bus
>> Feb 01 09:44:34 laptop systemd-logind[2412]:   device-enumerator:
>> scanning /sys/class
>> Feb 01 09:44:34 laptop systemd-logind[2412]: Failed to open
>> configuration file '/etc/systemd/sleep.conf': No such file or
>> directory
>> Feb 01 09:44:34 laptop systemd-logind[2412]: Suspending...
>> Feb 01 09:44:34 laptop systemd-logind[2412]: Sent message type=signal
>> sender=n/a destination=n/a object=/org/freedesktop/login1
>> interface=org.freedesktop.login1.Manager member=PrepareForSleep
>> cookie=570 reply
>> Feb 01 09:44:34 laptop systemd-logind[2412]: Got message
>> type=method_call sender=:1.46 destination=:1.1
>> object=/org/freedesktop/login1/session/_32
>> interface=org.freedesktop.login1.Session member=ReleaseDevice
>> Feb 01 09:44:34 laptop systemd-logind[2412]: Sent message type=signal
>> sender=n/a destination=:1.46
>> object=/org/freedesktop/login1/session/_32
>> interface=org.freedesktop.login1.Session member=PauseDevice cookie
>> Feb 01 09:44:34 laptop gnome-shell[2630]: Failed to apply DRM plane
>> transform 0: Permission denied
>> Feb 01 09:44:34 laptop gnome-shell[2630]: drmModeSetCursor2 failed
>> with (Permission denied), drawing cursor with OpenGL from now on
>>
>> But I don't see the word "cursor" in my system logs before the first
>> suspend.  What am I looking for?  This is Fedora 27 running a Gnome
>> Wayland session, but it hasn't been reinstalled in some time, so it's
>> possible that there are some weird settings sitting around.  But I did
>> check and I have no weird i915 parameters.
>
> You are using gnome-shell as the display server. From that it appears to
> have started off with a HW cursor and switched to a SW cursor after
> suspend. Did you notice a change in behaviour? After rebooting or just
> restarting gnome-shell?

I think it's less consistently bad after a reboot before suspending.

>
>> Also, are these things potentially related:
>>
>> [ 3067.702527] [drm:intel_pipe_update_start [i915]] *ERROR* Potential
>> atomic update failure on pipe A
>
> They are just "missed the immediate vblank for the screen update"
> messages. Should not be related to PSR, but may cause jitter by delaying
> the odd screen update.

I just got this one, and the timestamp is at least reasonably close to
a giant latency spike:

[  288.799654] [drm:intel_pipe_update_end [i915]] *ERROR* Atomic
update failure on pipe A (start=31 end=32) time 15 us, min 1073, max
1079, scanline start 1087, end 1088

>
>> As I'm typing this, I've seen a couple instances of what seems like a
>> full *second* of cursor latency, but I've only gotten the potential
>> atomic update failure once.
>>
>> And is there any straightforward tracing to do to distinguish between
>> PSR exit latency and other potential sources of latency?
>
> It looks plausible that we could at least report how long it takes the
> registers to reflect the change in state (but we don't). The best source
> of information atm is /sys/kernel/debug/dri/0/i915_edp_psr_status.

Hmm.

I went and looked at the code, and I noticed what could be bugs or
could (more likely) be my confusion since I don't know this code at
all:

intel_single_frame_update() does something inscrutable to me, but I
imagine it does something that causes the next page flip to get
noticed by the panel even with PSR on.  But how does the code that
calls it know that anything happened?  (Looking at the commit history,
maybe this is something special that's only needed on some platforms
but doesn't replace the normal PSR exit sequence.)

Perhaps more interestingly, intel_psr_flush() does this:

    /* By definition flush = invalidate + flush */
    if (frontbuffer_bits)
        intel_psr_exit(dev_priv);

    if (!dev_priv->psr.active && !dev_priv->psr.busy_frontbuffer_bits)
        if (!work_busy(&dev_priv->psr.work.work))
            schedule_delayed_work(&dev_priv->psr.work,
                          msecs_to_jiffies(100));

I'm guessing that the idea is that we're turning off PSR because we
want the panel to update and we expect that, in 100ms, the update will
have hit the panel and we'll have been idle long enough for it to make
sense to re-enter PSR.  IOW, the code wants PSR to be off for at least
100ms and then to turn back on.  But this code actually says "turn PSR
back on in at *most* 100ms".  What happens if there are two screen
updates 99ms apart?  The first one should work fine, but the next one
will hit with 1ms left on the delayed work, and intel_psr_work() will
get called in 1ms.  There's some magic with busy_frontbuffer_bits, but
it seems questionable to me that intel_psr_flush() clears
busy_frontbuffer_bits and *then* calls intel_psr_exit().

Naively, I would expect that PSR needs to be kept off until the vblank
following the page flip.

Also, in intel_psr_work(), shouldn't this code:

    /*
     * The delayed work can race with an invalidate hence we need to
     * recheck. Since psr_flush first clears this and then reschedules we
     * won't ever miss a flush when bailing out here.
     */
    if (dev_priv->psr.busy_frontbuffer_bits)
        goto unlock;

re-arm the delayed work?

Anyway, this is all on a 4.14 kernel.  I should update to 4.16 and see
what happens.
_______________________________________________
dri-devel mailing list
dri-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/dri-devel

Re: [Intel-gfx] i915 PSR test results and cursor lag

[Andy Lutomirski]

On Fri, Feb 2, 2018 at 1:24 AM, Andy Lutomirski <luto@kernel.org> wrote:
> On Thu, Feb 1, 2018 at 9:20 PM, Chris Wilson <chris@chris-wilson.co.uk> wrote:
>> Quoting Andy Lutomirski (2018-02-01 21:04:30)
>>> I got this after a recent suspend/resume:
>>>
>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Lid closed.
>>> Feb 01 09:44:34 laptop systemd-logind[2412]: device-enumerator: scan all dirs
>>> Feb 01 09:44:34 laptop systemd-logind[2412]:   device-enumerator:
>>> scanning /sys/bus
>>> Feb 01 09:44:34 laptop systemd-logind[2412]:   device-enumerator:
>>> scanning /sys/class
>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Failed to open
>>> configuration file '/etc/systemd/sleep.conf': No such file or
>>> directory
>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Suspending...
>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Sent message type=signal
>>> sender=n/a destination=n/a object=/org/freedesktop/login1
>>> interface=org.freedesktop.login1.Manager member=PrepareForSleep
>>> cookie=570 reply
>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Got message
>>> type=method_call sender=:1.46 destination=:1.1
>>> object=/org/freedesktop/login1/session/_32
>>> interface=org.freedesktop.login1.Session member=ReleaseDevice
>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Sent message type=signal
>>> sender=n/a destination=:1.46
>>> object=/org/freedesktop/login1/session/_32
>>> interface=org.freedesktop.login1.Session member=PauseDevice cookie
>>> Feb 01 09:44:34 laptop gnome-shell[2630]: Failed to apply DRM plane
>>> transform 0: Permission denied
>>> Feb 01 09:44:34 laptop gnome-shell[2630]: drmModeSetCursor2 failed
>>> with (Permission denied), drawing cursor with OpenGL from now on
>>>
>>> But I don't see the word "cursor" in my system logs before the first
>>> suspend.  What am I looking for?  This is Fedora 27 running a Gnome
>>> Wayland session, but it hasn't been reinstalled in some time, so it's
>>> possible that there are some weird settings sitting around.  But I did
>>> check and I have no weird i915 parameters.
>>
>> You are using gnome-shell as the display server. From that it appears to
>> have started off with a HW cursor and switched to a SW cursor after
>> suspend. Did you notice a change in behaviour? After rebooting or just
>> restarting gnome-shell?
>
> I think it's less consistently bad after a reboot before suspending.
>
>>
>>> Also, are these things potentially related:
>>>
>>> [ 3067.702527] [drm:intel_pipe_update_start [i915]] *ERROR* Potential
>>> atomic update failure on pipe A
>>
>> They are just "missed the immediate vblank for the screen update"
>> messages. Should not be related to PSR, but may cause jitter by delaying
>> the odd screen update.
>
> I just got this one, and the timestamp is at least reasonably close to
> a giant latency spike:
>
> [  288.799654] [drm:intel_pipe_update_end [i915]] *ERROR* Atomic
> update failure on pipe A (start=31 end=32) time 15 us, min 1073, max
> 1079, scanline start 1087, end 1088
>
>>
>>> As I'm typing this, I've seen a couple instances of what seems like a
>>> full *second* of cursor latency, but I've only gotten the potential
>>> atomic update failure once.
>>>
>>> And is there any straightforward tracing to do to distinguish between
>>> PSR exit latency and other potential sources of latency?
>>
>> It looks plausible that we could at least report how long it takes the
>> registers to reflect the change in state (but we don't). The best source
>> of information atm is /sys/kernel/debug/dri/0/i915_edp_psr_status.
>
> Hmm.
>
> I went and looked at the code, and I noticed what could be bugs or
> could (more likely) be my confusion since I don't know this code at
> all:
>
> intel_single_frame_update() does something inscrutable to me, but I
> imagine it does something that causes the next page flip to get
> noticed by the panel even with PSR on.  But how does the code that
> calls it know that anything happened?  (Looking at the commit history,
> maybe this is something special that's only needed on some platforms
> but doesn't replace the normal PSR exit sequence.)
>
> Perhaps more interestingly, intel_psr_flush() does this:
>
>     /* By definition flush = invalidate + flush */
>     if (frontbuffer_bits)
>         intel_psr_exit(dev_priv);
>
>     if (!dev_priv->psr.active && !dev_priv->psr.busy_frontbuffer_bits)
>         if (!work_busy(&dev_priv->psr.work.work))
>             schedule_delayed_work(&dev_priv->psr.work,
>                           msecs_to_jiffies(100));
>
> I'm guessing that the idea is that we're turning off PSR because we
> want the panel to update and we expect that, in 100ms, the update will
> have hit the panel and we'll have been idle long enough for it to make
> sense to re-enter PSR.  IOW, the code wants PSR to be off for at least
> 100ms and then to turn back on.  But this code actually says "turn PSR
> back on in at *most* 100ms".  What happens if there are two screen
> updates 99ms apart?  The first one should work fine, but the next one
> will hit with 1ms left on the delayed work, and intel_psr_work() will
> get called in 1ms.  There's some magic with busy_frontbuffer_bits, but
> it seems questionable to me that intel_psr_flush() clears
> busy_frontbuffer_bits and *then* calls intel_psr_exit().
>
> Naively, I would expect that PSR needs to be kept off until the vblank
> following the page flip.
>
> Also, in intel_psr_work(), shouldn't this code:
>
>     /*
>      * The delayed work can race with an invalidate hence we need to
>      * recheck. Since psr_flush first clears this and then reschedules we
>      * won't ever miss a flush when bailing out here.
>      */
>     if (dev_priv->psr.busy_frontbuffer_bits)
>         goto unlock;
>
> re-arm the delayed work?
>
> Anyway, this is all on a 4.14 kernel.  I should update to 4.16 and see
> what happens.

I updated to 4.15, and the situation is much worse.  With
enable_psr=1, the system survives for several seconds and then the
screen stops updating entirely.  If I boot with i915.enable_psr=1, I
get to the Fedora login screen and then the system dies.  If I set
enable_psr=1 using sysfs, it does a bit after the next resume.  It
seems like it also sometimes hangs even worse a bit after the screen
stops updating, but it's hard to tell.

I see this in my logs:

[drm:drm_atomic_helper_wait_for_flip_done [drm_kms_helper]] *ERROR*
[CRTC:37:pipe A] flip_done timed out

Sometimes I see this a bit later:

[drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR*
[CRTC:37:pipe A] flip_done timed out

I'm able to get some debugging out before the system dies.  I see
intel_psr_flush() getting called a bunch, and I don't see
intel_psr_invalidate() being called at all.  I also see
intel_psr_work() activating psr as little as 2ms after
intel_psr_flush() finishes.  So I think the code is indeed buggy or at
least questionable.  I'd try to fix it (at least as well as I can
without knowing anything about how the PSR state machine actually
works), but the fact that the system hangs would make it very hard to
test.
_______________________________________________
dri-devel mailing list
dri-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/dri-devel

Re: [Intel-gfx] i915 PSR test results and cursor lag

[Andy Lutomirski]

On Fri, Feb 2, 2018 at 7:18 PM, Andy Lutomirski <luto@kernel.org> wrote:
> On Fri, Feb 2, 2018 at 1:24 AM, Andy Lutomirski <luto@kernel.org> wrote:
>> On Thu, Feb 1, 2018 at 9:20 PM, Chris Wilson <chris@chris-wilson.co.uk> wrote:
>>> Quoting Andy Lutomirski (2018-02-01 21:04:30)
>>>> I got this after a recent suspend/resume:
>>>>
>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Lid closed.
>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: device-enumerator: scan all dirs
>>>> Feb 01 09:44:34 laptop systemd-logind[2412]:   device-enumerator:
>>>> scanning /sys/bus
>>>> Feb 01 09:44:34 laptop systemd-logind[2412]:   device-enumerator:
>>>> scanning /sys/class
>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Failed to open
>>>> configuration file '/etc/systemd/sleep.conf': No such file or
>>>> directory
>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Suspending...
>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Sent message type=signal
>>>> sender=n/a destination=n/a object=/org/freedesktop/login1
>>>> interface=org.freedesktop.login1.Manager member=PrepareForSleep
>>>> cookie=570 reply
>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Got message
>>>> type=method_call sender=:1.46 destination=:1.1
>>>> object=/org/freedesktop/login1/session/_32
>>>> interface=org.freedesktop.login1.Session member=ReleaseDevice
>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Sent message type=signal
>>>> sender=n/a destination=:1.46
>>>> object=/org/freedesktop/login1/session/_32
>>>> interface=org.freedesktop.login1.Session member=PauseDevice cookie
>>>> Feb 01 09:44:34 laptop gnome-shell[2630]: Failed to apply DRM plane
>>>> transform 0: Permission denied
>>>> Feb 01 09:44:34 laptop gnome-shell[2630]: drmModeSetCursor2 failed
>>>> with (Permission denied), drawing cursor with OpenGL from now on
>>>>
>>>> But I don't see the word "cursor" in my system logs before the first
>>>> suspend.  What am I looking for?  This is Fedora 27 running a Gnome
>>>> Wayland session, but it hasn't been reinstalled in some time, so it's
>>>> possible that there are some weird settings sitting around.  But I did
>>>> check and I have no weird i915 parameters.
>>>
>>> You are using gnome-shell as the display server. From that it appears to
>>> have started off with a HW cursor and switched to a SW cursor after
>>> suspend. Did you notice a change in behaviour? After rebooting or just
>>> restarting gnome-shell?
>>
>> I think it's less consistently bad after a reboot before suspending.
>>
>>>
>>>> Also, are these things potentially related:
>>>>
>>>> [ 3067.702527] [drm:intel_pipe_update_start [i915]] *ERROR* Potential
>>>> atomic update failure on pipe A
>>>
>>> They are just "missed the immediate vblank for the screen update"
>>> messages. Should not be related to PSR, but may cause jitter by delaying
>>> the odd screen update.
>>
>> I just got this one, and the timestamp is at least reasonably close to
>> a giant latency spike:
>>
>> [  288.799654] [drm:intel_pipe_update_end [i915]] *ERROR* Atomic
>> update failure on pipe A (start=31 end=32) time 15 us, min 1073, max
>> 1079, scanline start 1087, end 1088
>>
>>>
>>>> As I'm typing this, I've seen a couple instances of what seems like a
>>>> full *second* of cursor latency, but I've only gotten the potential
>>>> atomic update failure once.
>>>>
>>>> And is there any straightforward tracing to do to distinguish between
>>>> PSR exit latency and other potential sources of latency?
>>>
>>> It looks plausible that we could at least report how long it takes the
>>> registers to reflect the change in state (but we don't). The best source
>>> of information atm is /sys/kernel/debug/dri/0/i915_edp_psr_status.
>>
>> Hmm.
>>
>> I went and looked at the code, and I noticed what could be bugs or
>> could (more likely) be my confusion since I don't know this code at
>> all:
>>
>> intel_single_frame_update() does something inscrutable to me, but I
>> imagine it does something that causes the next page flip to get
>> noticed by the panel even with PSR on.  But how does the code that
>> calls it know that anything happened?  (Looking at the commit history,
>> maybe this is something special that's only needed on some platforms
>> but doesn't replace the normal PSR exit sequence.)
>>
>> Perhaps more interestingly, intel_psr_flush() does this:
>>
>>     /* By definition flush = invalidate + flush */
>>     if (frontbuffer_bits)
>>         intel_psr_exit(dev_priv);
>>
>>     if (!dev_priv->psr.active && !dev_priv->psr.busy_frontbuffer_bits)
>>         if (!work_busy(&dev_priv->psr.work.work))
>>             schedule_delayed_work(&dev_priv->psr.work,
>>                           msecs_to_jiffies(100));
>>
>> I'm guessing that the idea is that we're turning off PSR because we
>> want the panel to update and we expect that, in 100ms, the update will
>> have hit the panel and we'll have been idle long enough for it to make
>> sense to re-enter PSR.  IOW, the code wants PSR to be off for at least
>> 100ms and then to turn back on.  But this code actually says "turn PSR
>> back on in at *most* 100ms".  What happens if there are two screen
>> updates 99ms apart?  The first one should work fine, but the next one
>> will hit with 1ms left on the delayed work, and intel_psr_work() will
>> get called in 1ms.  There's some magic with busy_frontbuffer_bits, but
>> it seems questionable to me that intel_psr_flush() clears
>> busy_frontbuffer_bits and *then* calls intel_psr_exit().
>>
>> Naively, I would expect that PSR needs to be kept off until the vblank
>> following the page flip.
>>
>> Also, in intel_psr_work(), shouldn't this code:
>>
>>     /*
>>      * The delayed work can race with an invalidate hence we need to
>>      * recheck. Since psr_flush first clears this and then reschedules we
>>      * won't ever miss a flush when bailing out here.
>>      */
>>     if (dev_priv->psr.busy_frontbuffer_bits)
>>         goto unlock;
>>
>> re-arm the delayed work?
>>
>> Anyway, this is all on a 4.14 kernel.  I should update to 4.16 and see
>> what happens.
>
> I updated to 4.15, and the situation is much worse.  With
> enable_psr=1, the system survives for several seconds and then the
> screen stops updating entirely.  If I boot with i915.enable_psr=1, I
> get to the Fedora login screen and then the system dies.  If I set
> enable_psr=1 using sysfs, it does a bit after the next resume.  It
> seems like it also sometimes hangs even worse a bit after the screen
> stops updating, but it's hard to tell.
>
> I see this in my logs:
>
> [drm:drm_atomic_helper_wait_for_flip_done [drm_kms_helper]] *ERROR*
> [CRTC:37:pipe A] flip_done timed out
>
> Sometimes I see this a bit later:
>
> [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR*
> [CRTC:37:pipe A] flip_done timed out

I filed:

https://bugs.freedesktop.org/show_bug.cgi?id=104918
_______________________________________________
dri-devel mailing list
dri-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/dri-devel

Re: i915 PSR test results and cursor lag

[Chris Wilson]

Quoting Andy Lutomirski (2018-02-02 19:23:33)
> On Fri, Feb 2, 2018 at 7:18 PM, Andy Lutomirski <luto@kernel.org> wrote:
> > On Fri, Feb 2, 2018 at 1:24 AM, Andy Lutomirski <luto@kernel.org> wrote:
> >> Anyway, this is all on a 4.14 kernel.  I should update to 4.16 and see
> >> what happens.
> >
> > I updated to 4.15, and the situation is much worse.  With
> > enable_psr=1, the system survives for several seconds and then the
> > screen stops updating entirely.  If I boot with i915.enable_psr=1, I
> > get to the Fedora login screen and then the system dies.  If I set
> > enable_psr=1 using sysfs, it does a bit after the next resume.  It
> > seems like it also sometimes hangs even worse a bit after the screen
> > stops updating, but it's hard to tell.
> >
> > I see this in my logs:
> >
> > [drm:drm_atomic_helper_wait_for_flip_done [drm_kms_helper]] *ERROR*
> > [CRTC:37:pipe A] flip_done timed out
> >
> > Sometimes I see this a bit later:
> >
> > [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR*
> > [CRTC:37:pipe A] flip_done timed out
> 
> I filed:
> 
> https://bugs.freedesktop.org/show_bug.cgi?id=104918

Thank you. To be frank the only PSR system we have in CI isn't currently
doing PSR (due to the test not taking panel restrictions into account).
Not that I think we have any test looking for lag, but it should at
least have told us that PSR was snafu.
-Chris
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: i915 PSR test results and cursor lag

[Pandiyan, Dhinakaran]

On Fri, 2018-02-02 at 19:18 +0000, Andy Lutomirski wrote:
> On Fri, Feb 2, 2018 at 1:24 AM, Andy Lutomirski <luto@kernel.org> wrote:
> > On Thu, Feb 1, 2018 at 9:20 PM, Chris Wilson <chris@chris-wilson.co.uk> wrote:
> >> Quoting Andy Lutomirski (2018-02-01 21:04:30)
> >>> I got this after a recent suspend/resume:
> >>>
> >>> Feb 01 09:44:34 laptop systemd-logind[2412]: Lid closed.
> >>> Feb 01 09:44:34 laptop systemd-logind[2412]: device-enumerator: scan all dirs
> >>> Feb 01 09:44:34 laptop systemd-logind[2412]:   device-enumerator:
> >>> scanning /sys/bus
> >>> Feb 01 09:44:34 laptop systemd-logind[2412]:   device-enumerator:
> >>> scanning /sys/class
> >>> Feb 01 09:44:34 laptop systemd-logind[2412]: Failed to open
> >>> configuration file '/etc/systemd/sleep.conf': No such file or
> >>> directory
> >>> Feb 01 09:44:34 laptop systemd-logind[2412]: Suspending...
> >>> Feb 01 09:44:34 laptop systemd-logind[2412]: Sent message type=signal
> >>> sender=n/a destination=n/a object=/org/freedesktop/login1
> >>> interface=org.freedesktop.login1.Manager member=PrepareForSleep
> >>> cookie=570 reply
> >>> Feb 01 09:44:34 laptop systemd-logind[2412]: Got message
> >>> type=method_call sender=:1.46 destination=:1.1
> >>> object=/org/freedesktop/login1/session/_32
> >>> interface=org.freedesktop.login1.Session member=ReleaseDevice
> >>> Feb 01 09:44:34 laptop systemd-logind[2412]: Sent message type=signal
> >>> sender=n/a destination=:1.46
> >>> object=/org/freedesktop/login1/session/_32
> >>> interface=org.freedesktop.login1.Session member=PauseDevice cookie
> >>> Feb 01 09:44:34 laptop gnome-shell[2630]: Failed to apply DRM plane
> >>> transform 0: Permission denied
> >>> Feb 01 09:44:34 laptop gnome-shell[2630]: drmModeSetCursor2 failed
> >>> with (Permission denied), drawing cursor with OpenGL from now on
> >>>
> >>> But I don't see the word "cursor" in my system logs before the first
> >>> suspend.  What am I looking for?  This is Fedora 27 running a Gnome
> >>> Wayland session, but it hasn't been reinstalled in some time, so it's
> >>> possible that there are some weird settings sitting around.  But I did
> >>> check and I have no weird i915 parameters.
> >>
> >> You are using gnome-shell as the display server. From that it appears to
> >> have started off with a HW cursor and switched to a SW cursor after
> >> suspend. Did you notice a change in behaviour? After rebooting or just
> >> restarting gnome-shell?
> >
> > I think it's less consistently bad after a reboot before suspending.
> >
> >>
> >>> Also, are these things potentially related:
> >>>
> >>> [ 3067.702527] [drm:intel_pipe_update_start [i915]] *ERROR* Potential
> >>> atomic update failure on pipe A
> >>
> >> They are just "missed the immediate vblank for the screen update"
> >> messages. Should not be related to PSR, but may cause jitter by delaying
> >> the odd screen update.
> >
> > I just got this one, and the timestamp is at least reasonably close to
> > a giant latency spike:
> >
> > [  288.799654] [drm:intel_pipe_update_end [i915]] *ERROR* Atomic
> > update failure on pipe A (start=31 end=32) time 15 us, min 1073, max
> > 1079, scanline start 1087, end 1088
> >
> >>
> >>> As I'm typing this, I've seen a couple instances of what seems like a
> >>> full *second* of cursor latency, but I've only gotten the potential
> >>> atomic update failure once.
> >>>
> >>> And is there any straightforward tracing to do to distinguish between
> >>> PSR exit latency and other potential sources of latency?
> >>
> >> It looks plausible that we could at least report how long it takes the
> >> registers to reflect the change in state (but we don't). The best source
> >> of information atm is /sys/kernel/debug/dri/0/i915_edp_psr_status.
> >
> > Hmm.
> >
> > I went and looked at the code, and I noticed what could be bugs or
> > could (more likely) be my confusion since I don't know this code at
> > all:
> >
> > intel_single_frame_update() does something inscrutable to me, but I
> > imagine it does something that causes the next page flip to get
> > noticed by the panel even with PSR on.  But how does the code that
> > calls it know that anything happened?  (Looking at the commit history,
> > maybe this is something special that's only needed on some platforms
> > but doesn't replace the normal PSR exit sequence.)
> >
> > Perhaps more interestingly, intel_psr_flush() does this:
> >
> >     /* By definition flush = invalidate + flush */
> >     if (frontbuffer_bits)
> >         intel_psr_exit(dev_priv);
> >
> >     if (!dev_priv->psr.active && !dev_priv->psr.busy_frontbuffer_bits)
> >         if (!work_busy(&dev_priv->psr.work.work))
> >             schedule_delayed_work(&dev_priv->psr.work,
> >                           msecs_to_jiffies(100));
> >
> > I'm guessing that the idea is that we're turning off PSR because we
> > want the panel to update and we expect that, in 100ms, the update will
> > have hit the panel and we'll have been idle long enough for it to make
> > sense to re-enter PSR.  IOW, the code wants PSR to be off for at least
> > 100ms and then to turn back on.  But this code actually says "turn PSR
> > back on in at *most* 100ms".  What happens if there are two screen
> > updates 99ms apart?  The first one should work fine, but the next one
> > will hit with 1ms left on the delayed work, and intel_psr_work() will
> > get called in 1ms.  There's some magic with busy_frontbuffer_bits, but
> > it seems questionable to me that intel_psr_flush() clears
> > busy_frontbuffer_bits and *then* calls intel_psr_exit().
> >
> > Naively, I would expect that PSR needs to be kept off until the vblank
> > following the page flip.
> >
> > Also, in intel_psr_work(), shouldn't this code:
> >
> >     /*
> >      * The delayed work can race with an invalidate hence we need to
> >      * recheck. Since psr_flush first clears this and then reschedules we
> >      * won't ever miss a flush when bailing out here.
> >      */
> >     if (dev_priv->psr.busy_frontbuffer_bits)
> >         goto unlock;
> >
> > re-arm the delayed work?
> >
> > Anyway, this is all on a 4.14 kernel.  I should update to 4.16 and see
> > what happens.
> 
> I updated to 4.15, and the situation is much worse.  With
> enable_psr=1, the system survives for several seconds and then the
> screen stops updating entirely.  If I boot with i915.enable_psr=1, I
> get to the Fedora login screen and then the system dies.  If I set
> enable_psr=1 using sysfs, it does a bit after the next resume.  It
> seems like it also sometimes hangs even worse a bit after the screen
> stops updating, but it's hard to tell.

The login screen freeze sounds like what I have. Does this system have
DMC firmware? If yes, can you try this series
https://patchwork.freedesktop.org/series/37598/. You'll only need
patches 1,8,9 and 10.

-DK

> 
> I see this in my logs:
> 
> [drm:drm_atomic_helper_wait_for_flip_done [drm_kms_helper]] *ERROR*
> [CRTC:37:pipe A] flip_done timed out
> 
> Sometimes I see this a bit later:
> 
> [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR*
> [CRTC:37:pipe A] flip_done timed out
> 
> I'm able to get some debugging out before the system dies.  I see
> intel_psr_flush() getting called a bunch, and I don't see
> intel_psr_invalidate() being called at all.  I also see
> intel_psr_work() activating psr as little as 2ms after
> intel_psr_flush() finishes.  So I think the code is indeed buggy or at
> least questionable.  I'd try to fix it (at least as well as I can
> without knowing anything about how the PSR state machine actually
> works), but the fact that the system hangs would make it very hard to
> test.
> _______________________________________________
> Intel-gfx mailing list
> Intel-gfx@lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/intel-gfx
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: i915 PSR test results and cursor lag

[Andy Lutomirski]

On Sat, Feb 3, 2018 at 5:20 AM, Pandiyan, Dhinakaran
<dhinakaran.pandiyan@intel.com> wrote:
>
> On Fri, 2018-02-02 at 19:18 +0000, Andy Lutomirski wrote:
>> I updated to 4.15, and the situation is much worse.  With
>> enable_psr=1, the system survives for several seconds and then the
>> screen stops updating entirely.  If I boot with i915.enable_psr=1, I
>> get to the Fedora login screen and then the system dies.  If I set
>> enable_psr=1 using sysfs, it does a bit after the next resume.  It
>> seems like it also sometimes hangs even worse a bit after the screen
>> stops updating, but it's hard to tell.
>
> The login screen freeze sounds like what I have. Does this system have
> DMC firmware? If yes, can you try this series
> https://patchwork.freedesktop.org/series/37598/. You'll only need
> patches 1,8,9 and 10.

That fixes the hang.  Feel free to add:

Tested-by: Andy Lutomirski <luto@kernel.org>

to the i915 parts.  Also, any chance of getting it into the 4.15 stable kernels?

--Andy
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: i915 PSR test results and cursor lag

[Andy Lutomirski]

On Fri, Feb 2, 2018 at 7:18 PM, Andy Lutomirski <luto@kernel.org> wrote:
> On Fri, Feb 2, 2018 at 1:24 AM, Andy Lutomirski <luto@kernel.org> wrote:
>> On Thu, Feb 1, 2018 at 9:20 PM, Chris Wilson <chris@chris-wilson.co.uk> wrote:
>>> Quoting Andy Lutomirski (2018-02-01 21:04:30)
>>>> I got this after a recent suspend/resume:
>>>>
>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Lid closed.
>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: device-enumerator: scan all dirs
>>>> Feb 01 09:44:34 laptop systemd-logind[2412]:   device-enumerator:
>>>> scanning /sys/bus
>>>> Feb 01 09:44:34 laptop systemd-logind[2412]:   device-enumerator:
>>>> scanning /sys/class
>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Failed to open
>>>> configuration file '/etc/systemd/sleep.conf': No such file or
>>>> directory
>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Suspending...
>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Sent message type=signal
>>>> sender=n/a destination=n/a object=/org/freedesktop/login1
>>>> interface=org.freedesktop.login1.Manager member=PrepareForSleep
>>>> cookie=570 reply
>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Got message
>>>> type=method_call sender=:1.46 destination=:1.1
>>>> object=/org/freedesktop/login1/session/_32
>>>> interface=org.freedesktop.login1.Session member=ReleaseDevice
>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Sent message type=signal
>>>> sender=n/a destination=:1.46
>>>> object=/org/freedesktop/login1/session/_32
>>>> interface=org.freedesktop.login1.Session member=PauseDevice cookie
>>>> Feb 01 09:44:34 laptop gnome-shell[2630]: Failed to apply DRM plane
>>>> transform 0: Permission denied
>>>> Feb 01 09:44:34 laptop gnome-shell[2630]: drmModeSetCursor2 failed
>>>> with (Permission denied), drawing cursor with OpenGL from now on
>>>>
>>>> But I don't see the word "cursor" in my system logs before the first
>>>> suspend.  What am I looking for?  This is Fedora 27 running a Gnome
>>>> Wayland session, but it hasn't been reinstalled in some time, so it's
>>>> possible that there are some weird settings sitting around.  But I did
>>>> check and I have no weird i915 parameters.
>>>
>>> You are using gnome-shell as the display server. From that it appears to
>>> have started off with a HW cursor and switched to a SW cursor after
>>> suspend. Did you notice a change in behaviour? After rebooting or just
>>> restarting gnome-shell?
>>
>> I think it's less consistently bad after a reboot before suspending.
>>
>>>
>>>> Also, are these things potentially related:
>>>>
>>>> [ 3067.702527] [drm:intel_pipe_update_start [i915]] *ERROR* Potential
>>>> atomic update failure on pipe A
>>>
>>> They are just "missed the immediate vblank for the screen update"
>>> messages. Should not be related to PSR, but may cause jitter by delaying
>>> the odd screen update.
>>
>> I just got this one, and the timestamp is at least reasonably close to
>> a giant latency spike:
>>
>> [  288.799654] [drm:intel_pipe_update_end [i915]] *ERROR* Atomic
>> update failure on pipe A (start=31 end=32) time 15 us, min 1073, max
>> 1079, scanline start 1087, end 1088
>>
>>>
>>>> As I'm typing this, I've seen a couple instances of what seems like a
>>>> full *second* of cursor latency, but I've only gotten the potential
>>>> atomic update failure once.
>>>>
>>>> And is there any straightforward tracing to do to distinguish between
>>>> PSR exit latency and other potential sources of latency?
>>>
>>> It looks plausible that we could at least report how long it takes the
>>> registers to reflect the change in state (but we don't). The best source
>>> of information atm is /sys/kernel/debug/dri/0/i915_edp_psr_status.
>>
>> Hmm.
>>
>> I went and looked at the code, and I noticed what could be bugs or
>> could (more likely) be my confusion since I don't know this code at
>> all:
>>
>> intel_single_frame_update() does something inscrutable to me, but I
>> imagine it does something that causes the next page flip to get
>> noticed by the panel even with PSR on.  But how does the code that
>> calls it know that anything happened?  (Looking at the commit history,
>> maybe this is something special that's only needed on some platforms
>> but doesn't replace the normal PSR exit sequence.)
>>
>> Perhaps more interestingly, intel_psr_flush() does this:
>>
>>     /* By definition flush = invalidate + flush */
>>     if (frontbuffer_bits)
>>         intel_psr_exit(dev_priv);
>>
>>     if (!dev_priv->psr.active && !dev_priv->psr.busy_frontbuffer_bits)
>>         if (!work_busy(&dev_priv->psr.work.work))
>>             schedule_delayed_work(&dev_priv->psr.work,
>>                           msecs_to_jiffies(100));
>>
>> I'm guessing that the idea is that we're turning off PSR because we
>> want the panel to update and we expect that, in 100ms, the update will
>> have hit the panel and we'll have been idle long enough for it to make
>> sense to re-enter PSR.  IOW, the code wants PSR to be off for at least
>> 100ms and then to turn back on.  But this code actually says "turn PSR
>> back on in at *most* 100ms".  What happens if there are two screen
>> updates 99ms apart?  The first one should work fine, but the next one
>> will hit with 1ms left on the delayed work, and intel_psr_work() will
>> get called in 1ms.  There's some magic with busy_frontbuffer_bits, but
>> it seems questionable to me that intel_psr_flush() clears
>> busy_frontbuffer_bits and *then* calls intel_psr_exit().
>>
>> Naively, I would expect that PSR needs to be kept off until the vblank
>> following the page flip.
>>
>> Also, in intel_psr_work(), shouldn't this code:
>>
>>     /*
>>      * The delayed work can race with an invalidate hence we need to
>>      * recheck. Since psr_flush first clears this and then reschedules we
>>      * won't ever miss a flush when bailing out here.
>>      */
>>     if (dev_priv->psr.busy_frontbuffer_bits)
>>         goto unlock;
>>
>> re-arm the delayed work?
>>
>> Anyway, this is all on a 4.14 kernel.  I should update to 4.16 and see
>> what happens.
>
> I updated to 4.15, and the situation is much worse.  With
> enable_psr=1, the system survives for several seconds and then the
> screen stops updating entirely.  If I boot with i915.enable_psr=1, I
> get to the Fedora login screen and then the system dies.  If I set
> enable_psr=1 using sysfs, it does a bit after the next resume.  It
> seems like it also sometimes hangs even worse a bit after the screen
> stops updating, but it's hard to tell.
>
> I see this in my logs:
>
> [drm:drm_atomic_helper_wait_for_flip_done [drm_kms_helper]] *ERROR*
> [CRTC:37:pipe A] flip_done timed out
>
> Sometimes I see this a bit later:
>
> [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR*
> [CRTC:37:pipe A] flip_done timed out
>
> I'm able to get some debugging out before the system dies.  I see
> intel_psr_flush() getting called a bunch, and I don't see
> intel_psr_invalidate() being called at all.  I also see
> intel_psr_work() activating psr as little as 2ms after
> intel_psr_flush() finishes.  So I think the code is indeed buggy or at
> least questionable.  I'd try to fix it (at least as well as I can
> without knowing anything about how the PSR state machine actually
> works), but the fact that the system hangs would make it very hard to
> test.

I filed https://bugs.freedesktop.org/show_bug.cgi?id=104931 for the
questionable reactivation logic issue.  If nothing else, I doubt that
the reactivation timeout logic does what its author intended for it to
do.

--Andy
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: i915 PSR test results and cursor lag

[Andy Lutomirski]

On Sat, Feb 3, 2018 at 5:08 PM, Andy Lutomirski <luto@kernel.org> wrote:
> On Sat, Feb 3, 2018 at 5:20 AM, Pandiyan, Dhinakaran
> <dhinakaran.pandiyan@intel.com> wrote:
>>
>> On Fri, 2018-02-02 at 19:18 +0000, Andy Lutomirski wrote:
>>> I updated to 4.15, and the situation is much worse.  With
>>> enable_psr=1, the system survives for several seconds and then the
>>> screen stops updating entirely.  If I boot with i915.enable_psr=1, I
>>> get to the Fedora login screen and then the system dies.  If I set
>>> enable_psr=1 using sysfs, it does a bit after the next resume.  It
>>> seems like it also sometimes hangs even worse a bit after the screen
>>> stops updating, but it's hard to tell.
>>
>> The login screen freeze sounds like what I have. Does this system have
>> DMC firmware? If yes, can you try this series
>> https://patchwork.freedesktop.org/series/37598/. You'll only need
>> patches 1,8,9 and 10.
>
> That fixes the hang.  Feel free to add:
>
> Tested-by: Andy Lutomirski <luto@kernel.org>
>
> to the i915 parts.  Also, any chance of getting it into the 4.15 stable kernels?

Correction: I'm still getting a second or two of complete screen
freezing every now and then.  The kernel says:

[69400.016524] [drm:intel_pipe_update_end [i915]] *ERROR* Atomic
update failure on pipe A (start=19 end=20) time 198 us, min 1073, max
1079, scanline start 1068, end 1082

So something might still be a bit buggy.
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: i915 PSR test results and cursor lag

[Pandiyan, Dhinakaran]

On Sun, 2018-02-04 at 21:50 +0000, Andy Lutomirski wrote:
> On Sat, Feb 3, 2018 at 5:08 PM, Andy Lutomirski <luto@kernel.org> wrote:
> > On Sat, Feb 3, 2018 at 5:20 AM, Pandiyan, Dhinakaran
> > <dhinakaran.pandiyan@intel.com> wrote:
> >>
> >> On Fri, 2018-02-02 at 19:18 +0000, Andy Lutomirski wrote:
> >>> I updated to 4.15, and the situation is much worse.  With
> >>> enable_psr=1, the system survives for several seconds and then the
> >>> screen stops updating entirely.  If I boot with i915.enable_psr=1, I
> >>> get to the Fedora login screen and then the system dies.  If I set
> >>> enable_psr=1 using sysfs, it does a bit after the next resume.  It
> >>> seems like it also sometimes hangs even worse a bit after the screen
> >>> stops updating, but it's hard to tell.
> >>
> >> The login screen freeze sounds like what I have. Does this system have
> >> DMC firmware? If yes, can you try this series
> >> https://patchwork.freedesktop.org/series/37598/. You'll only need
> >> patches 1,8,9 and 10.
> >
> > That fixes the hang.  Feel free to add:
> >
> > Tested-by: Andy Lutomirski <luto@kernel.org>
> >
> > to the i915 parts.  Also, any chance of getting it into the 4.15 stable kernels?
> 
> Correction: I'm still getting a second or two of complete screen
> freezing every now and then.  The kernel says:
Thanks a lot for testing. How do you trigger this freeze? Moving the
cursor? Did you apply these patches on top of drm-tip or was it
mainline?

I also have another patch here that addresses screen freezes in console
mode with PSR - https://patchwork.freedesktop.org/patch/201144/ in case
that is what you are interested in.
> 
> [69400.016524] [drm:intel_pipe_update_end [i915]] *ERROR* Atomic
> update failure on pipe A (start=19 end=20) time 198 us, min 1073, max
> 1079, scanline start 1068, end 1082
> 
> So something might still be a bit buggy.

This series fixes only the long freezes due to frame counter resets, I
am sure there are still other issues with PSR.

BTW does your patch on top of these patches help with the cursor lag?

-DK
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [Intel-gfx] i915 PSR test results and cursor lag

[Andy Lutomirski]

On Mon, Feb 5, 2018 at 6:53 PM, Pandiyan, Dhinakaran
<dhinakaran.pandiyan@intel.com> wrote:
>
>
>
> On Sun, 2018-02-04 at 21:50 +0000, Andy Lutomirski wrote:
>> On Sat, Feb 3, 2018 at 5:08 PM, Andy Lutomirski <luto@kernel.org> wrote:
>> > On Sat, Feb 3, 2018 at 5:20 AM, Pandiyan, Dhinakaran
>> > <dhinakaran.pandiyan@intel.com> wrote:
>> >>
>> >> On Fri, 2018-02-02 at 19:18 +0000, Andy Lutomirski wrote:
>> >>> I updated to 4.15, and the situation is much worse.  With
>> >>> enable_psr=1, the system survives for several seconds and then the
>> >>> screen stops updating entirely.  If I boot with i915.enable_psr=1, I
>> >>> get to the Fedora login screen and then the system dies.  If I set
>> >>> enable_psr=1 using sysfs, it does a bit after the next resume.  It
>> >>> seems like it also sometimes hangs even worse a bit after the screen
>> >>> stops updating, but it's hard to tell.
>> >>
>> >> The login screen freeze sounds like what I have. Does this system have
>> >> DMC firmware? If yes, can you try this series
>> >> https://patchwork.freedesktop.org/series/37598/. You'll only need
>> >> patches 1,8,9 and 10.
>> >
>> > That fixes the hang.  Feel free to add:
>> >
>> > Tested-by: Andy Lutomirski <luto@kernel.org>
>> >
>> > to the i915 parts.  Also, any chance of getting it into the 4.15 stable kernels?
>>
>> Correction: I'm still getting a second or two of complete screen
>> freezing every now and then.  The kernel says:
> Thanks a lot for testing. How do you trigger this freeze? Moving the
> cursor? Did you apply these patches on top of drm-tip or was it
> mainline?
>
> I also have another patch here that addresses screen freezes in console
> mode with PSR - https://patchwork.freedesktop.org/patch/201144/ in case
> that is what you are interested in.
>>
>> [69400.016524] [drm:intel_pipe_update_end [i915]] *ERROR* Atomic
>> update failure on pipe A (start=19 end=20) time 198 us, min 1073, max
>> 1079, scanline start 1068, end 1082
>>
>> So something might still be a bit buggy.
>
> This series fixes only the long freezes due to frame counter resets, I
> am sure there are still other issues with PSR.
>
> BTW does your patch on top of these patches help with the cursor lag?

Maybe, but I'm not 100% sure.  I'm not currently seeing the lag with
or without the patch.  I also think my distro fixed the cursor in the
mean time so that it uses the HW cursor even after suspend/resume.

A couple of questions, though:

1. Does moving the HW cursor cause the hardware to automatically turn off PSR?

2 When something enables vblank interrupts (using drm_*_vblank_get(),
for example), are vblank interrupts generated even if PSR is on?  And
is the scanline, as returned by intel_get_crtc_scanline(), updated?
_______________________________________________
dri-devel mailing list
dri-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/dri-devel

Re: i915 PSR test results and cursor lag

[Pandiyan, Dhinakaran]

On Mon, 2018-02-05 at 20:35 +0000, Andy Lutomirski wrote:
> On Mon, Feb 5, 2018 at 6:53 PM, Pandiyan, Dhinakaran
> <dhinakaran.pandiyan@intel.com> wrote:
> >
> >
> >
> > On Sun, 2018-02-04 at 21:50 +0000, Andy Lutomirski wrote:
> >> On Sat, Feb 3, 2018 at 5:08 PM, Andy Lutomirski <luto@kernel.org> wrote:
> >> > On Sat, Feb 3, 2018 at 5:20 AM, Pandiyan, Dhinakaran
> >> > <dhinakaran.pandiyan@intel.com> wrote:
> >> >>
> >> >> On Fri, 2018-02-02 at 19:18 +0000, Andy Lutomirski wrote:
> >> >>> I updated to 4.15, and the situation is much worse.  With
> >> >>> enable_psr=1, the system survives for several seconds and then the
> >> >>> screen stops updating entirely.  If I boot with i915.enable_psr=1, I
> >> >>> get to the Fedora login screen and then the system dies.  If I set
> >> >>> enable_psr=1 using sysfs, it does a bit after the next resume.  It
> >> >>> seems like it also sometimes hangs even worse a bit after the screen
> >> >>> stops updating, but it's hard to tell.
> >> >>
> >> >> The login screen freeze sounds like what I have. Does this system have
> >> >> DMC firmware? If yes, can you try this series
> >> >> https://patchwork.freedesktop.org/series/37598/. You'll only need
> >> >> patches 1,8,9 and 10.
> >> >
> >> > That fixes the hang.  Feel free to add:
> >> >
> >> > Tested-by: Andy Lutomirski <luto@kernel.org>
> >> >
> >> > to the i915 parts.  Also, any chance of getting it into the 4.15 stable kernels?
> >>
> >> Correction: I'm still getting a second or two of complete screen
> >> freezing every now and then.  The kernel says:
> > Thanks a lot for testing. How do you trigger this freeze? Moving the
> > cursor? Did you apply these patches on top of drm-tip or was it
> > mainline?
> >
> > I also have another patch here that addresses screen freezes in console
> > mode with PSR - https://patchwork.freedesktop.org/patch/201144/ in case
> > that is what you are interested in.
> >>
> >> [69400.016524] [drm:intel_pipe_update_end [i915]] *ERROR* Atomic
> >> update failure on pipe A (start=19 end=20) time 198 us, min 1073, max
> >> 1079, scanline start 1068, end 1082
> >>
> >> So something might still be a bit buggy.
> >
> > This series fixes only the long freezes due to frame counter resets, I
> > am sure there are still other issues with PSR.
> >
> > BTW does your patch on top of these patches help with the cursor lag?
> 
> Maybe, but I'm not 100% sure.  I'm not currently seeing the lag with
> or without the patch.  I also think my distro fixed the cursor in the
> mean time so that it uses the HW cursor even after suspend/resume.
> 
> A couple of questions, though:
> 
> 1. Does moving the HW cursor cause the hardware to automatically turn off PSR?
> 
That is correct.

> 2 When something enables vblank interrupts (using drm_*_vblank_get(),
> for example), are vblank interrupts generated even if PSR is on?

Enabling vblank interrupts deactivates PSR (except on Braswell afaik)

>   And
> is the scanline, as returned by intel_get_crtc_scanline(), updated?

I don't think so, I have not really checked but there are no frames
generated, so the timing related registers will not get updated. This is
the case with the frame counter register.


> _______________________________________________
> Intel-gfx mailing list
> Intel-gfx@lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/intel-gfx
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: i915 PSR test results and cursor lag

[Andy Lutomirski]

On Mon, Feb 5, 2018 at 9:17 PM, Pandiyan, Dhinakaran
<dhinakaran.pandiyan@intel.com> wrote:
>
> On Mon, 2018-02-05 at 20:35 +0000, Andy Lutomirski wrote:
>> On Mon, Feb 5, 2018 at 6:53 PM, Pandiyan, Dhinakaran
>> <dhinakaran.pandiyan@intel.com> wrote:
>> >
>> >
>> >
>> > On Sun, 2018-02-04 at 21:50 +0000, Andy Lutomirski wrote:
>> >> On Sat, Feb 3, 2018 at 5:08 PM, Andy Lutomirski <luto@kernel.org> wrote:
>> >> > On Sat, Feb 3, 2018 at 5:20 AM, Pandiyan, Dhinakaran
>> >> > <dhinakaran.pandiyan@intel.com> wrote:
>> >> >>
>> >> >> On Fri, 2018-02-02 at 19:18 +0000, Andy Lutomirski wrote:
>> >> >>> I updated to 4.15, and the situation is much worse.  With
>> >> >>> enable_psr=1, the system survives for several seconds and then the
>> >> >>> screen stops updating entirely.  If I boot with i915.enable_psr=1, I
>> >> >>> get to the Fedora login screen and then the system dies.  If I set
>> >> >>> enable_psr=1 using sysfs, it does a bit after the next resume.  It
>> >> >>> seems like it also sometimes hangs even worse a bit after the screen
>> >> >>> stops updating, but it's hard to tell.
>> >> >>
>> >> >> The login screen freeze sounds like what I have. Does this system have
>> >> >> DMC firmware? If yes, can you try this series
>> >> >> https://patchwork.freedesktop.org/series/37598/. You'll only need
>> >> >> patches 1,8,9 and 10.
>> >> >
>> >> > That fixes the hang.  Feel free to add:
>> >> >
>> >> > Tested-by: Andy Lutomirski <luto@kernel.org>
>> >> >
>> >> > to the i915 parts.  Also, any chance of getting it into the 4.15 stable kernels?
>> >>
>> >> Correction: I'm still getting a second or two of complete screen
>> >> freezing every now and then.  The kernel says:
>> > Thanks a lot for testing. How do you trigger this freeze? Moving the
>> > cursor? Did you apply these patches on top of drm-tip or was it
>> > mainline?
>> >
>> > I also have another patch here that addresses screen freezes in console
>> > mode with PSR - https://patchwork.freedesktop.org/patch/201144/ in case
>> > that is what you are interested in.
>> >>
>> >> [69400.016524] [drm:intel_pipe_update_end [i915]] *ERROR* Atomic
>> >> update failure on pipe A (start=19 end=20) time 198 us, min 1073, max
>> >> 1079, scanline start 1068, end 1082
>> >>
>> >> So something might still be a bit buggy.
>> >
>> > This series fixes only the long freezes due to frame counter resets, I
>> > am sure there are still other issues with PSR.
>> >
>> > BTW does your patch on top of these patches help with the cursor lag?
>>
>> Maybe, but I'm not 100% sure.  I'm not currently seeing the lag with
>> or without the patch.  I also think my distro fixed the cursor in the
>> mean time so that it uses the HW cursor even after suspend/resume.
>>
>> A couple of questions, though:
>>
>> 1. Does moving the HW cursor cause the hardware to automatically turn off PSR?
>>
> That is correct.
>
>> 2 When something enables vblank interrupts (using drm_*_vblank_get(),
>> for example), are vblank interrupts generated even if PSR is on?
>
> Enabling vblank interrupts deactivates PSR (except on Braswell afaik)
>
>>   And
>> is the scanline, as returned by intel_get_crtc_scanline(), updated?
>
> I don't think so, I have not really checked but there are no frames
> generated, so the timing related registers will not get updated. This is
> the case with the frame counter register.
>

I bet that's the cause of some of the glitches I'm seeing.  I
instrumented intel_pipe_update_start() like this:

diff --git a/drivers/gpu/drm/i915/intel_sprite.c
b/drivers/gpu/drm/i915/intel_sprite.c
index 4a8a5d918a83..6ce0a35187fb 100644
--- a/drivers/gpu/drm/i915/intel_sprite.c
+++ b/drivers/gpu/drm/i915/intel_sprite.c
@@ -97,6 +97,7 @@ void intel_pipe_update_start(const struct
intel_crtc_state *new_crtc_state)
     bool need_vlv_dsi_wa = (IS_VALLEYVIEW(dev_priv) ||
IS_CHERRYVIEW(dev_priv)) &&
         intel_crtc_has_type(new_crtc_state, INTEL_OUTPUT_DSI);
     DEFINE_WAIT(wait);
+    int first_scanline = -1;

     vblank_start = adjusted_mode->crtc_vblank_start;
     if (adjusted_mode->flags & DRM_MODE_FLAG_INTERLACE)
@@ -131,9 +132,12 @@ void intel_pipe_update_start(const struct
intel_crtc_state *new_crtc_state)
         if (scanline < min || scanline > max)
             break;

+        if (first_scanline == -1)
+            first_scanline = scanline;
+
         if (timeout <= 0) {
-            DRM_ERROR("Potential atomic update failure on pipe %c\n",
-                  pipe_name(crtc->pipe));
+            DRM_ERROR("Potential atomic update failure on pipe %c.
scanline=%d, first_scanline=%d\n",
+                  pipe_name(crtc->pipe), scanline, first_scanline);
             break;
         }

and I got:

[drm:intel_pipe_update_start [i915]] *ERROR* Potential atomic update
failure on pipe A.  scanline=1079, first_scanline=1079

so it looks like it can get stuck if called at the wrong time.

Anyway, I'll send my patch.  I'm not convinced it fixes any of the
glitches I'm seeing, but I think it's a good improvement regardless.
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [Intel-gfx] i915 PSR test results and cursor lag

[Rodrigo Vivi]

On Thu, Feb 01, 2018 at 08:33:29PM +0000, Chris Wilson wrote:
> Quoting Kristian Høgsberg (2018-02-01 20:22:40)
> > On Thu, Feb 1, 2018 at 9:53 AM Chris Wilson <chris@chris-wilson.co.uk>
> > wrote:
> > 
> > > Quoting Andy Lutomirski (2018-02-01 17:40:22)
> > > > *However*, I do see one unfortunate side effect of turning on PSR.  It
> > > > seems that, when I move my cursor a little bit after a few seconds of
> > > > doing nothing, there seems to be a little bit of lag, as if either a
> > > > few frames are dropped at the beginning of the motion or maybe the
> > > > entire motion is delayed a bit.  I don't notice a similar delay when
> > > > typing, so I'm wondering if maybe there's a min
> > > or driver bug in which
> > > > the driver doesn't kick the panel out of PSR quite as quickly when the
> > > > cursor is updated as it does when the framebuffer is updated.
> > 
> > > One thing that's important know regarding the cursor is whether the
> > > display server is using a HW cursor or SW cursor. Could you please attach
> > > the log from the display server (or if you are using a stock
> > > distribution that's probably enough to work out what it is using)?
> > > -Chris
> > 
> > We had a similar problem for Rockchip in ChromeOS and ended up using an
> > input handler to let us start the PSR exit as early as possible:
> 
> Reminds me of mutter devs suggesting that we may like to kick the gpu to
> max clocks high frequency on any input activity as well. (I'm still not
> convinced that's a good idea, for mundane typing we barely need to wake
> up the gpu. :) I guess it all depends on expected wakeup latencies, but
> I didn't think PSR had multi-frame lag?

yeap. This shouldn't be needed for PSR. The wakeup latency is definitely
not a problem here.
All the current PSR related corner cases and limitations are probably
still related to *what* cases to exit PSR rather than *when*.

So I'd say the governor there is probably covering few of missing cases.

> -Chris
_______________________________________________
dri-devel mailing list
dri-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/dri-devel

Re: [Intel-gfx] i915 PSR test results and cursor lag

[Rodrigo Vivi]

On Mon, Feb 05, 2018 at 08:35:25PM +0000, Andy Lutomirski wrote:

Andy, first of all thank you very much for those findings.

> On Mon, Feb 5, 2018 at 6:53 PM, Pandiyan, Dhinakaran
> <dhinakaran.pandiyan@intel.com> wrote:
> >
> >
> >
> > On Sun, 2018-02-04 at 21:50 +0000, Andy Lutomirski wrote:
> >> On Sat, Feb 3, 2018 at 5:08 PM, Andy Lutomirski <luto@kernel.org> wrote:
> >> > On Sat, Feb 3, 2018 at 5:20 AM, Pandiyan, Dhinakaran
> >> > <dhinakaran.pandiyan@intel.com> wrote:
> >> >>
> >> >> On Fri, 2018-02-02 at 19:18 +0000, Andy Lutomirski wrote:
> >> >>> I updated to 4.15, and the situation is much worse.  With
> >> >>> enable_psr=1, the system survives for several seconds and then the
> >> >>> screen stops updating entirely.  If I boot with i915.enable_psr=1, I
> >> >>> get to the Fedora login screen and then the system dies.  If I set
> >> >>> enable_psr=1 using sysfs, it does a bit after the next resume.  It
> >> >>> seems like it also sometimes hangs even worse a bit after the screen
> >> >>> stops updating, but it's hard to tell.
> >> >>
> >> >> The login screen freeze sounds like what I have. Does this system have
> >> >> DMC firmware? If yes, can you try this series
> >> >> https://patchwork.freedesktop.org/series/37598/. You'll only need
> >> >> patches 1,8,9 and 10.
> >> >
> >> > That fixes the hang.  Feel free to add:
> >> >
> >> > Tested-by: Andy Lutomirski <luto@kernel.org>
> >> >
> >> > to the i915 parts.  Also, any chance of getting it into the 4.15 stable kernels?
> >>
> >> Correction: I'm still getting a second or two of complete screen
> >> freezing every now and then.  The kernel says:
> > Thanks a lot for testing. How do you trigger this freeze? Moving the
> > cursor? Did you apply these patches on top of drm-tip or was it
> > mainline?
> >
> > I also have another patch here that addresses screen freezes in console
> > mode with PSR - https://patchwork.freedesktop.org/patch/201144/ in case
> > that is what you are interested in.
> >>
> >> [69400.016524] [drm:intel_pipe_update_end [i915]] *ERROR* Atomic
> >> update failure on pipe A (start=19 end=20) time 198 us, min 1073, max
> >> 1079, scanline start 1068, end 1082
> >>
> >> So something might still be a bit buggy.
> >
> > This series fixes only the long freezes due to frame counter resets, I
> > am sure there are still other issues with PSR.
> >
> > BTW does your patch on top of these patches help with the cursor lag?

Andy, what happens if you keep psr enabled but disable dc state (i915.enable_dc=0).
Do you still see cursor lag in this case?

> 
> Maybe, but I'm not 100% sure.  I'm not currently seeing the lag with
> or without the patch.  I also think my distro fixed the cursor in the
> mean time so that it uses the HW cursor even after suspend/resume.
> 
> A couple of questions, though:
> 
> 1. Does moving the HW cursor cause the hardware to automatically turn off PSR?
> 
> 2 When something enables vblank interrupts (using drm_*_vblank_get(),
> for example), are vblank interrupts generated even if PSR is on?  And
> is the scanline, as returned by intel_get_crtc_scanline(), updated?
_______________________________________________
dri-devel mailing list
dri-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/dri-devel

Re: [Intel-gfx] i915 PSR test results and cursor lag

[Rodrigo Vivi]

On Sat, Feb 03, 2018 at 05:33:08PM +0000, Andy Lutomirski wrote:
> On Fri, Feb 2, 2018 at 7:18 PM, Andy Lutomirski <luto@kernel.org> wrote:
> > On Fri, Feb 2, 2018 at 1:24 AM, Andy Lutomirski <luto@kernel.org> wrote:
> >> On Thu, Feb 1, 2018 at 9:20 PM, Chris Wilson <chris@chris-wilson.co.uk> wrote:
> >>> Quoting Andy Lutomirski (2018-02-01 21:04:30)
> >>>> I got this after a recent suspend/resume:
> >>>>
> >>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Lid closed.
> >>>> Feb 01 09:44:34 laptop systemd-logind[2412]: device-enumerator: scan all dirs
> >>>> Feb 01 09:44:34 laptop systemd-logind[2412]:   device-enumerator:
> >>>> scanning /sys/bus
> >>>> Feb 01 09:44:34 laptop systemd-logind[2412]:   device-enumerator:
> >>>> scanning /sys/class
> >>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Failed to open
> >>>> configuration file '/etc/systemd/sleep.conf': No such file or
> >>>> directory
> >>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Suspending...
> >>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Sent message type=signal
> >>>> sender=n/a destination=n/a object=/org/freedesktop/login1
> >>>> interface=org.freedesktop.login1.Manager member=PrepareForSleep
> >>>> cookie=570 reply
> >>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Got message
> >>>> type=method_call sender=:1.46 destination=:1.1
> >>>> object=/org/freedesktop/login1/session/_32
> >>>> interface=org.freedesktop.login1.Session member=ReleaseDevice
> >>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Sent message type=signal
> >>>> sender=n/a destination=:1.46
> >>>> object=/org/freedesktop/login1/session/_32
> >>>> interface=org.freedesktop.login1.Session member=PauseDevice cookie
> >>>> Feb 01 09:44:34 laptop gnome-shell[2630]: Failed to apply DRM plane
> >>>> transform 0: Permission denied
> >>>> Feb 01 09:44:34 laptop gnome-shell[2630]: drmModeSetCursor2 failed
> >>>> with (Permission denied), drawing cursor with OpenGL from now on
> >>>>
> >>>> But I don't see the word "cursor" in my system logs before the first
> >>>> suspend.  What am I looking for?  This is Fedora 27 running a Gnome
> >>>> Wayland session, but it hasn't been reinstalled in some time, so it's
> >>>> possible that there are some weird settings sitting around.  But I did
> >>>> check and I have no weird i915 parameters.
> >>>
> >>> You are using gnome-shell as the display server. From that it appears to
> >>> have started off with a HW cursor and switched to a SW cursor after
> >>> suspend. Did you notice a change in behaviour? After rebooting or just
> >>> restarting gnome-shell?
> >>
> >> I think it's less consistently bad after a reboot before suspending.
> >>
> >>>
> >>>> Also, are these things potentially related:
> >>>>
> >>>> [ 3067.702527] [drm:intel_pipe_update_start [i915]] *ERROR* Potential
> >>>> atomic update failure on pipe A
> >>>
> >>> They are just "missed the immediate vblank for the screen update"
> >>> messages. Should not be related to PSR, but may cause jitter by delaying
> >>> the odd screen update.
> >>
> >> I just got this one, and the timestamp is at least reasonably close to
> >> a giant latency spike:
> >>
> >> [  288.799654] [drm:intel_pipe_update_end [i915]] *ERROR* Atomic
> >> update failure on pipe A (start=31 end=32) time 15 us, min 1073, max
> >> 1079, scanline start 1087, end 1088
> >>
> >>>
> >>>> As I'm typing this, I've seen a couple instances of what seems like a
> >>>> full *second* of cursor latency, but I've only gotten the potential
> >>>> atomic update failure once.
> >>>>
> >>>> And is there any straightforward tracing to do to distinguish between
> >>>> PSR exit latency and other potential sources of latency?
> >>>
> >>> It looks plausible that we could at least report how long it takes the
> >>> registers to reflect the change in state (but we don't). The best source
> >>> of information atm is /sys/kernel/debug/dri/0/i915_edp_psr_status.
> >>
> >> Hmm.
> >>
> >> I went and looked at the code, and I noticed what could be bugs or
> >> could (more likely) be my confusion since I don't know this code at
> >> all:
> >>
> >> intel_single_frame_update() does something inscrutable to me, but I
> >> imagine it does something that causes the next page flip to get
> >> noticed by the panel even with PSR on.  But how does the code that
> >> calls it know that anything happened?  (Looking at the commit history,
> >> maybe this is something special that's only needed on some platforms
> >> but doesn't replace the normal PSR exit sequence.)
> >>
> >> Perhaps more interestingly, intel_psr_flush() does this:
> >>
> >>     /* By definition flush = invalidate + flush */
> >>     if (frontbuffer_bits)
> >>         intel_psr_exit(dev_priv);
> >>
> >>     if (!dev_priv->psr.active && !dev_priv->psr.busy_frontbuffer_bits)
> >>         if (!work_busy(&dev_priv->psr.work.work))
> >>             schedule_delayed_work(&dev_priv->psr.work,
> >>                           msecs_to_jiffies(100));
> >>
> >> I'm guessing that the idea is that we're turning off PSR because we
> >> want the panel to update and we expect that, in 100ms, the update will
> >> have hit the panel and we'll have been idle long enough for it to make
> >> sense to re-enter PSR.  IOW, the code wants PSR to be off for at least
> >> 100ms and then to turn back on.  But this code actually says "turn PSR
> >> back on in at *most* 100ms".  What happens if there are two screen
> >> updates 99ms apart?  The first one should work fine, but the next one
> >> will hit with 1ms left on the delayed work, and intel_psr_work() will
> >> get called in 1ms.  There's some magic with busy_frontbuffer_bits, but
> >> it seems questionable to me that intel_psr_flush() clears
> >> busy_frontbuffer_bits and *then* calls intel_psr_exit().
> >>
> >> Naively, I would expect that PSR needs to be kept off until the vblank
> >> following the page flip.
> >>
> >> Also, in intel_psr_work(), shouldn't this code:
> >>
> >>     /*
> >>      * The delayed work can race with an invalidate hence we need to
> >>      * recheck. Since psr_flush first clears this and then reschedules we
> >>      * won't ever miss a flush when bailing out here.
> >>      */
> >>     if (dev_priv->psr.busy_frontbuffer_bits)
> >>         goto unlock;
> >>
> >> re-arm the delayed work?
> >>
> >> Anyway, this is all on a 4.14 kernel.  I should update to 4.16 and see
> >> what happens.
> >
> > I updated to 4.15, and the situation is much worse.  With
> > enable_psr=1, the system survives for several seconds and then the
> > screen stops updating entirely.  If I boot with i915.enable_psr=1, I
> > get to the Fedora login screen and then the system dies.  If I set
> > enable_psr=1 using sysfs, it does a bit after the next resume.  It
> > seems like it also sometimes hangs even worse a bit after the screen
> > stops updating, but it's hard to tell.
> >
> > I see this in my logs:
> >
> > [drm:drm_atomic_helper_wait_for_flip_done [drm_kms_helper]] *ERROR*
> > [CRTC:37:pipe A] flip_done timed out
> >
> > Sometimes I see this a bit later:
> >
> > [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR*
> > [CRTC:37:pipe A] flip_done timed out
> >
> > I'm able to get some debugging out before the system dies.  I see
> > intel_psr_flush() getting called a bunch, and I don't see
> > intel_psr_invalidate() being called at all.  I also see
> > intel_psr_work() activating psr as little as 2ms after
> > intel_psr_flush() finishes.  So I think the code is indeed buggy or at
> > least questionable.  I'd try to fix it (at least as well as I can
> > without knowing anything about how the PSR state machine actually
> > works), but the fact that the system hangs would make it very hard to
> > test.
> 
> I filed https://bugs.freedesktop.org/show_bug.cgi?id=104931 for the
> questionable reactivation logic issue.  If nothing else, I doubt that
> the reactivation timeout logic does what its author intended for it to
> do.

Thanks for that. I will check the logic and your patch here.

One thing to consider is that when activating PSR HW engine will
consider the number of static frames before transitioning it to
active state. So, in general the immediate return to active status
shouldn't be a problem.
At least not for core platforms. maybe for vlv/chv.

> 
> --Andy
_______________________________________________
dri-devel mailing list
dri-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/dri-devel

Re: i915 PSR test results and cursor lag

[Rodrigo Vivi]

On Thu, Feb 01, 2018 at 05:43:56PM +0000, Andy Lutomirski wrote:
> On Thu, Feb 1, 2018 at 9:40 AM, Andy Lutomirski <luto@kernel.org> wrote:
> > Hi-
> >
> > As requested in your blog post, I tested PSR.  I see something like
> > 2.69W with PSR off and 2.17W with PSR on.  Screen blanking,
> > suspend/resume, and the contents of the screen all seem okay.  This is
> > a Dell XPS 13 9350, i.e.:
> >
> > System Information
> >         Manufacturer: Dell Inc.
> >         Product Name: XPS 13 9350
> >
> > EDID is attached.
> >
> > *However*, I do see one unfortunate side effect of turning on PSR.  It
> > seems that, when I move my cursor a little bit after a few seconds of
> > doing nothing, there seems to be a little bit of lag, as if either a
> > few frames are dropped at the beginning of the motion or maybe the
> > entire motion is delayed a bit.  I don't notice a similar delay when
> > typing, so I'm wondering if maybe there's a minor driver bug in which
> > the driver doesn't kick the panel out of PSR quite as quickly when the
> > cursor is updated as it does when the framebuffer is updated.
> >
> 
> I'm also getting occasional messages like:
> 
> [ 2675.574486] [drm:intel_pipe_update_start [i915]] *ERROR* Potential
> atomic update failure on pipe A
> 
> with PSR on.  But there is nowhere near one of these messages per tiny
> lag incident.

That's indeed strange.
I believe that should also be part of PSR + DMC, so could you check if you
see this with psr enabled + dc state disabled?

I wonder if those I915_READ_FW are not waking DMC hence reading 0 in some
registers.

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: i915 PSR test results and cursor lag

[Andy Lutomirski]

> On Feb 5, 2018, at 2:50 PM, Rodrigo Vivi <rodrigo.vivi@intel.com> wrote:
> 
>> On Sat, Feb 03, 2018 at 05:33:08PM +0000, Andy Lutomirski wrote:
>>> On Fri, Feb 2, 2018 at 7:18 PM, Andy Lutomirski <luto@kernel.org> wrote:
>>>> On Fri, Feb 2, 2018 at 1:24 AM, Andy Lutomirski <luto@kernel.org> wrote:
>>>>> On Thu, Feb 1, 2018 at 9:20 PM, Chris Wilson <chris@chris-wilson.co.uk> wrote:
>>>>> Quoting Andy Lutomirski (2018-02-01 21:04:30)
>>>>>> I got this after a recent suspend/resume:
>>>>>> 
>>>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Lid closed.
>>>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: device-enumerator: scan all dirs
>>>>>> Feb 01 09:44:34 laptop systemd-logind[2412]:   device-enumerator:
>>>>>> scanning /sys/bus
>>>>>> Feb 01 09:44:34 laptop systemd-logind[2412]:   device-enumerator:
>>>>>> scanning /sys/class
>>>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Failed to open
>>>>>> configuration file '/etc/systemd/sleep.conf': No such file or
>>>>>> directory
>>>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Suspending...
>>>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Sent message type=signal
>>>>>> sender=n/a destination=n/a object=/org/freedesktop/login1
>>>>>> interface=org.freedesktop.login1.Manager member=PrepareForSleep
>>>>>> cookie=570 reply
>>>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Got message
>>>>>> type=method_call sender=:1.46 destination=:1.1
>>>>>> object=/org/freedesktop/login1/session/_32
>>>>>> interface=org.freedesktop.login1.Session member=ReleaseDevice
>>>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Sent message type=signal
>>>>>> sender=n/a destination=:1.46
>>>>>> object=/org/freedesktop/login1/session/_32
>>>>>> interface=org.freedesktop.login1.Session member=PauseDevice cookie
>>>>>> Feb 01 09:44:34 laptop gnome-shell[2630]: Failed to apply DRM plane
>>>>>> transform 0: Permission denied
>>>>>> Feb 01 09:44:34 laptop gnome-shell[2630]: drmModeSetCursor2 failed
>>>>>> with (Permission denied), drawing cursor with OpenGL from now on
>>>>>> 
>>>>>> But I don't see the word "cursor" in my system logs before the first
>>>>>> suspend.  What am I looking for?  This is Fedora 27 running a Gnome
>>>>>> Wayland session, but it hasn't been reinstalled in some time, so it's
>>>>>> possible that there are some weird settings sitting around.  But I did
>>>>>> check and I have no weird i915 parameters.
>>>>> 
>>>>> You are using gnome-shell as the display server. From that it appears to
>>>>> have started off with a HW cursor and switched to a SW cursor after
>>>>> suspend. Did you notice a change in behaviour? After rebooting or just
>>>>> restarting gnome-shell?
>>>> 
>>>> I think it's less consistently bad after a reboot before suspending.
>>>> 
>>>>> 
>>>>>> Also, are these things potentially related:
>>>>>> 
>>>>>> [ 3067.702527] [drm:intel_pipe_update_start [i915]] *ERROR* Potential
>>>>>> atomic update failure on pipe A
>>>>> 
>>>>> They are just "missed the immediate vblank for the screen update"
>>>>> messages. Should not be related to PSR, but may cause jitter by delaying
>>>>> the odd screen update.
>>>> 
>>>> I just got this one, and the timestamp is at least reasonably close to
>>>> a giant latency spike:
>>>> 
>>>> [  288.799654] [drm:intel_pipe_update_end [i915]] *ERROR* Atomic
>>>> update failure on pipe A (start=31 end=32) time 15 us, min 1073, max
>>>> 1079, scanline start 1087, end 1088
>>>> 
>>>>> 
>>>>>> As I'm typing this, I've seen a couple instances of what seems like a
>>>>>> full *second* of cursor latency, but I've only gotten the potential
>>>>>> atomic update failure once.
>>>>>> 
>>>>>> And is there any straightforward tracing to do to distinguish between
>>>>>> PSR exit latency and other potential sources of latency?
>>>>> 
>>>>> It looks plausible that we could at least report how long it takes the
>>>>> registers to reflect the change in state (but we don't). The best source
>>>>> of information atm is /sys/kernel/debug/dri/0/i915_edp_psr_status.
>>>> 
>>>> Hmm.
>>>> 
>>>> I went and looked at the code, and I noticed what could be bugs or
>>>> could (more likely) be my confusion since I don't know this code at
>>>> all:
>>>> 
>>>> intel_single_frame_update() does something inscrutable to me, but I
>>>> imagine it does something that causes the next page flip to get
>>>> noticed by the panel even with PSR on.  But how does the code that
>>>> calls it know that anything happened?  (Looking at the commit history,
>>>> maybe this is something special that's only needed on some platforms
>>>> but doesn't replace the normal PSR exit sequence.)
>>>> 
>>>> Perhaps more interestingly, intel_psr_flush() does this:
>>>> 
>>>>    /* By definition flush = invalidate + flush */
>>>>    if (frontbuffer_bits)
>>>>        intel_psr_exit(dev_priv);
>>>> 
>>>>    if (!dev_priv->psr.active && !dev_priv->psr.busy_frontbuffer_bits)
>>>>        if (!work_busy(&dev_priv->psr.work.work))
>>>>            schedule_delayed_work(&dev_priv->psr.work,
>>>>                          msecs_to_jiffies(100));
>>>> 
>>>> I'm guessing that the idea is that we're turning off PSR because we
>>>> want the panel to update and we expect that, in 100ms, the update will
>>>> have hit the panel and we'll have been idle long enough for it to make
>>>> sense to re-enter PSR.  IOW, the code wants PSR to be off for at least
>>>> 100ms and then to turn back on.  But this code actually says "turn PSR
>>>> back on in at *most* 100ms".  What happens if there are two screen
>>>> updates 99ms apart?  The first one should work fine, but the next one
>>>> will hit with 1ms left on the delayed work, and intel_psr_work() will
>>>> get called in 1ms.  There's some magic with busy_frontbuffer_bits, but
>>>> it seems questionable to me that intel_psr_flush() clears
>>>> busy_frontbuffer_bits and *then* calls intel_psr_exit().
>>>> 
>>>> Naively, I would expect that PSR needs to be kept off until the vblank
>>>> following the page flip.
>>>> 
>>>> Also, in intel_psr_work(), shouldn't this code:
>>>> 
>>>>    /*
>>>>     * The delayed work can race with an invalidate hence we need to
>>>>     * recheck. Since psr_flush first clears this and then reschedules we
>>>>     * won't ever miss a flush when bailing out here.
>>>>     */
>>>>    if (dev_priv->psr.busy_frontbuffer_bits)
>>>>        goto unlock;
>>>> 
>>>> re-arm the delayed work?
>>>> 
>>>> Anyway, this is all on a 4.14 kernel.  I should update to 4.16 and see
>>>> what happens.
>>> 
>>> I updated to 4.15, and the situation is much worse.  With
>>> enable_psr=1, the system survives for several seconds and then the
>>> screen stops updating entirely.  If I boot with i915.enable_psr=1, I
>>> get to the Fedora login screen and then the system dies.  If I set
>>> enable_psr=1 using sysfs, it does a bit after the next resume.  It
>>> seems like it also sometimes hangs even worse a bit after the screen
>>> stops updating, but it's hard to tell.
>>> 
>>> I see this in my logs:
>>> 
>>> [drm:drm_atomic_helper_wait_for_flip_done [drm_kms_helper]] *ERROR*
>>> [CRTC:37:pipe A] flip_done timed out
>>> 
>>> Sometimes I see this a bit later:
>>> 
>>> [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR*
>>> [CRTC:37:pipe A] flip_done timed out
>>> 
>>> I'm able to get some debugging out before the system dies.  I see
>>> intel_psr_flush() getting called a bunch, and I don't see
>>> intel_psr_invalidate() being called at all.  I also see
>>> intel_psr_work() activating psr as little as 2ms after
>>> intel_psr_flush() finishes.  So I think the code is indeed buggy or at
>>> least questionable.  I'd try to fix it (at least as well as I can
>>> without knowing anything about how the PSR state machine actually
>>> works), but the fact that the system hangs would make it very hard to
>>> test.
>> 
>> I filed https://bugs.freedesktop.org/show_bug.cgi?id=104931 for the
>> questionable reactivation logic issue.  If nothing else, I doubt that
>> the reactivation timeout logic does what its author intended for it to
>> do.
> 
> Thanks for that. I will check the logic and your patch here.
> 
> One thing to consider is that when activating PSR HW engine will
> consider the number of static frames before transitioning it to
> active state. So, in general the immediate return to active status
> shouldn't be a problem.
> At least not for core platforms. maybe for vlv/chv.
> 

Hmm.  Is there some register that can be poked to tell the hardware "hey, I updated the image even if your dirty tracking didn't notice, so turn off PSR if it's on and reset your idle frame counter"?  If so, the logic could be dramatically simplified.
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: i915 PSR test results and cursor lag

[Rodrigo Vivi]

On Mon, Feb 05, 2018 at 11:54:04PM +0000, Andy Lutomirski wrote:
> 
> 
> > On Feb 5, 2018, at 2:50 PM, Rodrigo Vivi <rodrigo.vivi@intel.com> wrote:
> > 
> >> On Sat, Feb 03, 2018 at 05:33:08PM +0000, Andy Lutomirski wrote:
> >>> On Fri, Feb 2, 2018 at 7:18 PM, Andy Lutomirski <luto@kernel.org> wrote:
> >>>> On Fri, Feb 2, 2018 at 1:24 AM, Andy Lutomirski <luto@kernel.org> wrote:
> >>>>> On Thu, Feb 1, 2018 at 9:20 PM, Chris Wilson <chris@chris-wilson.co.uk> wrote:
> >>>>> Quoting Andy Lutomirski (2018-02-01 21:04:30)
> >>>>>> I got this after a recent suspend/resume:
> >>>>>> 
> >>>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Lid closed.
> >>>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: device-enumerator: scan all dirs
> >>>>>> Feb 01 09:44:34 laptop systemd-logind[2412]:   device-enumerator:
> >>>>>> scanning /sys/bus
> >>>>>> Feb 01 09:44:34 laptop systemd-logind[2412]:   device-enumerator:
> >>>>>> scanning /sys/class
> >>>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Failed to open
> >>>>>> configuration file '/etc/systemd/sleep.conf': No such file or
> >>>>>> directory
> >>>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Suspending...
> >>>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Sent message type=signal
> >>>>>> sender=n/a destination=n/a object=/org/freedesktop/login1
> >>>>>> interface=org.freedesktop.login1.Manager member=PrepareForSleep
> >>>>>> cookie=570 reply
> >>>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Got message
> >>>>>> type=method_call sender=:1.46 destination=:1.1
> >>>>>> object=/org/freedesktop/login1/session/_32
> >>>>>> interface=org.freedesktop.login1.Session member=ReleaseDevice
> >>>>>> Feb 01 09:44:34 laptop systemd-logind[2412]: Sent message type=signal
> >>>>>> sender=n/a destination=:1.46
> >>>>>> object=/org/freedesktop/login1/session/_32
> >>>>>> interface=org.freedesktop.login1.Session member=PauseDevice cookie
> >>>>>> Feb 01 09:44:34 laptop gnome-shell[2630]: Failed to apply DRM plane
> >>>>>> transform 0: Permission denied
> >>>>>> Feb 01 09:44:34 laptop gnome-shell[2630]: drmModeSetCursor2 failed
> >>>>>> with (Permission denied), drawing cursor with OpenGL from now on
> >>>>>> 
> >>>>>> But I don't see the word "cursor" in my system logs before the first
> >>>>>> suspend.  What am I looking for?  This is Fedora 27 running a Gnome
> >>>>>> Wayland session, but it hasn't been reinstalled in some time, so it's
> >>>>>> possible that there are some weird settings sitting around.  But I did
> >>>>>> check and I have no weird i915 parameters.
> >>>>> 
> >>>>> You are using gnome-shell as the display server. From that it appears to
> >>>>> have started off with a HW cursor and switched to a SW cursor after
> >>>>> suspend. Did you notice a change in behaviour? After rebooting or just
> >>>>> restarting gnome-shell?
> >>>> 
> >>>> I think it's less consistently bad after a reboot before suspending.
> >>>> 
> >>>>> 
> >>>>>> Also, are these things potentially related:
> >>>>>> 
> >>>>>> [ 3067.702527] [drm:intel_pipe_update_start [i915]] *ERROR* Potential
> >>>>>> atomic update failure on pipe A
> >>>>> 
> >>>>> They are just "missed the immediate vblank for the screen update"
> >>>>> messages. Should not be related to PSR, but may cause jitter by delaying
> >>>>> the odd screen update.
> >>>> 
> >>>> I just got this one, and the timestamp is at least reasonably close to
> >>>> a giant latency spike:
> >>>> 
> >>>> [  288.799654] [drm:intel_pipe_update_end [i915]] *ERROR* Atomic
> >>>> update failure on pipe A (start=31 end=32) time 15 us, min 1073, max
> >>>> 1079, scanline start 1087, end 1088
> >>>> 
> >>>>> 
> >>>>>> As I'm typing this, I've seen a couple instances of what seems like a
> >>>>>> full *second* of cursor latency, but I've only gotten the potential
> >>>>>> atomic update failure once.
> >>>>>> 
> >>>>>> And is there any straightforward tracing to do to distinguish between
> >>>>>> PSR exit latency and other potential sources of latency?
> >>>>> 
> >>>>> It looks plausible that we could at least report how long it takes the
> >>>>> registers to reflect the change in state (but we don't). The best source
> >>>>> of information atm is /sys/kernel/debug/dri/0/i915_edp_psr_status.
> >>>> 
> >>>> Hmm.
> >>>> 
> >>>> I went and looked at the code, and I noticed what could be bugs or
> >>>> could (more likely) be my confusion since I don't know this code at
> >>>> all:
> >>>> 
> >>>> intel_single_frame_update() does something inscrutable to me, but I
> >>>> imagine it does something that causes the next page flip to get
> >>>> noticed by the panel even with PSR on.  But how does the code that
> >>>> calls it know that anything happened?  (Looking at the commit history,
> >>>> maybe this is something special that's only needed on some platforms
> >>>> but doesn't replace the normal PSR exit sequence.)
> >>>> 
> >>>> Perhaps more interestingly, intel_psr_flush() does this:
> >>>> 
> >>>>    /* By definition flush = invalidate + flush */
> >>>>    if (frontbuffer_bits)
> >>>>        intel_psr_exit(dev_priv);
> >>>> 
> >>>>    if (!dev_priv->psr.active && !dev_priv->psr.busy_frontbuffer_bits)
> >>>>        if (!work_busy(&dev_priv->psr.work.work))
> >>>>            schedule_delayed_work(&dev_priv->psr.work,
> >>>>                          msecs_to_jiffies(100));
> >>>> 
> >>>> I'm guessing that the idea is that we're turning off PSR because we
> >>>> want the panel to update and we expect that, in 100ms, the update will
> >>>> have hit the panel and we'll have been idle long enough for it to make
> >>>> sense to re-enter PSR.  IOW, the code wants PSR to be off for at least
> >>>> 100ms and then to turn back on.  But this code actually says "turn PSR
> >>>> back on in at *most* 100ms".  What happens if there are two screen
> >>>> updates 99ms apart?  The first one should work fine, but the next one
> >>>> will hit with 1ms left on the delayed work, and intel_psr_work() will
> >>>> get called in 1ms.  There's some magic with busy_frontbuffer_bits, but
> >>>> it seems questionable to me that intel_psr_flush() clears
> >>>> busy_frontbuffer_bits and *then* calls intel_psr_exit().
> >>>> 
> >>>> Naively, I would expect that PSR needs to be kept off until the vblank
> >>>> following the page flip.
> >>>> 
> >>>> Also, in intel_psr_work(), shouldn't this code:
> >>>> 
> >>>>    /*
> >>>>     * The delayed work can race with an invalidate hence we need to
> >>>>     * recheck. Since psr_flush first clears this and then reschedules we
> >>>>     * won't ever miss a flush when bailing out here.
> >>>>     */
> >>>>    if (dev_priv->psr.busy_frontbuffer_bits)
> >>>>        goto unlock;
> >>>> 
> >>>> re-arm the delayed work?
> >>>> 
> >>>> Anyway, this is all on a 4.14 kernel.  I should update to 4.16 and see
> >>>> what happens.
> >>> 
> >>> I updated to 4.15, and the situation is much worse.  With
> >>> enable_psr=1, the system survives for several seconds and then the
> >>> screen stops updating entirely.  If I boot with i915.enable_psr=1, I
> >>> get to the Fedora login screen and then the system dies.  If I set
> >>> enable_psr=1 using sysfs, it does a bit after the next resume.  It
> >>> seems like it also sometimes hangs even worse a bit after the screen
> >>> stops updating, but it's hard to tell.
> >>> 
> >>> I see this in my logs:
> >>> 
> >>> [drm:drm_atomic_helper_wait_for_flip_done [drm_kms_helper]] *ERROR*
> >>> [CRTC:37:pipe A] flip_done timed out
> >>> 
> >>> Sometimes I see this a bit later:
> >>> 
> >>> [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR*
> >>> [CRTC:37:pipe A] flip_done timed out
> >>> 
> >>> I'm able to get some debugging out before the system dies.  I see
> >>> intel_psr_flush() getting called a bunch, and I don't see
> >>> intel_psr_invalidate() being called at all.  I also see
> >>> intel_psr_work() activating psr as little as 2ms after
> >>> intel_psr_flush() finishes.  So I think the code is indeed buggy or at
> >>> least questionable.  I'd try to fix it (at least as well as I can
> >>> without knowing anything about how the PSR state machine actually
> >>> works), but the fact that the system hangs would make it very hard to
> >>> test.
> >> 
> >> I filed https://bugs.freedesktop.org/show_bug.cgi?id=104931 for the
> >> questionable reactivation logic issue.  If nothing else, I doubt that
> >> the reactivation timeout logic does what its author intended for it to
> >> do.
> > 
> > Thanks for that. I will check the logic and your patch here.
> > 
> > One thing to consider is that when activating PSR HW engine will
> > consider the number of static frames before transitioning it to
> > active state. So, in general the immediate return to active status
> > shouldn't be a problem.
> > At least not for core platforms. maybe for vlv/chv.
> > 
> 
> Hmm.  Is there some register that can be poked to tell the hardware "hey, I updated the image even if your dirty tracking didn't notice, so turn off PSR if it's on and reset your idle frame counter"?  If so, the logic could be dramatically simplified.

that would be my dream ;)

But the only thing we can do is to disable psr and re-enable it. So the frame counter will restart.
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx