Bug 496071 - xset dpms force off, xrandr cause order-1s system-wide latency
Summary: xset dpms force off, xrandr cause order-1s system-wide latency
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Fedora
Classification: Fedora
Component: kernel
Version: 14
Hardware: All
OS: Linux
low
medium
Target Milestone: ---
Assignee: Jonathan Blandford
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2009-04-16 13:29 UTC by James
Modified: 2013-04-02 04:22 UTC (History)
4 users (show)

Fixed In Version: 2.6.37-1
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2011-10-11 18:03:17 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)
Output from strace -r xset dpms force off (16.02 KB, text/plain)
2009-04-16 13:29 UTC, James
no flags Details
Output from strace -r xrandr (22.34 KB, application/octet-stream)
2009-08-24 16:58 UTC, James
no flags Details
.config for kernel.org kernel 2.6.34.1 that has no latency issues (83.88 KB, text/plain)
2010-07-25 09:45 UTC, James
no flags Details
Patch to resolve this issue for 2.6.36 series (865 bytes, patch)
2010-10-25 16:21 UTC, James
no flags Details | Diff


Links
System ID Private Priority Status Summary Last Updated
Linux Kernel 13453 0 None None None Never

Description James 2009-04-16 13:29:22 UTC
Created attachment 339843 [details]
Output from strace -r xset dpms force off

Description of problem:
Running xset dpms force off turn off the display causes a spike of kernel-mode CPU activity and around 1 second of system-wide latency (repeating sound from the audio buffer, etc.).

Version-Release number of selected component (if applicable):
kernel-2.6.29.1-85.fc11.x86_64
xorg-x11-server-Xorg-1.6.1-1.fc11.x86_64
xorg-x11-drv-intel-2.6.99.902-3.fc11.x86_64

How reproducible:
Always.

Steps to Reproduce:
1. Start playing music.
2. Run xset dpms force off.
3. Note brief latency.
  
Additional info:
On Intel X3100 graphics.

Output from strace -r xset dpms force off is attached; I guess the lines of relevance are:

     0.000052 read(3, 0x157ebd4, 4096)  = -1 EAGAIN (Resource temporarily unavailable)
     0.000037 nanosleep({0, 100000000}, NULL) = 0
     0.100340 poll([{fd=3, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=3, revents=POLLOUT}])
     0.000263 writev(3, [{"\203\4\1\0\203\6\2\0\3\0\0\0<\0\2\0\0\0\200\5+\0\1\0"..., 24}, {NULL, 0}, {""..., 0}], 3) = 24

More stats:

$ time xset dpms force off 

real	0m1.030s
user	0m0.001s
sys	0m0.004s

$ strace -c xset dpms force off 
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.000040           1        46        36 open
  0.00    0.000000           0        30         9 read
  0.00    0.000000           0        11           close
  0.00    0.000000           0         4         4 stat
  0.00    0.000000           0        10           fstat
  0.00    0.000000           0        21           poll
  0.00    0.000000           0        26           mmap
  0.00    0.000000           0        11           mprotect
  0.00    0.000000           0         2           munmap
  0.00    0.000000           0         3           brk
  0.00    0.000000           0        11           writev
  0.00    0.000000           0         2         1 access
  0.00    0.000000           0         1           nanosleep
  0.00    0.000000           0         1           socket
  0.00    0.000000           0         1           connect
  0.00    0.000000           0         1           getpeername
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           uname
  0.00    0.000000           0         3           fcntl
  0.00    0.000000           0         1           arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00    0.000040                   187        50 total

Comment 1 Chuck Ebbert 2009-04-17 14:09:14 UTC
The final read takes almost a full second:

0.100340 poll([{fd=3, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=3, revents=POLLOUT}])

0.000263 writev(3, [{"\203\4\1\0\203\6\2\0\3\0\0\0<\0\2\0\0\0\200\5+\0\1\0"..., 24}, {NULL, 0}, {""..., 0}], 3) = 24

0.000294 poll([{fd=3, events=POLLIN}], 1, -1) = 1 ([{fd=3, revents=POLLIN}])

