Bug 50078

Created attachment 61778 [details]
i915_error_state

Created attachment 61779 [details]
intel_reg_dumper.txt

Created attachment 61780 [details]
Xorg.0.log

Created attachment 61781 [details]
dmesg with drm.debug=0x06

Can you please attach a drm.debug=7 dmesg from across the s&r to the hang?

Can you please install the intel-sna package and test whether the workaround SNA uses is sufficient to detect when the pipe is off (as well as the request for drm.debug=7 across the suspend)?

Created attachment 61910 [details]
syslog with drm.debug=0x07

Here's syslog with drm.debug=0x07.

Maybe not so much the xorg driver bug after all:

May 21 07:37:25 htpc kernel: [   42.544787] Restarting tasks ... done.
May 21 07:37:25 htpc acpid: client 1029[0:0] has disconnected
May 21 07:37:25 htpc acpid: client connected from 1029[0:0]
May 21 07:37:25 htpc acpid: 1 client rule loaded
May 21 07:37:25 htpc kernel: [   42.552508] [drm:drm_ioctl], pid=1029, cmd=0x641e, nr=0x1e, dev 0xe200, auth=1
May 21 07:37:25 htpc kernel: [   42.552517] [drm:drm_ioctl], pid=1029, cmd=0xc01c64ad, nr=0xad, dev 0xe200, auth=1
May 21 07:37:25 htpc kernel: [   42.552522] [drm:drm_mode_getfb] *ERROR* invalid framebuffer id
May 21 07:37:25 htpc kernel: [   42.552525] [drm:drm_ioctl], ret = ffffffea
May 21 07:37:25 htpc kernel: [   42.552568] [drm:drm_ioctl], pid=1029, cmd=0xc02064a5, nr=0xa5, dev 0xe200, auth=1
May 21 07:37:25 htpc kernel: [   42.552576] [drm:drm_ioctl], pid=1029, cmd=0xc06864a2, nr=0xa2, dev 0xe200, auth=1
May 21 07:37:25 htpc kernel: [   42.552580] [drm:drm_mode_setcrtc], [CRTC:3]
May 21 07:37:25 htpc kernel: [   42.552586] [drm:drm_mode_setcrtc], [CONNECTOR:12:HDMI-A-2]
May 21 07:37:25 htpc kernel: [   42.552589] [drm:drm_crtc_helper_set_config], 
May 21 07:37:25 htpc kernel: [   42.552591] [drm:drm_crtc_helper_set_config], [CRTC:3] [FB:18] #connectors=1 (x y) (0 0)
May 21 07:37:25 htpc kernel: [   42.552599] [drm:drm_crtc_helper_set_config], crtc has no fb, full mode set
May 21 07:37:25 htpc kernel: [   42.552603] [drm:drm_crtc_helper_set_config], encoder changed, full mode switch
May 21 07:37:25 htpc kernel: [   42.552605] [drm:drm_crtc_helper_set_config], crtc changed, full mode switch
May 21 07:37:25 htpc kernel: [   42.552608] [drm:drm_crtc_helper_set_config], [CONNECTOR:12:HDMI-A-2] to [CRTC:3]
May 21 07:37:25 htpc kernel: [   42.552611] [drm:drm_crtc_helper_set_config], attempting to set mode from userspace
May 21 07:37:25 htpc kernel: [   42.552614] [drm:drm_mode_debug_printmodeline], Modeline 17:"1920x1080i" 0 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x0 0x5
May 21 07:37:25 htpc kernel: [   42.552620] [drm:drm_crtc_helper_set_mode], [CRTC:3]
May 21 07:37:25 htpc kernel: [   42.552635] [drm:drm_vblank_get], enabling vblank on crtc 0, ret: -22
May 21 07:37:25 htpc kernel: [   42.552675] [drm:intel_choose_pipe_bpp_dither], forcing bpc to 8 for HDMI
May 21 07:37:25 htpc kernel: [   42.552678] [drm:intel_choose_pipe_bpp_dither], setting pipe bpc to 8 (max display bpc 8)
May 21 07:37:25 htpc kernel: [   42.552681] [drm:ironlake_crtc_mode_set], Mode for pipe 0:
May 21 07:37:25 htpc kernel: [   42.552684] [drm:drm_mode_debug_printmodeline], Modeline 17:"1920x1080i" 0 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x0 0x5
May 21 07:37:25 htpc kernel: [   42.552988] [drm:ironlake_crtc_mode_set], disabling CxSR downclocking
May 21 07:37:25 htpc kernel: [   42.556389] ata6: SATA link down (SStatus 0 SControl 300)
May 21 07:37:25 htpc kernel: [   42.560369] ata3: SATA link down (SStatus 0 SControl 300)
May 21 07:37:25 htpc kernel: [   42.568367] ata2: SATA link down (SStatus 0 SControl 300)
May 21 07:37:25 htpc kernel: [   42.608235] [drm:intel_wait_for_vblank], vblank wait timed out
May 21 07:37:25 htpc kernel: [   42.608245] [drm:ironlake_update_plane], Writing base 029F7000 00000000 0 0 7680
May 21 07:37:25 htpc kernel: [   42.608249] [drm:intel_update_fbc], 
May 21 07:37:25 htpc kernel: [   42.608253] [drm:ironlake_update_wm], FIFO watermarks For pipe A - plane 9, cursor: 6
May 21 07:37:25 htpc kernel: [   42.608256] [drm:ironlake_check_srwm], watermark 1: display plane 91, fbc lines 3, cursor 6
May 21 07:37:25 htpc kernel: [   42.608260] [drm:ironlake_check_srwm], watermark 2: display plane 202, fbc lines 4, cursor 10
May 21 07:37:25 htpc kernel: [   42.608265] [drm:drm_crtc_helper_set_mode], [ENCODER:11:TMDS-11] set [MODE:17:1920x1080i]
May 21 07:37:25 htpc kernel: [   42.608270] [drm:ironlake_update_wm], FIFO watermarks For pipe A - plane 9, cursor: 6
May 21 07:37:25 htpc kernel: [   42.608273] [drm:ironlake_check_srwm], watermark 1: display plane 91, fbc lines 3, cursor 6
May 21 07:37:25 htpc kernel: [   42.608276] [drm:ironlake_check_srwm], watermark 2: display plane 202, fbc lines 4, cursor 10
May 21 07:37:25 htpc kernel: [   42.664088] [drm:intel_wait_for_vblank], vblank wait timed out
May 21 07:37:25 htpc kernel: [   42.719969] [drm:intel_wait_for_vblank], vblank wait timed out
May 21 07:37:25 htpc kernel: [   42.720274] [drm:ironlake_fdi_link_train], FDI_RX_IIR 0x100
May 21 07:37:25 htpc kernel: [   42.720276] [drm:ironlake_fdi_link_train], FDI train 1 done.
May 21 07:37:25 htpc kernel: [   42.720429] [drm:ironlake_fdi_link_train], FDI_RX_IIR 0x600
May 21 07:37:25 htpc kernel: [   42.720431] [drm:ironlake_fdi_link_train], FDI train 2 done.
May 21 07:37:25 htpc kernel: [   42.720433] [drm:ironlake_fdi_link_train], FDI train done
May 21 07:37:25 htpc kernel: [   42.720675] [drm:intel_prepare_page_flip], preparing flip with no unpin work?
May 21 07:37:25 htpc kernel: [   42.721633] [drm:intel_update_fbc], 
May 21 07:37:25 htpc kernel: [   42.721640] [drm:drm_calc_timestamping_constants], crtc 3: hwmode: htotal 2200, vtotal 1125, vdisplay 1080
May 21 07:37:25 htpc kernel: [   42.721642] [drm:drm_calc_timestamping_constants], crtc 3: clock 148500 kHz framedur 16665750 linedur 14814, pixeldur 6
May 21 07:37:25 htpc kernel: [   42.721647] [drm:drm_crtc_helper_set_config], Setting connector DPMS state to on
May 21 07:37:25 htpc kernel: [   42.721650] [drm:drm_crtc_helper_set_config], 	[CONNECTOR:12:HDMI-A-2] set DPMS on
May 21 07:37:25 htpc kernel: [   42.721663] [drm:ironlake_crtc_dpms], crtc 0/0 dpms off
May 21 07:37:25 htpc kernel: [   42.721667] [drm:i915_get_vblank_timestamp], crtc 0 is disabled

