Bug 735268 - Extremely sluggish graphical performance and high CPU use when using a >= 3.1 kernel with debugging options enabled
Summary: Extremely sluggish graphical performance and high CPU use when using a >= 3.1...
Keywords:
Status: CLOSED EOL
Alias: None
Product: Fedora
Classification: Fedora
Component: xorg-x11-drv-ati
Version: 19
Hardware: x86_64
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: Jérôme Glisse
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard: [cat:modesetting]
: 732508 796312 798724 803526 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2011-09-02 04:43 UTC by Evandro Giovanini
Modified: 2018-04-11 13:25 UTC (History)
21 users (show)

Fixed In Version: kernel-3.1.0-0.rc6.git0.0.fc16
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2015-02-18 13:37:04 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)
dmesg output (94.41 KB, text/plain)
2011-09-02 05:45 UTC, Evandro Giovanini
no flags Details
Xorg log file (45.45 KB, text/plain)
2011-09-02 05:46 UTC, Evandro Giovanini
no flags Details
dmesg with selinux=0 (84.39 KB, text/plain)
2011-09-02 23:05 UTC, Evandro Giovanini
no flags Details
Perf data (329.66 KB, application/x-gzip)
2011-09-19 05:33 UTC, Bruno Wolff III
no flags Details
perf data running 3.1.0-0.rc10.git0.1.fc16.x86_64 (569.74 KB, application/octet-stream)
2011-10-24 15:19 UTC, Julius B.
no flags Details

Description Evandro Giovanini 2011-09-02 04:43:35 UTC
Description of problem:
CPU usage by the Xorg process is very high, going anywhere from 2-100% as measured by top when very simple operations are performed, such as creating windows or moving them around. The system becomes very slow as a result.


Version-Release number of selected component (if applicable):
3.1.0-0.rc3.git0.0.fc16.x86_64


How reproducible:
Always reproducible. This happens under GNOME Shell as well as GNOME's fallback mode with no compositor enabled.


Additional info:
Hardware is and HP dm1 laptop, which is based on AMD Fusion's platform (AMD E-350 Processor, Radeon 6310HD GPU).

I'm filing this bug against the kernel because the system behaves fine after installing a custom kernel image. In particular, I manually extracted and installed a pre-built kernel from Debian, 3.0.0-1-amd64, to the Fedora 16 system.

Comment 1 Evandro Giovanini 2011-09-02 05:45:53 UTC
Created attachment 521146 [details]
dmesg output

Comment 2 Evandro Giovanini 2011-09-02 05:46:47 UTC
Created attachment 521147 [details]
Xorg log file

Comment 3 Matěj Cepl 2011-09-02 19:58:47 UTC
> [   41.960227] systemd-tmpfiles[743]: Failed to set security context
> system_u:object_r:tmp_t:s0 for /tmp: Permission denied

This is probably a red herring, but if we don't have /tmp, then really weird things can happen.

Thank you for filing the bug report

Comment 4 Evandro Giovanini 2011-09-02 23:05:13 UTC
Created attachment 521300 [details]
dmesg with selinux=0

With selinux disabled the /tmp problem goes away but performance of Xorg seems about the same.

Comment 5 Thorsten Leemhuis 2011-09-07 08:24:09 UTC
Seeing the same problem here with
00:00.0 Host bridge [0600]: Intel Corporation Core Processor DMI [8086:d131] (rev 11)
01:00.0 VGA compatible controller [0300]: ATI Technologies Inc RV710 [Radeon HD 4350] [1002:954f]

Saw it already when I tried to use a 3.1 kernel on F15 a week or two agi; seeing it now again after updating to F16 current. I went back to the 3.0/2.6.40 kernel from F15 on my machine, as X is fast with it

Comment 6 Evandro Giovanini 2011-09-07 20:40:41 UTC
Today I downloaded kernel-3.1.0-0.rc4.git0.1.fc16.src.rpm from koji and tried building without debug options to see if it would work any better (rpmbuild -bb --with baseonly --with firmware --without debuginfo --target=`uname -m` kernel.spec). It didn't really help.