0.914570 read(3, "\1\2\16\0\0\0\0\0}\0\240\4\0\0\0\0\200_\341\7\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 32


fd 3 is:

0.000152 socket(PF_FILE, SOCK_STREAM, 0) = 3
0.000094 connect(3, {sa_family=AF_FILE, path=@"/tmp/.X11-unix/X0"...}, 20) = 0

Comment 2 James 2009-06-04 09:26:00 UTC
Still present in kernel-2.6.29.4-167.fc11.x86_64, xorg-x11-drv-intel-2.7.0-7.fc11.x86_64. I presume this is a kernel issue? If so, I'll take it to the kernel bugzilla.

Comment 3 Bug Zapper 2009-06-09 13:55:07 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 11 development cycle.
Changing version to '11'.

More information and reason for this action is here:
http://fedoraproject.org/wiki/BugZappers/HouseKeeping

Comment 4 James 2009-06-16 13:14:33 UTC
Still present in kernel-2.6.29.5-186.fc11.x86_64.

Comment 5 James 2009-07-13 10:36:51 UTC
Also in kernel-2.6.29.6-213.fc11.x86_64.

Comment 6 James 2009-08-15 20:22:56 UTC
No change in kernel-2.6.30.5-28.rc2.fc11.x86_64.

Comment 7 James 2009-08-24 16:58:23 UTC
Seem something similar just running xrandr. Again, reads of fd 3 seem to take quite a while --- around 1/5 of a second in the case attached below. Causes systemwide latency (audio skip, etc.).

     0.000065 connect(3, {sa_family=AF_FILE, path=@"/tmp/.X11-unix/X0"...}, 20) = 0
     ...
     0.227042 read(3, "\1\0\f\0\217\0\0\0t\234\1\0\27\232\1\0\2\0\2\0\16\0l\0h\34Q\0\0\0\0\0009"..., 4096) = 604

Comment 8 James 2009-08-24 16:58:50 UTC
Created attachment 358490 [details]
Output from strace -r xrandr

Comment 9 James 2009-10-22 13:00:21 UTC
Still present in:

kernel-2.6.31.1-56.fc12.x86_64
xorg-x11-drv-intel-2.9.0-2.fc12.x86_64

Comment 11 Bug Zapper 2009-11-16 09:55:16 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 12 development cycle.
Changing version to '12'.

More information and reason for this action is here:
http://fedoraproject.org/wiki/BugZappers/HouseKeeping

Comment 12 James 2009-12-04 11:34:07 UTC
There's a patch in the upstream Bugzilla which seems to work... (issue still present in kernel-2.6.32-1.fc13.x86_64).

Comment 13 James 2010-03-21 14:32:11 UTC
This seems to be fixed nicely upstream with the "return early and timeout in FBC disable path".

Comment 14 James 2010-05-21 07:27:15 UTC
I still see this with recent Fedora 12 kernels, any chance fbc-disable-timeout.patch could be included?

Comment 15 James 2010-06-06 08:37:08 UTC
Odd, might have returned in recent kernels. Seem to see kernel-mode CPU spike with DPMS off even with fbc patch.

Comment 16 James 2010-07-09 16:13:00 UTC
Again, this defect is still present in stock Fedora 13 kernels. Please pull in the fbc-disable-timeout patch linked in the upstream bug report.

Comment 17 James 2010-07-25 09:45:00 UTC
I'm going to have to re-open this (the only option available seems to be ASSIGNED, but that's clearly not what's required). While this bug seems to be sort of fixed in the kernel.org upstream kernel, 2.6.34.1, it's still present in kernel-2.6.34.1-29.fc13.x86_64.

With the unpatched kernel.org source (compiled using the .config attached below), running xset dpms force off causes a spike of system CPU activity, but no noticeable latency (e.g., no stuttering audio).

Running xset dpms force off with the Fedora 13 kernel *does* cause severe audio latency, so something must be awry in the Fedora patchset.

Comment 18 James 2010-07-25 09:45:57 UTC
Created attachment 434226 [details]
.config for kernel.org kernel 2.6.34.1 that has no latency issues

Comment 19 James 2010-07-25 10:07:45 UTC
Strike my Comment #17 from the record, the bug is still present in the vanilla sources; it's just harder to reproduce...

Comment 20 Chuck Ebbert 2010-07-25 21:12:11 UTC
(In reply to comment #16)
> Again, this defect is still present in stock Fedora 13 kernels. Please pull in
> the fbc-disable-timeout patch linked in the upstream bug report.    

That patch is included in the drm-next patch in our 2.6.34 kernel:

$ grep -i -C 1 'already off' *.patch
drm-next.patch-+	if (!(I915_READ(FBC_CONTROL) & FBC_CTL_EN))
drm-next.patch:+		return;	/* Already off, just return */
drm-next.patch-+

Comment 21 James 2010-07-27 17:14:08 UTC
(In reply to comment #20)
> (In reply to comment #16)
> > Again, this defect is still present in stock Fedora 13 kernels. Please pull in
> > the fbc-disable-timeout patch linked in the upstream bug report.    

Thanks for this! I've been trying out the F13 2.6.34.1 from sources and noticed that the patch was already included. However, I think I may have been mistaken about it solving the latency issue. What happened was I was compiling the kernels with full pre-emption enabled, so when running xset dpms force off, the CPU still span briefly but audio was not interrupted. Kernels with the f-d-t patch and *voluntary* pre-emption still hiccup on the X3100 and X4500 hardware I have in front of me.

BUT: In the earlier kernel.org bug report at

https://bugzilla.kernel.org/show_bug.cgi?id=13453

there was a patch (see comment #8 in the above) that adds msleeps around the code that switches the display off. Now as far as I have tested, this patch *does* solve the latency issue even with voluntary pre-emption. The trouble was in the past when I tried it, it lead to soft lockups. This bug was then marked as a duplicate of kernel bz15015, and I assumed that the f-d-t patch in that bug-report would fix the latency issue; however, it may be that it was intended to fix the soft lockups caused by the msleep patch of kernel bz13453.

Either way, I'm now using a kernel with both the bz13453 and bz15015 patches applied and haven't seen any trouble, on either X3100 or X4500 hardware. (Also, yesterday I ran a vanilla kernel without the f-d-t patch, but just the msleep patch without incident.) However, the mean time between failure for this one was around a week, so I recall, so I'll just keep an eye on this for now.

Comment 22 James 2010-10-25 16:21:25 UTC
Created attachment 455571 [details]
Patch to resolve this issue for 2.6.36 series

Moving version up to rawhide, hopefully there'll be some motion on this. It's still present in the F15 2.6.36 kernel, but the affected code has changed in intel_lvds.c. The attached patch resolves the CPU-spike-on-LVDS-off issue for me with 2.6.35-1.fc15 sources. (Puts in an msleep(1), so doing the same thing as the older patch.)

Comment 23 James 2011-01-06 12:37:44 UTC
I believe that this is finally fixed in 2.6.37. I'll close it later if nobody objects.

Comment 24 Bug Zapper 2011-06-02 18:09:15 UTC
This message is a reminder that Fedora 13 is nearing its end of life.
Approximately 30 (thirty) days from now Fedora will stop maintaining
and issuing updates for Fedora 13.  It is Fedora's policy to close all
bug reports from releases that are no longer maintained.  At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '13'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 13's end of life.

Bug Reporter: Thank you for reporting this issue and we are sorry that 
we may not be able to fix it before Fedora 13 is end of life.  If you 
would still like to see this bug fixed and are able to reproduce it 
against a later version of Fedora please change the 'version' of this 
bug to the applicable version.  If you are unable to change the version, 
please add a comment here and someone will do it for you.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events.  Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

The process we are following is described here: 
http://fedoraproject.org/wiki/BugZappers/HouseKeeping

Comment 25 Dave Jones 2011-10-11 18:03:17 UTC
closing based on comment #23


Note You need to log in before you can comment on or make changes to this bug.