That paste was pretty unreadable. The synopsis is upon restoring the mode after resume, we turn the output *off*.

Can you add this patch to your kernel and grab the dmesg across s&r again?

diff --git a/drivers/gpu/drm/i915/intel_display.c b/drivers/gpu/drm/i915/intel_d
index 83f9389..7f4cb62 100644
--- a/drivers/gpu/drm/i915/intel_display.c
+++ b/drivers/gpu/drm/i915/intel_display.c
@@ -3386,6 +3386,8 @@ static void intel_crtc_dpms(struct drm_crtc *crtc, int mod
        int pipe = intel_crtc->pipe;
        bool enabled;
 
+       DRM_DEBUG_KMS("setting DPMS mode %d, currently %d\n",
+                     mode, intel_crtc->dpms_mode);
        if (intel_crtc->dpms_mode == mode)
                return;

I've updated my graphics stack to the git HEAD versions offered by the Ubuntu
Xorg Edgers PPA.

After installing 2.19.0+git20120509.a83d90ee-0ubuntu0sarvatt2~sna~precise from
this PPA: https://launchpad.net/~sarvatt/+archive/intel-sna, resume from
standby appears to work "better" in this scenario.

I use XBMC as my window manager and it flashes repeatedly to black until I do
something that forces the entire screen to redraw (like going from Videos to
the main menu).  At that point, everything works great!

Created attachment 61911 [details]
Xorg.0.log with intel-sna git HEAD

Please note the "(WW) intel(0): flip queue failed: Device or resource busy" that is printed to Xorg.0.log on resume from standby until the receiver is turned on.

Chris,

I can apply that patch and get you an updated log, but it will be 8-9 hours as I have to go to work.

Thanks for your help.

Actually this is an xorg bug; sorry for the ping-pong. What is happening is that after setting the userspace mode, disconnected connectors are pruned and turned off. X needs to be aware and update its state accordingly.

Kyle, quick patch for you to test on SNA master which hopefully will be far easier for you test than the kernel. :)

