xorg and ltrace: fatal combo?
Andreas Mohr
andi at lisas.de
Tue May 15 14:09:48 PDT 2007
Hello all,
on two PCs (Debian unstable/testing) with ATI cards
(one is using Rage Mobility M4 with r128, the other Radeon 9000 with radeon)
I get rather very severe effects when ltrace:ing a running /usr/bin/X
via ltrace -i -p <PID>: Xorg crashes and restarts (xdm) or locks up
almost instantly.
This happens with both xserver-xorg-core 2:1.3.0.0.dfsg-4 and
xserver-xorg-core 2:1.1.1-20.
And both current 2.6.21-mmX kernel versions and an older 2.6.16-ck5.
Is this a known issue? Does this also happen with non-ATI cards?
Obviously This Damn Definitely Should Not Happen (tm).
A log may look like:
Backtrace:
0: /usr/bin/X(xf86SigHandler+0x81) [0x80c2511]
1: [0xffffe420]
2: [0x8258ae0]
Fatal server error:
Caught signal 11. Server aborting
(II) AIGLX: Suspending AIGLX clients for VT switch
ltrace.log may contain something like:
.
.
.
[0x81afa53] select(256, 0x81f65e0, 0, 0, 0xbffd04b0 <unfinished ...>
[0xb7e17868] --- SIGALRM (Alarm clock) ---
[0x81b649f] __errno_location() = 0xb7d3868c
[0x81b6379] setitimer(0, 0xbffcff54, 0, 0x10000000, 0) = 0
[0x81afa53] <... select resumed> ) = -1
[0x81afa5a] __errno_location() = 0xb7d3868c
[0x81b6fca] gettimeofday(0xbffd0268, NULL) = 0
[0x81b6fca] gettimeofday(0xbffd0268, NULL) = 0
[0x81afa53] select(256, 0x81f65e0, 0, 0, 0xbffd04b0) = 1
[0x81afa5a] __errno_location() = 0xb7d3868c
[0x80ac4d1] sigemptyset(0xbffd010c) = 0
[0x80ac4e1] sigaddset(0xbffd010c, 29) = 0
[0x80ac4f5] sigprocmask(0, 0xbffd010c, 0xbffd008c) = 0
[0x80ac505] sigismember(0xbffd008c, 29) = 0
[0x80a8c7d] read(4, ".", 64) = 1
[0x81b6fca] gettimeofday(0xbffd0078, NULL) = 0
[0x80ac3d1] sigemptyset(0xbffcffcc) = 0
[0x80ac3e5] sigprocmask(0, 0xbffcffcc, 0xbffcff4c) = 0
[0x80ac3f5] sigismember(0xbffcff4c, 29) = 1
[0x80ac45f] sigemptyset(0xbffd0110) = 0
[0x80ac46f] sigaddset(0xbffd0110, 29) = 0
[0x80ac487] sigprocmask(1, 0xbffd0110, NULL) = 0
[0x81b6319] setitimer(0, 0xbffd0264, 0, 0x81f65e0, 3) = 0
[0x81b6fca] gettimeofday(0xbffd0348, NULL) = 0
[0x81b485e] memmove(0x867c650, 0xbffd044c, 32, 0x80e0acb, 0xbffd009c) = 0x867c650
[0x81b43a0] __errno_location() = 0xb7d3868c
[0x81ba57e] writev(15, 0xbffd0454, 1, 0x816fc44, 0x8694790) = 32
[0x81b6fca] gettimeofday(0xbffd0268, NULL) = 0
[0x81b6fca] --- SIGALRM (Alarm clock) ---
[0xffffffff] +++ killed by SIGKILL +++
Side note: I was looking into the ltrace thing since I discovered
even simple window tab switching causing a friggin' 24% profiling traffic
in page fault / __page_alloc / malloc/free areas.
ltrace is showing huge (== pretty dominant) streams of malloc/free,
which (when looking up the instruction address in gdb) resolves to Xalloc().
Of course Xalloc is a pretty generic function, so it's not obvious whether
someone is having excessive activity, but it seems something should be done
about excessive malloc/free use given my 24% oprofile result (this is 24%
profiling activity, not 24% absolute activity, I think).
Very frequently an malloc() is free()d again immediately:
[0x81afa5a] __errno_location() = 0xb7d3868c
[0x81b6fca] gettimeofday(0xbffd0268, NULL) = 0
[0x81b6fca] gettimeofday(0xbffd0268, NULL) = 0
[0x81afa53] select(256, 0x81f65e0, 0, 0, 0xbffd04b0) = 1
[0x81afa5a] __errno_location() = 0xb7d3868c
[0x81b6319] setitimer(0, 0xbffd0264, 0, 0x81f65e0, 3) = 0
[0x81b6fca] gettimeofday(0xbffd0268, NULL) = 0
[0x81ba63e] read(15, "8", 5160) = 5160
[0x81b6501] free(0x873a920) = <void>
[0x81b6501] free(0x875e178) = <void>
[0x81b6787] malloc(72) = 0x8792778
[0x81b6501] free(0x8792778) = <void>
[0x81b6501] free(0x86f67a8) = <void>
[0x81b6501] free(0x86dbd68) = <void>
[0x81b6787] malloc(72) = 0x8722498
[0x81b6501] free(0x8722498) = <void>
[0x81b6787] malloc(440) = 0x86bf0d0
[0x81b6787] malloc(88) = 0x8772820
[0x815164e] strlen("nearest") = 7
[0x81b6787] malloc(88) = 0x8753c08
[0x815164e] strlen("nearest") = 7
[0x81b6787] malloc(12) = 0x86dbd68
[0x81b6787] malloc(12) = 0x875e178
[0x81b6501] free(0x86dbd68) = <void>
[0x81b6501] free(0x8753c08) = <void>
[0x81b6787] malloc(72) = 0x86fc610
[0x81b6501] free(0x86fc610) = <void>
[0x81b6787] malloc(72) = 0x8772a90
[0x81b6501] free(0x8772a90) = <void>
[0x81b6501] free(0x875e178) = <void>
[0x81b6501] free(0x8772820) = <void>
[0x81b6501] free(0x86bf0d0) = <void>
[0x81b6787] malloc(72) = 0x8792778
[0x81b6501] free(0x8792778) = <void>
[0x81b6787] malloc(72) = 0x86f67a8
[0x81b6501] free(0x86f67a8) = <void>
[0x81b6787] malloc(440) = 0x86bf0d0
[0x81b6787] malloc(88) = 0x87983c8
[0x815164e] strlen("nearest") = 7
[0x81b6787] malloc(88) = 0x8753c08
[0x815164e] strlen("nearest") = 7
[0x81b6787] malloc(12) = 0x875e178
[0x81b6787] malloc(12) = 0x86dbd68
[0x81b6501] free(0x875e178) = <void>
[0x81b6501] free(0x8753c08) = <void>
[0x81b6787] malloc(72) = 0x8722498
[0x81b6501] free(0x8722498) = <void>
[0x81b6787] malloc(72) = 0x86fc610
[0x81b6501] free(0x86fc610) = <void>
[0x81b6501] free(0x86dbd68) = <void>
[0x81b6501] free(0x87983c8) = <void>
[0x81b6501] free(0x86bf0d0) = <void>
[0x81b6787] malloc(72) = 0x8772a90
[0x81b6501] free(0x8772a90) = <void>
[0x81b6787] malloc(72) = 0x8792778
[0x81b6501] free(0x8792778) = <void>
[0x81b6787] malloc(824) = 0x8772f10
[0x81b6787] malloc(88) = 0x8772820
[0x815164e] strlen("nearest") = 7
[0x81b6787] malloc(88) = 0x8753c08
[0x815164e] strlen("nearest") = 7
[0x81b6787] malloc(12) = 0x86c3838
[0x81b6787] malloc(12) = 0x8786418
[0x81b6501] free(0x86c3838) = <void>
Maybe one should let Xalloc() have its own memory pools (via mmap or so)
instead of very frequently using malloc() syscalls.
Window tab switching performance with overlapped windows is truly glacial
(well, comparatively at least) on this P3/700 here...
Andreas Mohr
More information about the xorg
mailing list