Comment 7 Josh Boyer 2011-09-07 20:49:28 UTC
(In reply to comment #6)
> Today I downloaded kernel-3.1.0-0.rc4.git0.1.fc16.src.rpm from koji and tried
> building without debug options to see if it would work any better (rpmbuild -bb
> --with baseonly --with firmware --without debuginfo --target=`uname -m`
> kernel.spec). It didn't really help.

That's because you didn't really turn off any of the debug options.  The options need to be disabled with 'make release' before you build the SRPM.

Comment 8 Mike Chambers 2011-09-08 15:04:27 UTC
(In reply to comment #5)
You can use a 2.6.40 kernel with F16 and it works better or you (as I am currently) went back to F15?

Comment 9 Thorsten Leemhuis 2011-09-08 18:53:27 UTC
(In reply to comment #8)
> You can use a 2.6.40 kernel with F16 and it works better

yes, that's my workaround for now

Comment 10 Mike Chambers 2011-09-09 17:12:57 UTC
It seems most if not all the 2.6.40 kernels seem to be a lot faster, than using any of the 3.0 kernels, to include earlier ones.  The one thing I do see between the two besides just responsiveness, is when using 3.0 kernels, X has very high (over 50%) CPU usage.  On the 2.6.40 kernels, X isn't nowhere nearly as high (less than 20%), although on the latest 2.6.40 kernel X uses some CPU (20-30%)but near as much as 3.0.

kernel-2.6.40.3-0.fc15.x86_64
kernel-3.1.0-0.rc4.git0.0.fc16.x86_64
kernel-3.0.1-5.fc16.x86_64
kernel-2.6.40.4-5.fc15.x86_64

So maybe whatever the difference is between the 2 type of kernels, and/or the difference in what they are built against (programs, X, glib, gcc, etc..)

Hope this helps

Comment 11 Josh Boyer 2011-09-09 17:40:47 UTC
(In reply to comment #10)
> It seems most if not all the 2.6.40 kernels seem to be a lot faster, than using
> any of the 3.0 kernels, to include earlier ones.  The one thing I do see
> between the two besides just responsiveness, is when using 3.0 kernels, X has
> very high (over 50%) CPU usage.  On the 2.6.40 kernels, X isn't nowhere nearly
> as high (less than 20%), although on the latest 2.6.40 kernel X uses some CPU
> (20-30%)but near as much as 3.0.
> 
> kernel-2.6.40.3-0.fc15.x86_64
> kernel-3.1.0-0.rc4.git0.0.fc16.x86_64
> kernel-3.0.1-5.fc16.x86_64
> kernel-2.6.40.4-5.fc15.x86_64
> 
> So maybe whatever the difference is between the 2 type of kernels, and/or the
> difference in what they are built against (programs, X, glib, gcc, etc..)

All of the 3.x kernels you have listed have all of the debug options enabled in the kernel.  None of the 2.6.40 kernels do.

Comment 12 Josh Boyer 2011-09-09 18:08:36 UTC
Given we're approaching F16 Beta, the next kernel update I submit (not rc5 but whatever comes next) will have the debug options disabled.  You can try that if you'd like.

Comment 13 Adam Williamson 2011-09-09 18:38:49 UTC
I've been affected by this too, with nouveau, and I'm using 3.0.1-3 as a fallback kernel that works much better. Does that have debug stuff enabled?

Comment 14 Adam Williamson 2011-09-09 21:14:27 UTC
I checked, and 3.0.1-3 does seem to have debug enabled (at least according to the changelog), so for me this isn't a simple debug vs. no debug issue; kernels which all have debugging turned on perform very differently for me (3.0.1-3 vs. any 3.1 kernel).

Comment 15 Adam Williamson 2011-09-10 00:07:44 UTC
*** Bug 732508 has been marked as a duplicate of this bug. ***

Comment 16 Adam Williamson 2011-09-10 00:08:54 UTC
It seems reasonably well established that this apparent sluggishness is affecting more than just one graphics driver, so re-assigning to kernel for now.

Here's some numbers I ran comparing 3.0.1-3 and 3.1rc5 with x11perf, on nouveau, GeForce 9600 GT.

3.0.1-3.fc16
------------

[adamw@adam ~]$ x11perf -copypixwin{10,100,500}
x11perf - X11 performance program, version 1.2
Fedora Project server version 11100000 on :0
from adam.localdomain
Fri Sep  9 16:56:32 2011

Sync time adjustment is 0.0842 msecs.

1600000 reps @   0.0032 msec (312000.0/sec): Copy 10x10 from pixmap to window
1600000 reps @   0.0032 msec (309000.0/sec): Copy 10x10 from pixmap to window
1600000 reps @   0.0032 msec (310000.0/sec): Copy 10x10 from pixmap to window
1600000 reps @   0.0032 msec (315000.0/sec): Copy 10x10 from pixmap to window
1600000 reps @   0.0032 msec (316000.0/sec): Copy 10x10 from pixmap to window
8000000 trep @   0.0032 msec (313000.0/sec): Copy 10x10 from pixmap to window

 240000 reps @   0.0231 msec ( 43400.0/sec): Copy 100x100 from pixmap to window
 240000 reps @   0.0232 msec ( 43200.0/sec): Copy 100x100 from pixmap to window
 240000 reps @   0.0233 msec ( 42900.0/sec): Copy 100x100 from pixmap to window
 240000 reps @   0.0233 msec ( 42900.0/sec): Copy 100x100 from pixmap to window
 240000 reps @   0.0234 msec ( 42800.0/sec): Copy 100x100 from pixmap to window
1200000 trep @   0.0232 msec ( 43000.0/sec): Copy 100x100 from pixmap to window

  36000 reps @   0.1418 msec (  7050.0/sec): Copy 500x500 from pixmap to window
  36000 reps @   0.1420 msec (  7040.0/sec): Copy 500x500 from pixmap to window
  36000 reps @   0.1426 msec (  7010.0/sec): Copy 500x500 from pixmap to window
  36000 reps @   0.1443 msec (  6930.0/sec): Copy 500x500 from pixmap to window
  36000 reps @   0.1463 msec (  6840.0/sec): Copy 500x500 from pixmap to window
 180000 trep @   0.1434 msec (  6970.0/sec): Copy 500x500 from pixmap to window

3.1.0-0.rc5.git0.0.fc16
-----------------------

[adamw@adam ~]$ x11perf -copypixwin{10,100,500}
x11perf - X11 performance program, version 1.2
Fedora Project server version 11100000 on :0
from adam.localdomain
Fri Sep  9 16:48:03 2011

Sync time adjustment is 0.2411 msecs.

1600000 reps @   0.0037 msec (270000.0/sec): Copy 10x10 from pixmap to window
1600000 reps @   0.0038 msec (263000.0/sec): Copy 10x10 from pixmap to window
1600000 reps @   0.0038 msec (263000.0/sec): Copy 10x10 from pixmap to window
1600000 reps @   0.0038 msec (265000.0/sec): Copy 10x10 from pixmap to window
1600000 reps @   0.0038 msec (264000.0/sec): Copy 10x10 from pixmap to window
8000000 trep @   0.0038 msec (265000.0/sec): Copy 10x10 from pixmap to window

  32000 reps @   0.1550 msec (  6450.0/sec): Copy 100x100 from pixmap to window
  32000 reps @   0.1560 msec (  6410.0/sec): Copy 100x100 from pixmap to window
  32000 reps @   0.1576 msec (  6350.0/sec): Copy 100x100 from pixmap to window
  32000 reps @   0.1649 msec (  6070.0/sec): Copy 100x100 from pixmap to window
  32000 reps @   0.1564 msec (  6390.0/sec): Copy 100x100 from pixmap to window
 160000 trep @   0.1580 msec (  6330.0/sec): Copy 100x100 from pixmap to window

  32000 reps @   0.1687 msec (  5930.0/sec): Copy 500x500 from pixmap to window
  32000 reps @   0.1662 msec (  6020.0/sec): Copy 500x500 from pixmap to window
  32000 reps @   0.1680 msec (  5950.0/sec): Copy 500x500 from pixmap to window
  32000 reps @   0.1658 msec (  6030.0/sec): Copy 500x500 from pixmap to window
  32000 reps @   0.1674 msec (  5970.0/sec): Copy 500x500 from pixmap to window
 160000 trep @   0.1672 msec (  5980.0/sec): Copy 500x500 from pixmap to window

Comment 17 Adam Williamson 2011-09-10 00:21:56 UTC
For the lulz, here's the numbers from 2.6.40.4-5.fc15, the current F15 kernel (so should be quite similar to 3.0.1-3 but without debugging code). It's twice as fast as 3.0.1-3 on 100x100. So it seems debugging code has a definite impact, but is not the whole story.

2.6.40.4-5.fc15
---------------

[adamw@adam ~]$ x11perf -copypixwin{10,100,500}
x11perf - X11 performance program, version 1.2
Fedora Project server version 11100000 on :0
from adam.localdomain
Fri Sep  9 17:17:17 2011

Sync time adjustment is 0.0379 msecs.

1600000 reps @   0.0031 msec (320000.0/sec): Copy 10x10 from pixmap to window
1600000 reps @   0.0031 msec (320000.0/sec): Copy 10x10 from pixmap to window
1600000 reps @   0.0031 msec (319000.0/sec): Copy 10x10 from pixmap to window
1600000 reps @   0.0031 msec (320000.0/sec): Copy 10x10 from pixmap to window
1600000 reps @   0.0031 msec (319000.0/sec): Copy 10x10 from pixmap to window
8000000 trep @   0.0031 msec (320000.0/sec): Copy 10x10 from pixmap to window

 800000 reps @   0.0117 msec ( 85400.0/sec): Copy 100x100 from pixmap to window
 800000 reps @   0.0118 msec ( 84800.0/sec): Copy 100x100 from pixmap to window
 800000 reps @   0.0117 msec ( 85400.0/sec): Copy 100x100 from pixmap to window
 800000 reps @   0.0118 msec ( 85000.0/sec): Copy 100x100 from pixmap to window
 800000 reps @   0.0116 msec ( 86200.0/sec): Copy 100x100 from pixmap to window
4000000 trep @   0.0117 msec ( 85300.0/sec): Copy 100x100 from pixmap to window

  36000 reps @   0.1426 msec (  7010.0/sec): Copy 500x500 from pixmap to window
  36000 reps @   0.1444 msec (  6930.0/sec): Copy 500x500 from pixmap to window
  36000 reps @   0.1436 msec (  6960.0/sec): Copy 500x500 from pixmap to window
  36000 reps @   0.1440 msec (  6950.0/sec): Copy 500x500 from pixmap to window
  36000 reps @   0.1443 msec (  6930.0/sec): Copy 500x500 from pixmap to window
 180000 trep @   0.1438 msec (  6960.0/sec): Copy 500x500 from pixmap to window

Comment 18 Adam Williamson 2011-09-10 00:23:49 UTC
oh, the CPU usage difference is definitely noticeable. Booted with RC5, if you close all apps and run htop, the per-CPU percentage is noticeably above zero on at least one CPU all the time, and the load average is quite high. On 2.6.40.4-5, per-CPU percentage when 'idle' is usually 0.8% on one CPU and zeroes on the others, and load average is much lower. CPU usage when just scrolling a web page is a lot lower too.

Comment 19 Adam Williamson 2011-09-10 02:30:16 UTC
so, this is interesting...here's numbers for 3.1rc5 with debugging disabled (I did a build locally to test):

3.1.0-0.rc5.git0.2.fc16.x86_64 (adamw private build)
----------------------------------------------------

[adamw@adam ~]$ x11perf -copypixwin{10,100,500}
x11perf - X11 performance program, version 1.2
Fedora Project server version 11100000 on :0
from adam.localdomain
Fri Sep  9 19:26:10 2011

Sync time adjustment is 0.0720 msecs.

1600000 reps @   0.0031 msec (318000.0/sec): Copy 10x10 from pixmap to window
1600000 reps @   0.0031 msec (320000.0/sec): Copy 10x10 from pixmap to window
1600000 reps @   0.0031 msec (320000.0/sec): Copy 10x10 from pixmap to window
1600000 reps @   0.0031 msec (320000.0/sec): Copy 10x10 from pixmap to window
1600000 reps @   0.0031 msec (319000.0/sec): Copy 10x10 from pixmap to window
8000000 trep @   0.0031 msec (319000.0/sec): Copy 10x10 from pixmap to window

 800000 reps @   0.0116 msec ( 85900.0/sec): Copy 100x100 from pixmap to window
 800000 reps @   0.0117 msec ( 85500.0/sec): Copy 100x100 from pixmap to window
 800000 reps @   0.0117 msec ( 85700.0/sec): Copy 100x100 from pixmap to window
 800000 reps @   0.0117 msec ( 85500.0/sec): Copy 100x100 from pixmap to window
 800000 reps @   0.0116 msec ( 86000.0/sec): Copy 100x100 from pixmap to window
4000000 trep @   0.0117 msec ( 85700.0/sec): Copy 100x100 from pixmap to window

  36000 reps @   0.1420 msec (  7040.0/sec): Copy 500x500 from pixmap to window
  36000 reps @   0.1416 msec (  7060.0/sec): Copy 500x500 from pixmap to window
  36000 reps @   0.1410 msec (  7090.0/sec): Copy 500x500 from pixmap to window
  36000 reps @   0.1412 msec (  7080.0/sec): Copy 500x500 from pixmap to window
  36000 reps @   0.1406 msec (  7110.0/sec): Copy 500x500 from pixmap to window
 180000 trep @   0.1413 msec (  7080.0/sec): Copy 500x500 from pixmap to window

the performance is on par with 2.6.40.4-5.fc15. So it looks like this really is down to debug overhead, but somehow the debug overhead got much heavier between 3.0 and 3.1. New upstream debug options, I guess. anyway, I expect this will magically go away when kernel team pushes a build with debug disabled.

Comment 20 Adam Williamson 2011-09-10 02:31:54 UTC
and indeed, that kernel is good from the subjective angle too: doesn't feel sluggish at all.

Comment 21 Mads Kiilerich 2011-09-10 08:25:26 UTC
Suggestion: Add an explicit kernel log message when debugging is enabled, something that will appear in the beginning of dmesg right next to the kernel version ... or perhaps even an extra "DEBUG" in the rpm release tag.

Comment 22 Martin Kho 2011-09-10 11:50:35 UTC
Hi,

I've experienced the performance drop too. It's especially dramatic in Fedora 16 KDE (B) (see the difference with Fedora 16 desktop (A), for the reference I've added the results from Fedora 15 KDE (C)):

test command: x11perf -copypixwin{10,100,500}
hardware: Geforce 7600 GS (NV4b)

A] Fedora 16 Desktop (installed pre-alpha (TC2), distro-synced, with all updates)

* 3.1.0-0.rc4.git0.0.fc16.x86_64
* xorg-x11-drv-nouveau-0.0.16-27.20110720gitb806e3f.fc16.x86_64
* xorg-x11-server-Xorg-1.11.0-1.fc16.x86_64

Sync time adjustment is 0.2799 msecs.

1200000 reps @   0.0044 msec (226000.0/sec): Copy 10x10 from pixmap to window
1200000 reps @   0.0044 msec (226000.0/sec): Copy 10x10 from pixmap to window
1200000 reps @   0.0045 msec (224000.0/sec): Copy 10x10 from pixmap to window
1200000 reps @   0.0045 msec (224000.0/sec): Copy 10x10 from pixmap to window
1200000 reps @   0.0044 msec (226000.0/sec): Copy 10x10 from pixmap to window
6000000 trep @   0.0044 msec (225000.0/sec): Copy 10x10 from pixmap to window

  80000 reps @   0.1030 msec (  9710.0/sec): Copy 100x100 from pixmap to window
  80000 reps @   0.1042 msec (  9600.0/sec): Copy 100x100 from pixmap to window
  80000 reps @   0.1039 msec (  9630.0/sec): Copy 100x100 from pixmap to window
  80000 reps @   0.1040 msec (  9620.0/sec): Copy 100x100 from pixmap to window
  80000 reps @   0.1034 msec (  9670.0/sec): Copy 100x100 from pixmap to window
 400000 trep @   0.1037 msec (  9640.0/sec): Copy 100x100 from pixmap to window

  28000 reps @   0.1991 msec (  5020.0/sec): Copy 500x500 from pixmap to window
  28000 reps @   0.1996 msec (  5010.0/sec): Copy 500x500 from pixmap to window
  28000 reps @   0.2003 msec (  4990.0/sec): Copy 500x500 from pixmap to window
  28000 reps @   0.2002 msec (  5000.0/sec): Copy 500x500 from pixmap to window
  28000 reps @   0.2001 msec (  5000.0/sec): Copy 500x500 from pixmap to window
 140000 trep @   0.1998 msec (  5000.0/sec): Copy 500x500 from pixmap to window

B] Fedora 16 KDE (upgraded from fedora 15, with all updates)

* 3.1.0-0.rc4.git0.0.fc16.x86_64
* xorg-x11-drv-nouveau-0.0.16-27.20110720gitb806e3f.fc16.x86_64
* xorg-x11-server-Xorg-1.11.0-1.fc16.x86_64

Sync time adjustment is 0.5553 msecs.

  20000 reps @   0.2966 msec (  3370.0/sec): Copy 10x10 from pixmap to window
  20000 reps @   0.2999 msec (  3330.0/sec): Copy 10x10 from pixmap to window
  20000 reps @   0.2979 msec (  3360.0/sec): Copy 10x10 from pixmap to window
  20000 reps @   0.2984 msec (  3350.0/sec): Copy 10x10 from pixmap to window
  20000 reps @   0.2984 msec (  3350.0/sec): Copy 10x10 from pixmap to window
 100000 trep @   0.2982 msec (  3350.0/sec): Copy 10x10 from pixmap to window

  12000 reps @   0.5484 msec (  1820.0/sec): Copy 100x100 from pixmap to window
  12000 reps @   0.5534 msec (  1810.0/sec): Copy 100x100 from pixmap to window
  12000 reps @   0.5544 msec (  1800.0/sec): Copy 100x100 from pixmap to window
  12000 reps @   0.5536 msec (  1810.0/sec): Copy 100x100 from pixmap to window
  12000 reps @   0.5507 msec (  1820.0/sec): Copy 100x100 from pixmap to window
  60000 trep @   0.5521 msec (  1810.0/sec): Copy 100x100 from pixmap to window

  12000 reps @   0.5500 msec (  1820.0/sec): Copy 500x500 from pixmap to window
  12000 reps @   0.5528 msec (  1810.0/sec): Copy 500x500 from pixmap to window
  12000 reps @   0.5523 msec (  1810.0/sec): Copy 500x500 from pixmap to window
  12000 reps @   0.5527 msec (  1810.0/sec): Copy 500x500 from pixmap to window
  12000 reps @   0.5536 msec (  1810.0/sec): Copy 500x500 from pixmap to window
  60000 trep @   0.5523 msec (  1810.0/sec): Copy 500x500 from pixmap to window

C] Fedora 15 KDE (installed final, with all updates)

* 2.6.40.4-5.fc15.x86_64
* xorg-x11-drv-nouveau-0.0.16-24.20110324git8378443.fc15.x86_64
* xorg-x11-server-Xorg-1.10.3-1.fc15.x86_64 

Sync time adjustment is 0.0559 msecs.

 320000 reps @   0.0162 msec ( 61700.0/sec): Copy 10x10 from pixmap to window
 320000 reps @   0.0162 msec ( 61700.0/sec): Copy 10x10 from pixmap to window
 320000 reps @   0.0162 msec ( 61700.0/sec): Copy 10x10 from pixmap to window
 320000 reps @   0.0164 msec ( 61100.0/sec): Copy 10x10 from pixmap to window
 320000 reps @   0.0162 msec ( 61600.0/sec): Copy 10x10 from pixmap to window
1600000 trep @   0.0162 msec ( 61600.0/sec): Copy 10x10 from pixmap to window

 240000 reps @   0.0227 msec ( 44100.0/sec): Copy 100x100 from pixmap to window
 240000 reps @   0.0228 msec ( 43800.0/sec): Copy 100x100 from pixmap to window
 240000 reps @   0.0228 msec ( 43900.0/sec): Copy 100x100 from pixmap to window
 240000 reps @   0.0227 msec ( 44000.0/sec): Copy 100x100 from pixmap to window
 240000 reps @   0.0227 msec ( 44000.0/sec): Copy 100x100 from pixmap to window
1200000 trep @   0.0227 msec ( 44000.0/sec): Copy 100x100 from pixmap to window

  24000 reps @   0.2180 msec (  4590.0/sec): Copy 500x500 from pixmap to window
  24000 reps @   0.2174 msec (  4600.0/sec): Copy 500x500 from pixmap to window
  24000 reps @   0.2174 msec (  4600.0/sec): Copy 500x500 from pixmap to window
  24000 reps @   0.2156 msec (  4640.0/sec): Copy 500x500 from pixmap to window
  24000 reps @   0.2174 msec (  4600.0/sec): Copy 500x500 from pixmap to window
 120000 trep @   0.2172 msec (  4600.0/sec): Copy 500x500 from pixmap to window

Comment 23 Adam Williamson 2011-09-10 18:38:23 UTC
mads: I think the thing that caught us off guard here is how *much* of an overhead the debugging code now seems to have. I know when debugging is on and when it's off, but in previous releases, it's never had such an overhead that you'd see it in simple, day-to-day graphical operations like scrolling a window or switching tabs.

Comment 24 Josh Boyer 2011-09-12 22:44:05 UTC
I've started a 3.1-rc6 build that has the debugging options turned off.  Please test when the build is complete:

http://koji.fedoraproject.org/koji/taskinfo?taskID=3346292

I'll be queuing this into updates-testing/updates either way due to another bug, but it would be good to test this build for this issue since the debug options are disabled and that has large impacts on performance.

Comment 25 Thorsten Leemhuis 2011-09-13 05:38:07 UTC
(In reply to comment #24)
> I've started a 3.1-rc6 build that has the debugging options turned off.  Please
> test when the build is complete: 
> http://koji.fedoraproject.org/koji/taskinfo?taskID=3346292

Installed the latests updates and this kernel on top -- now the problem is gone for me.

Comment 26 Mike Chambers 2011-09-13 06:13:00 UTC
Agree, so far it seems lot more responsive and not slow at all, or seems not to be.

Comment 27 Thorsten Leemhuis 2011-09-13 06:53:37 UTC
Josh, should we try to narrow the real issue down? Any idea in which area we could look more closely to find the root cause? 

I guess we all want to avoid the problem comes back in rawhide/F17-pre...

Comment 28 Fedora Update System 2011-09-13 10:20:05 UTC
kernel-3.1.0-0.rc6.git0.0.fc16 has been submitted as an update for Fedora 16.
https://admin.fedoraproject.org/updates/kernel-3.1.0-0.rc6.git0.0.fc16

Comment 29 Josh Boyer 2011-09-13 10:25:34 UTC
(In reply to comment #27)
> Josh, should we try to narrow the real issue down? Any idea in which area we
> could look more closely to find the root cause? 

If we ignore the obviously unrelated debugging options, we're left with these:

CONFIG_DEBUG_ATOMIC_SLEEP=y

CONFIG_DEBUG_MUTEXES=y
CONFIG_DEBUG_RT_MUTEXES=y
CONFIG_DEBUG_LOCK_ALLOC=y
CONFIG_PROVE_LOCKING=y
CONFIG_DEBUG_VM=y
CONFIG_DEBUG_SPINLOCK=y
CONFIG_PROVE_RCU=y

CONFIG_DEBUG_PER_CPU_MAPS=y

CONFIG_FAULT_INJECTION=y
CONFIG_FAILSLAB=y
CONFIG_FAIL_PAGE_ALLOC=y
CONFIG_FAIL_MAKE_REQUEST=y
CONFIG_FAULT_INJECTION_DEBUG_FS=y
CONFIG_FAULT_INJECTION_STACKTRACE_FILTER=y
CONFIG_FAIL_IO_TIMEOUT=y

CONFIG_SLUB_DEBUG_ON=y

CONFIG_LOCK_STAT=y

CONFIG_DEBUG_STACK_USAGE=y

CONFIG_ACPI_DEBUG=y

CONFIG_DEBUG_WRITECOUNT=y
CONFIG_DEBUG_OBJECTS=y
CONFIG_DEBUG_OBJECTS_FREE=y
CONFIG_DEBUG_OBJECTS_TIMERS=y
CONFIG_DEBUG_OBJECTS_RCU_HEAD=y

CONFIG_DMA_API_DEBUG=y

CONFIG_MMIOTRACE=y

CONFIG_DEBUG_OBJECTS_WORK=y

CONFIG_DMADEVICES_DEBUG=y
CONFIG_DMADEVICES_VDEBUG=y

CONFIG_DEBUG_OBJECTS_PERCPU_COUNTER=y
CONFIG_TEST_LIST_SORT=y

CONFIG_DEBUG_SET_MODULE_RONX=y
CONFIG_DETECT_HUNG_TASK=y

> I guess we all want to avoid the problem comes back in rawhide/F17-pre...

If someone is willing to poke at which option introduces the overhead that shows the symptoms, that would be much appreciated.

Comment 30 Adam Williamson 2011-09-13 16:46:37 UTC
there's about 0 chance I'm going to get around to that, but yeah, it would be good if someone could; otherwise I suspect people will end up using non-debug kernels when running rawhide/branched to avoid excessively sluggish performance, which obviously isn't good for actually finding and fixing issues.

Comment 31 Adam Williamson 2011-09-13 16:47:30 UTC
adjusting the summary.

Comment 32 Dave Jones 2011-09-14 21:05:02 UTC
at the least, finding out where the overhead is happening using perf would be helpful.

perf record -a sleep 10

and then attach the perf.data

Comment 33 Fedora Update System 2011-09-15 15:15:16 UTC
kernel-3.1.0-0.rc6.git0.0.fc16 has been pushed to the Fedora 16 stable repository.  If problems still persist, please make note of it in this bug report.

Comment 34 Josh Boyer 2011-09-15 15:36:58 UTC
I'm going to reopen this and move it to rawhide.  F16 will remain "fixed", but Dave is right that we should try poking at it a bit more.

Comment 35 Bruno Wolff III 2011-09-19 05:33:34 UTC
Created attachment 523783 [details]
Perf data

I uploaded compressed perf data. Though I have been seeing I/O related slowdowns rather than noticeable display related slowdowns.

Comment 36 Thorsten Leemhuis 2011-09-29 15:59:55 UTC
(In reply to comment #32)
> at the least, finding out where the overhead is happening using perf would be
> helpful.
> perf record -a sleep 10

Better late than never: 

= mostly idle system = 
Kernel with enabled debug options:
http://www.leemhuis.info/files/misc/perf/perf.data-debug-idle
Kernel where most debug options are disabled:
http://www.leemhuis.info/files/misc/perf/perf.data-regular-idle

= Switching back and forth between workspaces in gnome =
Kernel with enabled debug options:
http://www.leemhuis.info/files/misc/perf/perf.data-debug-switching
Kernel where most debug options are disabled:
http://www.leemhuis.info/files/misc/perf/perf.data-regular-switching

Comment 37 Julius B. 2011-10-24 15:19:48 UTC
Created attachment 529900 [details]
perf data running 3.1.0-0.rc10.git0.1.fc16.x86_64

I'm having the same problem running 3.1.0-0.rc10.git0.1.fc16.x86_64 and xorg-x11-drv-nvidia.x86_64 1:285.05.09-1.fc16.

Comment 38 Adam Williamson 2011-10-25 02:01:14 UTC
That's not at all the same problem.

Comment 39 Thorsten Leemhuis 2011-11-14 07:57:04 UTC
(In reply to comment #36)
> (In reply to comment #32)
> > at the least, finding out where the overhead is happening using perf would be
> > helpful.  perf record -a sleep 10
> Better late than never: 
> [...]

Problem showed up again when using 3.2.0-0.rc1.git3.1.fc17.x86_64 on f16 (as expected). But only on one of my machines -- one with a radeon chipset. But I got the impression the fan on my T420 (Sandy Bridge graphics) runs more often when running that kernel; but graphics is at least smooth there. 

@Jwb, want a new bug to track this further or will this report do?

Comment 40 Adam Williamson 2011-11-15 22:03:47 UTC
Yeah, still very sluggish on my nouveau now I moved to F17. I'm being bad and just recompiling the kernel with debugging disabled for now, though, instead of trying to help fix it.



-- 
Fedora Bugzappers volunteer triage team
https://fedoraproject.org/wiki/BugZappers

Comment 41 Adam Williamson 2011-11-22 18:54:52 UTC
Josh, Dave - this is still a problem in F17 and causes me to rebuild all Rawhide kernels with debugging disabled, which a) potentially deprives you of debugging info and b) annoys me :)

Do you need any further information beyond the perf data that's now been provided to look into this?



-- 
Fedora Bugzappers volunteer triage team
https://fedoraproject.org/wiki/BugZappers

Comment 42 Dave Jones 2011-11-22 21:07:12 UTC
try disabling just CONFIG_DEBUG_SPINLOCK and see if that makes a big difference.

Comment 43 Adam Williamson 2011-11-29 19:06:19 UTC
Unfortunately I'm having trouble building a kernel with CONFIG_DEBUG_SPINLOCK disabled but all other debugging options left as-is. Editing config-debug and config-nodebug and changing "CONFIG_DEBUG_SPINLOCK=y" to "CONFIG_DEBUG_SPINLOCK=n" or "# CONFIG_DEBUG_SPINLOCK is not set ", generating a srpm, and building it both seem to result in a kernel where CONFIG_DEBUG_SPINLOCK is y, according to the /boot/config file, and performance is still very slow.

Not sure what I'm doing wrong.

Comment 44 Adam Williamson 2011-11-29 22:03:54 UTC
Figured out the problem thanks to mjg59 - some other options implied CONFIG_DEBUG_SPINLOCK. For the record you also have to disable DEBUG_LOCK_ALLOC, PROVE_LOCKING, and LOCK_STAT.

The kernel I'm building now is at http://koji.fedoraproject.org/koji/taskinfo?taskID=3551670 if anyone else wants to test it too. It has this change plus a patch for suspending with CIFS/NFS shares active that I'm testing for jlayton.



-- 
Fedora Bugzappers volunteer triage team
https://fedoraproject.org/wiki/BugZappers

Comment 45 Adam Williamson 2011-11-29 23:30:55 UTC
okay, so here's my results. A 'release' build, with debug options completely disabled, runs gtkperf in 4.1s. The current stock Rawhide kernel, with all debug stuff enabled, takes 22s. Building the current kernel with CONFIG_DEBUG_SPINLOCK, DEBUG_LOCK_ALLOC, PROVE_LOCKING, and LOCK_STAT disabled but everything else left enabled, gtkperf runs in 11s.

Subjective perception of performance lines up with that - with the spinlock-disabled kernel I can still perceive a difference in performance to the 'release' built kernel, but it's a lot less painful than the stock kernel with spinlock enabled.

Comment 46 Bruno Wolff III 2011-12-29 13:11:36 UTC
My issue is different then Adam's and disabling just the options above didn't help me. I have a pretty old dual processor and I seem to be being cpu bound when doing disk I/O. I use encrypted raid 1 devices. Turning off all of the debugging options does cut cpu use of the worker threads while doing disk I/O a lot.

Comment 47 Adam Williamson 2012-02-28 05:39:20 UTC
*** Bug 796312 has been marked as a duplicate of this bug. ***

Comment 48 Josh Boyer 2012-02-29 17:37:21 UTC
*** Bug 798724 has been marked as a duplicate of this bug. ***

Comment 49 Josh Boyer 2012-03-15 00:09:23 UTC
*** Bug 803526 has been marked as a duplicate of this bug. ***

Comment 50 Mikhail 2012-03-15 13:33:58 UTC
kernel 3.3.0-0.rc6.git0.2.fc17.i686.PAE compiled without DEBUG flag? I ask because that it worked fine. And the next kernel 3.3.0-0.rc7.git0.3.fc17.i686.PAE again terribly slow.

Comment 51 Josh Boyer 2012-03-15 13:39:09 UTC
(In reply to comment #50)
> kernel 3.3.0-0.rc6.git0.2.fc17.i686.PAE compiled without DEBUG flag? 

Yes.  We build one kernel per RC without debug enabled.

Comment 52 Mikhail 2012-03-15 14:38:10 UTC
Is there any benefit from the use of kernels with DEBUG flag to developers? Do you do profiling or grab information necessary for fixing bugs such as (12309) https://bugzilla.kernel.org/show_bug.cgi?id=12309

Comment 53 Dave Jones 2012-03-16 00:49:48 UTC
of course there's a benefit, or we wouldn't do it.
take a look at the open bugs to see the problems those options continuously catch.

Comment 54 Victor Costan 2012-03-18 01:21:00 UTC
Can you please provide a reasonably fast & easy method for switching to kernels without debugging enabled?

By "reasonably fast & easy", I mean better than http://fedoraproject.org/wiki/Building_a_custom_kernel. Ideally, it would involve adding another yum source.

The debugging kernel is making my workstation unusable (wouldn't be here otherwise), so I have to choose between reverting to a stable release, and building a kernel without debug flags. Right now, reverting is a lot easier, so you're driving testers away. I might not be able to catch kernel bugs, but I'd still report crashes in all the other packages.

I'm guessing you're concerned that if you provide a non-debug kernel, everyone will switch to it. I think that, as long as there is some action required, testers won't switch away from the debugging kernel unless it's causing them pain.

Thank you for your consideration!

Comment 55 Ben Boeckel 2012-03-18 04:13:49 UTC
FYI, you can get a non-debug F17 kernel from <http://koji.fedoraproject.org/koji/buildinfo?buildID=304743>. I got it as an update before, so it's just in my boot configuration, but downloading the RPMs directly will also work as mirrors likely have debug versions only again.

Comment 56 Mikhail 2012-03-18 08:17:01 UTC
Ok, how can I help solve my problem with the interface hangs during page swapping and hard work with disk using the DEBUG option.

Comment 57 Fedora End Of Life 2013-04-03 19:25:19 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 19 development cycle.
Changing version to '19'.

(As we did not run this process for some time, it could affect also pre-Fedora 19 development
cycle bugs. We are very sorry. It will help us with cleanup during Fedora 19 End Of Life. Thank you.)

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

Comment 58 Fedora End Of Life 2015-01-09 21:52:25 UTC
This message is a notice that Fedora 19 is now at end of life. Fedora 
has stopped maintaining and issuing updates for Fedora 19. It is 
Fedora's policy to close all bug reports from releases that are no 
longer maintained. Approximately 4 (four) weeks from now this bug will
be closed as EOL if it remains open with a Fedora 'version' of '19'.

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.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 19 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, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

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.

Comment 59 Fedora End Of Life 2015-02-18 13:37:04 UTC
Fedora 19 changed to end-of-life (EOL) status on 2015-01-06. Fedora 19 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.


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