1:49 p.m.
Rawhide is working great recently, with one exception:
gnome-terminal seems to make the xorg process use 100% of the CPU for a
2-3 seconds when scrolling text such as dmesg. Does not happen with
xterm, but I was wondering if anyone else had noticed anything like
this? I'm not sure what component to file this for in bugzilla, or how
to debug this.
Thanks,
Richard.
1:52 p.m.
On Tue, 2007-02-27 at 19:49 +0000, Richard Hughes wrote:
Rawhide is working great recently, with one exception:
gnome-terminal seems to make the xorg process use 100% of the CPU for a
2-3 seconds when scrolling text such as dmesg. Does not happen with
xterm, but I was wondering if anyone else had noticed anything like
this? I'm not sure what component to file this for in bugzilla, or how
to debug this.
Well it's at least partly Xorg's fault, but it would be helpful to know
what the slow path is there; so if you do file a bug against Xorg,
please accompany it with oprofile goodness.
- ajax
3:59 p.m.
On Tue, 2007-02-27 at 14:52 -0500, Adam Jackson wrote:
Well it's at least partly Xorg's fault, but it would be helpful to
know
what the slow path is there; so if you do file a bug against Xorg,
please accompany it with oprofile goodness.
Well, I get this:
CPU: Core Solo / Duo, speed 1662.57 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Unhalted clock cycles) with a unit mask
of 0x00 (Unhalted core cycles) count 860000
CPU_CLK_UNHALT...|
samples| %|
------------------
12704 82.6330 /usr/bin/Xorg
CPU_CLK_UNHALT...|
samples| %|
------------------
12066 94.9780 /usr/lib/xorg/modules/libfb.so
286 2.2513 /usr/bin/Xorg
216 1.7003 /usr/lib/xorg/modules/drivers/nv_drv.so
75 0.5904 /lib/libc-2.5.90.so
48 0.3778 /usr/lib/xorg/modules/libxaa.so
6 0.0472 /usr/lib/xorg/modules/extensions/libextmod.so
3 0.0236 /lib/librt-2.5.90.so
1 0.0079 /usr/lib/libXfont.so.1.4.1
1 0.0079 /usr/lib/xorg/modules/input/mouse_drv.so
1 0.0079 /usr/lib/xorg/modules/input/synaptics_drv.so
1 0.0079 /usr/lib/xorg/modules/libramdac.so
But also I get this (!!!):
oprofile: using NMI interrupt.
=================================
[ INFO: inconsistent lock state ]
2.6.20-1.2949.fc7 #1
---------------------------------
inconsistent {hardirq-on-W} -> {in-hardirq-W} usage.
swapper/0 [HC1[1]:SC0[0]:HE0:SE1] takes:
(oprofilefs_lock){+-..}, at: [<f8c6db5e>] nmi_cpu_setup+0x15/0x4f
[oprofile]
{hardirq-on-W} state was registered at:
[<c0442440>] __lock_acquire+0x448/0xba4
[<c0442f8e>] lock_acquire+0x56/0x6f
[<c0614949>] _spin_lock+0x2b/0x38
[<f8c6d33c>] oprofilefs_ulong_from_user+0x4e/0x74 [oprofile]
[<f8c6d38c>] ulong_write_file+0x2a/0x38 [oprofile]
[<c047e20b>] vfs_write+0xaf/0x163
[<c047e859>] sys_write+0x3d/0x61
[<c0405134>] syscall_call+0x7/0xb
[<ffffffff>] 0xffffffff
irq event stamp: 23424902
hardirqs last enabled at (23424901): [<c0614d4d>]
_spin_unlock_irqrestore+0x36/0x3c
hardirqs last disabled at (23424902): [<c0405bb5>]
call_function_interrupt+0x29/0x38
softirqs last enabled at (23424892): [<c042c0d8>] __do_softirq
+0xdc/0xe2
softirqs last disabled at (23424885): [<c04074dc>] do_softirq+0x61/0xd0
other info that might help us debug this:
no locks held by swapper/0.
stack backtrace:
[<c04062a5>] show_trace_log_lvl+0x1a/0x2f
[<c0406869>] show_trace+0x12/0x14
[<c04068ed>] dump_stack+0x16/0x18
[<c0440f67>] print_usage_bug+0x141/0x14b
[<c0441620>] mark_lock+0xa2/0x419
[<c04423b1>] __lock_acquire+0x3b9/0xba4
[<c0442f8e>] lock_acquire+0x56/0x6f
[<c0614949>] _spin_lock+0x2b/0x38
[<f8c6db5e>] nmi_cpu_setup+0x15/0x4f [oprofile]
[<c0417e6a>] smp_call_function_interrupt+0x3f/0x5b
[<c0405bbf>] call_function_interrupt+0x33/0x38
[<c0614896>] _spin_unlock+0x16/0x20
[<c043ded6>] clockevents_notify+0x3e/0x42
[<c0532f67>] acpi_state_timer_broadcast+0x2e/0x31
[<c05338e8>] acpi_processor_idle+0x285/0x419
[<c040348e>] cpu_idle+0xb7/0xdd
[<c0418eef>] start_secondary+0x330/0x338
[<00000000>] 0x0
=======================
Why do the simplest bugs always turn into the most complicated ones ;-)
Richard.
4:42 p.m.
On Tue, 2007-02-27 at 21:59 +0000, Richard Hughes wrote:
Well, I get this:
CPU: Core Solo / Duo, speed 1662.57 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Unhalted clock cycles) with a unit mask
of 0x00 (Unhalted core cycles) count 860000
CPU_CLK_UNHALT...|
samples| %|
------------------
12704 82.6330 /usr/bin/Xorg
CPU_CLK_UNHALT...|
samples| %|
------------------
12066 94.9780 /usr/lib/xorg/modules/libfb.so
That's pretty well expected. If anything's going to be burning CPU time
it's either fb or GLcore. (Or the driver itself when it sits in
infinite loops waiting for the command queue to catch up, but that case
usually means wedged hardware.) More interesting is knowing which
functions it's hitting, if you can get that.
Would also like to know whether the same slowdown happens when using
Option "ShadowFB". If not then we can assume the slowdown is being
caused by a software fallback to something that happens to be in card
memory, and there might be a reasonable heuristic for evicting things
from card memory when that happens, or just a smarter way to write that
routine that hits the bus less. But if it's still slow when shadowfb'd
then either it's some particularly naive code, or g-t is just asking us
to do a lot of really painful things.
But also I get this (!!!):
oprofile: using NMI interrupt.
=================================
[ INFO: inconsistent lock state ]
2.6.20-1.2949.fc7 #1
Yow!
- ajax
5:07 p.m.
On Tue, 2007-02-27 at 17:42 -0500, Adam Jackson wrote:
Would also like to know whether the same slowdown happens when using
Option "ShadowFB".
Using this option returns the console output to blindingly fast.
Do you want me to file this in bugzilla, or continue to debug this with
OProfile?
Thanks for your help with this.
Richard.
5:11 p.m.
On Tue, 2007-02-27 at 23:07 +0000, Richard Hughes wrote:
On Tue, 2007-02-27 at 17:42 -0500, Adam Jackson wrote:
> Would also like to know whether the same slowdown happens when using
> Option "ShadowFB".
Using this option returns the console output to blindingly fast.
Do you want me to file this in bugzilla, or continue to debug this with
OProfile?
Still would like some oprofile with symbol names for the non-shadowfb
case (although I have a reasonable idea), but yes, bz would be
excellent.
Re reasonable idea: Software alpha-blending of text just sucks. In
principle g-t is double-buffered, so the composition should be something
like CA blend to the backing pixmap followed by blit to the front
buffer, and therefore the backing pixmap could come out of card memory,
which would turn the blit into hostdata upload, which isn't _that_
painful. You could even damage-track the blending if you wanted,
although that might not be a win. Plus if you start evicting everything
you do text blends to, you might not have a lot left in card memory.
Tough to say.
Also it's not clear whether this is just latent sucking, or something
introduced between FC6 and now. Swapping out the X server to test might
be an idea, it should be reasonably independent.
- ajax
6 p.m.
On Tue, 2007-02-27 at 18:11 -0500, Adam Jackson wrote:
Also it's not clear whether this is just latent sucking, or
something
introduced between FC6 and now. Swapping out the X server to test might
be an idea, it should be reasonably independent.
I'm seeing this on Rawhide with X.org packages from FC6 (binary ATI crap
for my Macbook Pro). It didn't use to be like this (and it's forcing me
to use xterm - yuck!) so it points to something above X.
David
6:07 p.m.
On Tue, 2007-02-27 at 19:00 -0500, David Zeuthen wrote:
I'm seeing this on Rawhide with X.org packages from FC6 (binary ATI
crap for my Macbook Pro). It didn't use to be like this (and it's
forcing me to use xterm - yuck!) so it points to something above X.
https://bugzilla.redhat.com/bugzilla/show_bug.cgi?id=230294
Or for the mailing list;
hughsie@localhost:~$ opreport -cl --demangle=smart `which Xorg`
warning: /usr/bin/Xorg could not be read.
CPU: Core Solo / Duo, speed 1662.68 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Unhalted clock cycles) with a unit mask of 0x00 (Unhalted
core cycles) count 860000
samples % image name symbol name
-------------------------------------------------------------------------------
1582 88.2812 libfb.so fbCompositeSolidMask_nx8888x8888Cmmx
1582 100.000 libfb.so fbCompositeSolidMask_nx8888x8888Cmmx [self]
-------------------------------------------------------------------------------
136 7.5893 libfb.so fbCompositeSrcAdd_8888x8888mmx
136 100.000 libfb.so fbCompositeSrcAdd_8888x8888mmx [self]
-------------------------------------------------------------------------------
65 3.6272 nv_drv.so NVSync
65 100.000 nv_drv.so NVSync [self]
-------------------------------------------------------------------------------
5 0.2790 Xorg (no symbols)
5 100.000 Xorg (no symbols) [self]
-------------------------------------------------------------------------------
2 0.1116 libfb.so fbPolySegment32
2 100.000 libfb.so fbPolySegment32 [self]
-------------------------------------------------------------------------------
1 0.0558 libc-2.5.90.so free
1 100.000 libc-2.5.90.so free [self]
-------------------------------------------------------------------------------
1 0.0558 libfb.so fbSolidFillmmx
1 100.000 libfb.so fbSolidFillmmx [self]
-------------------------------------------------------------------------------
It's interesting davidz is getting this too on different hardware.
Richard.
6260
days inactive
6261
days old
7 comments
3 participants
participants (3)
-
Adam Jackson -
David Zeuthen -
Richard Hughes