Great!  Thanks for your help Chris.  I've got the updated driver with your changes built now.  I can test when I get home in about 6 hours.

Could this change be backported to the pre-SNA driver?

Yes it should be, just useful to know that I'm on the right track first ;-)

Using commit 952e3dcba3a651d22d44dbb039ad97e111d9bc63.  The SNA driver still
has the same behavior as before your changeset.

"I use XBMC as my window manager and it flashes repeatedly to black until I do
something that forces the entire screen to redraw (like going from Videos to
the main menu).  At that point, everything works great!"

"Please note the "(WW) intel(0): flip queue failed: Device or resource busy"
that is printed to Xorg.0.log on resume from standby until the receiver is
turned on."

I'm not sure if the problem that you fixed in the SNA driver was ever present
on my machine though.  I was using the UXA driver before you asked me to test
the SNA version.

After further testing things appear to be somewhat unreliable.  I've seen 3 different possible results, somewhat at random;
1. Everything resumes perfectly no warnings or errors
2. Sometimes I get "(WW) intel(0): flip queue failed: Device or resource busy" and XBMC flashses or the VT is displayed until I give XBMC some input and then the screen redraws and XBMC works properly
3. X crashes.  (Unfortunately I don't have the crash output currently).  I'll try to get the logs to you shortly.

That -EBUSY is indicated of trying to use a stale CRTC configuration. So I'm not getting the notification that a pipe is absent after resume. Hmm, the logs would be useful (and if you can reproduce with --enable-sna --enable-debug=full, that would be most excellent).

I've updated xf86-video-intel.git (sna) so that it appears to behave given a disconnect while VT-switched, which should encompass s&r. Time to test that theory.

So one slight difference across s&r is that the disconnection (of my DP) is after we restore the mode. The pipe is up and running (so the CRTC appears valid), even though the output itself is disconnected.

Kyle, can you please test whether the current head does the trick?

Created attachment 61991 [details]
Xorg.0.log from 5/22 at git HEAD with --enable-sna and --enable-debug=full

I think the driver is now working properly across suspend/resume.  I don't see any errors or warnings printed to Xorg.0.log.  

However, XBMC is crashing on resume and I'm not sure if it's related to the updated graphics stack or not.  But, I think the resume problems with my receiver is on standby are fixed.  If I restart lightdm, then XBMC comes up fine.  Previously I had to reboot as the intel driver disabled hardware acceleration and restarting X did not fix the problem.

I have tried several times and have been unable to reproduce the behavior that caused the flashing screen or crash.

Do you see anything out of the ordinary in the attached log?  What can I do to help you out?

Can't see a reason for the segfault. We wake up from suspend at 60.125, discover that the outputs are now disabled and happily resume. Then xbmc starts running unthrottled (since we have no vblank, hmm maybe I suspend any client that requests a vsync swap when offscreen) until 61.552 when it ceases.

The good news is that this does seem the right approach to prevent the driving from submitting invalid commands upon resume. Can you look in ~/.xsession-errors to see if xbmc has been leaving any information as to the cause of the crash?

Created attachment 62016 [details]
Xorg.0.log from 5/23 at git HEAD with --enable-sna and --enable-debug=full

I was mistaken about XBMC crashing, I was looking at an old crashlog.  When the non-SNA driver would resume and the GPU would hang XBMC would crash when issuing GL commands.

The attached Xorg.0.log was captured this morning.  The system resumes from standby but the image displayed on the virtual terminal no longer updates.  The X server and XBMC are still running (verified by ps), but the picture on the screen still looks like the console window right before the system suspended.  I can change VTs, but when I try to go back to VT7, the old VT console picture is drawn.  However, I must be on VT7 as when I type nothing on the screen updates.  It seems the image is getting "stuck".

Another tweak for you to test:

commit fb9da4cb9e12ca733c31879b8b37906f361a8c35
Author: Chris Wilson <chris@chris-wilson.co.uk>
Date:   Wed May 23 13:53:37 2012 +0100

    sna: Only mark an unattached output as inactive
    
    So that a latter attempt to set the DesiredMode may succeed and we do
    not modify the configuration without notifying clients.
    
    Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>

Can you describe your testing methodology? Upon resume, we try to restore the mode on the connector and that fails, so we mark it as inactive. First, does that match your expectations, is the output in standby upon resume? Then we have the issue of not seeing the hotplug event for when it switches on, so we never actually re-enable the output.

Ah, I've spotted the hotplug notification. At which point, I have to ask whether there is anything responding to the X hotplug event and restoring the mode? If xbmc is running as the only client, it should be taught how to handle hotplug events.

My test methodology is to put the receiver in standby, then suspend the PC.  Next I resume the PC and wait 30 seconds.  Finally, I bring the receiver out of standby.  I would presume that the output would appear to be in standby when the PC resumes.

At this point, this very well may be a bug with XBMC, the GPU no longer gets hung on resume.  I believe that XBMC is not actually active on resume from suspend.  I believe that XBMC shuts itself down on suspend and is restarted by lightdm (or maybe the x-server?) on resume.  I'm not sure what the exact sequence is on resume, but I'm quite certain that XBMC is actually exited on suspend and then started again on resume, rather than simply being suspended.

I tried testing this again with your changes from today. Please see the attached Xorg.0.log.

Created attachment 62040 [details]
Xorg.0.log from 5/23(2) at git HEAD with --enable-sna and --enable-debug=full

Interesting...  It appears that XBMC is actually crashing at some point during suspend/resume and then being relaunched.  I'm not sure who is doing this launching and I'll dig into that more shortly.  However, I can provide a backtrace from within XBMC of the calls into libX11.s0.6, if that would be helpful (See xbmc_crashlog-20120523_183644).  I'll start following up with the XBMC developers on this as well.

I'm also attaching an updated syslog with drm.debug=7.  Please note that on resume it looks like invalid EDID information is being returned as soon as the receiver is brought out of standby (Note that the PC has already been resumed for several seconds at this point).  In the past, (on the pre-SNA driver) EDID information has always been read correctly.

Created attachment 62041 [details]
XBMC Crashlog

Created attachment 62042 [details]
syslog.5.23 with drm.debug=0x07

(In reply to comment #32)
> Created attachment 62041 [details]
> XBMC Crashlog

Ok, that looks to be an SDL bug mishandling an XError. The error was probably a quite ordinary BadDrawable (no other error is raised by DRI2WaitMSC, but there is a possibility that it was an earlier error now caught.)

(In reply to comment #31)
> I'm also attaching an updated syslog with drm.debug=7.  Please note that on
> resume it looks like invalid EDID information is being returned as soon as the
> receiver is brought out of standby (Note that the PC has already been resumed
> for several seconds at this point).  In the past, (on the pre-SNA driver) EDID
> information has always been read correctly.

EDID retrieval isn't a function of the driver, but the kernel. X just passes on the EDID returned from the last connection probe. Let's see what's hidden in the details...

Yes, the EDID read returned garbage; garbage in, garbage out.

What is truly odd is that when I try to reproduce this, I don't see the effect of the pipe being disabled due to the output being disconnected. Perplexing.

And to complete the original bug-fix, here is the UXA variant:

commit 3f3bde4f0c72f6f31aae322bcdc20b95eade6631
Author: Chris Wilson <chris@chris-wilson.co.uk>
Date:   Thu May 24 11:58:46 2012 +0100

    uxa: Only consider an output valid if the kernel reports it attached
    
    Reported-by: Kyle Hill <kyle.hill@tacomafia.net>
    Bugzilla: https://bugs.freedesktop.org/show_bug.cgi?id=50078
    Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>

Kyle, do you mind testing UXA with xf86-video-intel.git? I think the residual issues are not our bugs, so if we can make UXA stable, I believe this bug to be fixed.

The driver works under UXA.  I don't see the warnings or errors in the Xorg.0.log like I saw previously.  However, XBMC does not draw on the screen until I switch VTs from 1 to 7.  It does not crash though.

Like you said earlier, this may be a XBMC bug now.  I'll follow up with those developers about this issue.

Would it be possible to roll this change into a new stable release?  I'd like to come off of the bleeding edge on my graphics stack, if possible :)

Thanks for all your help!

Yes, I think this warrants a stable release, I'll try to get around to making one in the near future. Let's close this bug as we've solved the original issue. I'm pretty sure the blank screen is a result of the hotplug event after resume being ignored, so let's treat that as a new bug if you after a little more digging you suspect the driver again.