Without identifiable cause X does sometimes (well, too often to work with the system) heavily load the CPU. strace -p freezes the machine most of the time. I was able to provide a log with shows an endless gettimeofday loop. Reproducible: Sometimes Steps to Reproduce: 1. 2. 3. # emerge info Portage 2.0.51.19 (default-linux/x86/2005.0, gcc-3.3.5-20050130, glibc-2.3.4.20041102-r1, 2.6.11-gentoo-r11 i686) ================================================================= System uname: 2.6.11-gentoo-r11 i686 Intel(R) Pentium(R) M processor 1.60GHz Gentoo Base System version 1.6.12 Python: dev-lang/python-2.3.5 [2.3.5 (#1, Apr 30 2005, 16:24:40)] dev-lang/python: 2.3.5 sys-apps/sandbox: [Not Present] sys-devel/autoconf: 2.59-r6, 2.13 sys-devel/automake: 1.7.9-r1, 1.8.5-r3, 1.5, 1.4_p6, 1.6.3, 1.9.5 sys-devel/binutils: 2.15.92.0.2-r10 sys-devel/libtool: 1.5.16 virtual/os-headers: 2.6.8.1-r2 ACCEPT_KEYWORDS="x86" AUTOCLEAN="yes" CFLAGS="-O2 -march=pentium3 -pipe -fomit-frame-pointer -funroll-loops -mmmx -msse -msse2 -mfpmath=sse" CHOST="i686-pc-linux-gnu" CONFIG_PROTECT="/usr/kde/3.4/env /usr/kde/3.4/share/config /usr/kde/3.4/shutdown /usr/lib/X11/xkb /usr/share/config" CONFIG_PROTECT_MASK="/etc/gconf /etc/terminfo /etc/env.d" CXXFLAGS="-O2 -march=pentium3 -pipe -fomit-frame-pointer -funroll-loops -mmmx -msse -msse2 -mfpmath=sse" DISTDIR="/usr/portage/distfiles" FEATURES="autoaddcvs autoconfig ccache distlocks sandbox sfperms strict" GENTOO_MIRRORS="ftp://sunsite.informatik.rwth-aachen.de/pub/Linux/gentoo" MAKEOPTS="-j2" PKGDIR="/usr/portage/packages" PORTAGE_TMPDIR="/var/tmp" PORTDIR="/usr/portage" PORTDIR_OVERLAY="/usr/local/portage" SYNC="rsync://rsync.de.gentoo.org/gentoo-portage" USE="x86 X aac acpi alsa apm arts avi berkdb bitmap-fonts cdr crypt cups curl dvd emboss encode esd fam foomaticdb fortran gdbm gif gpm gtk gtk2 icc icc-pgo ieee1394 imagemagick imlib ipv6 java jpeg kde libg++ libwww mad mikmod mmx motif mp3 mpeg ncurses nls nptl nptlonly ogg oggvorbis opengl oss pam pdflib perl png python qt quicktime readline samba sdl spell sse ssl svga tcltk tcpd threads tiff truetype truetype-fonts type1-fonts unicode vorbis wifi xine xml2 xmms xv zlib userland_GNU kernel_linux elibc_glibc" Unset: ASFLAGS, CBUILD, CTARGET, LANG, LC_ALL, LDFLAGS, LINGUAS gettimeofday({1119210368, 403147}, NULL) = 0 read(26, "5\30\4\0002\301\252\2F\0\0\0 \0 \0>\377\7\0\313\306\273"..., 4120) = 4120 read(26, "\377\377\377\377\377\377\377\377\250\250\250\377\375\375"..., 260) = 260 read(26, "5\1\4\0006\301\252\2F\0\0\0 \0 \0007\377\4\0007\301\252"..., 4120) = 1416 writev(26, [{"\16\211m\"4\301\252\2\0\0>\r\0\0\0\0\0\0\0\0 \0\0\0 \0"..., 64}, {"\377\377\377\377\241\241\241\377\317\317\317 \377\317\317"..., 4096}], 2) = 4160 read(26, 0xd935640, 4120) = -1 EAGAIN (Resource temporarily unavailable) gettimeofday({1119210368, 404304}, NULL) = 0 select(256, [1 3 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 38], NULL, NULL, {1344, 469000}) = 1 (in [26], left {1344, 469000}) gettimeofday({1119210368, 404716}, NULL) = 0 read(26, "I\2\5\0:\304\273\2\0\0\0\0 \0 \0\377\377\377\377", 4120) = 20 read(26, 0xd935640, 4120) = -1 EAGAIN (Resource temporarily unavailable) writev(26, [{"\1\10\203\"\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0@V\223"..., 1056}], 1) = 1056 gettimeofday({1119210368, 405298}, NULL) = 0 select(256, [1 3 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 38], NULL, NULL, {1344, 468000}) = 1 (in [26], left {1344, 468000}) gettimeofday({1119210368, 405831}, NULL) = 0 read(26, "5\30\4\0<\301\252\2F\0\0\0 \0 \0>\377\7\0007\304\273\2"..., 4120) = 4120 read(26, "\377\377\377\377\377\377\377\377\250\250\250\377\375\375"..., 260) = 260 read(26, "5\1\4\0@\301\252\2F\0\0\0 \0 \0007\377\4\0A\301\252\2@"..., 4120) = 1416 writev(26, [{"\16A\217\">\301\252\2\0\0>\t\0\0\0\0\0\0\0\0 \0\0\0 \0"..., 64}, {"\377\377\377\377\377\377\377\377\317\317\317 \377\317\317"..., 4096}], 2) = 4160 read(26, 0xd935640, 4120) = -1 EAGAIN (Resource temporarily unavailable) gettimeofday({1119210368, 407633}, NULL) = 0 select(256, [1 3 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 38], NULL, NULL, {1344, 466000}) = 1 (in [19], left {1344, 466000})
Created attachment 61506 [details] strace -p log repeating strace -p log. Aborted by CTRL-C.
Created attachment 61507 [details] strace X log
of course X is going to call gettimeofday a lot, it timestamps packets. it would be more interesting to know what it's being asked to do that's taking so much time. iow, oprofile numbers or gdb backtraces are more useful than strace output. and this is almost certainly an upstream problem, not a gentoo problem.
I try to provide oprofile/gdb data next time the problem occurs but could you be somewhat more precise on that upstream theory?
(In reply to comment #4) > I try to provide oprofile/gdb data next time the problem occurs but could you > be somewhat more precise on that upstream theory? what's to be precise about? none of the patches gentoo is applying should be creating code paths where we can get heavy CPU usage. thus it's probably a problem in Xorg's code rather than in the changes gentoo is made; hence, upstream.
Well, the machine freezes when I try to attach to the X process with gdb (so does strace -p) :(
You need to ssh in and gdb.
this is also why i suggested oprofile, as it's non-intrusive.
Hmm, well, this is a backtrace when X did load the CPU *relatively* high (not 100%): #0 0xffffe410 in ?? () #1 0xbffff688 in ?? () #2 0x00000000 in ?? () #3 0x08216440 in AnyClientsWriteBlocked () #4 0xb7f0df9d in ___newselect_nocancel () from /lib/tls/libc.so.6 #5 0x080e477e in WaitForSomething () #6 0x080c5c15 in Dispatch () #7 0x080d29d6 in main ()
I have the 100% problem now and the backtrace is identical. Unfortunately I currently don't have oprofile installed on that particular machine.
How does that oprofiler thing work? I started the profiler (oprof_start), profiles and pressed Stop profile and then save and quit. Well, and where the profile log now? Parameters used: CPUTYPE timer BUF_SIZE default value CPU_BUF_SIZE default value SEPARATE_LIB 1 SEPARATE_KERNEL 1 SEPARATE_THREAD 0 SEPARATE_CPU 0 CALLGRAPH 0 VMLINUX /lib/modules/2.6.11-gentoo-r11/build/vmlinux KERNEL_RANGE c0100000,c0416b16 executing oprofiled --separate-lib=1 --separate-kernel=1 --separate-thread=0 --separate-cpu=0 --events= --vmlinux=/lib/modules/2.6.11-gentoo-r11/build/vmlinux --kernel-range=c0100000,c0416b16 --verbose=all Daemon started. Profiler running. Stopping profiling. Killing daemon.
Please tell me, what oprofile information you need. From what I can see the trace below doesn't say anything but that X is loading the CPU... # opreport --long-filenames -l /usr/X11R6/bin/X warning: /no-vmlinux could not be found. CPU: CPU with timer interrupt, speed 0 MHz (estimated) Profiling through timer interrupt Processes with a thread ID of 6792 Processes with a thread ID of all samples % samples % image name symbol name 9388 96.9835 379977 81.2052 /usr/X11R6/bin/Xorg (no symbols) 51 0.5269 741 0.1584 /lib/tls/libc.so.6 _int_malloc 41 0.4236 267 0.0571 /lib/tls/libc.so.6 __libc_select 34 0.3512 332 0.0710 /lib/tls/libc.so.6 __i686.get_pc_thunk.bx 31 0.3202 234 0.0500 /lib/tls/libc.so.6 ___newselect_nocancel 22 0.2273 400 0.0855 /lib/tls/libc.so.6 __GI___libc_malloc 21 0.2169 244 0.0521 /lib/tls/libc.so.6 __GI___errno_location 19 0.1963 347 0.0742 /lib/tls/libc.so.6 __GI_memmove 17 0.1756 184 0.0393 /lib/tls/libc.so.6 malloc_consolidate 11 0.1136 228 0.0487 /lib/tls/libc.so.6 __GI_read 10 0.1033 199 0.0425 /lib/tls/libc.so.6 __libc_writev 7 0.0723 157 0.0336 /lib/tls/libc.so.6 __i686.get_pc_thunk.cx 5 0.0517 155 0.0331 /lib/tls/libc.so.6 __GI___gettimeofday_internal 5 0.0517 150 0.0321 /lib/tls/libc.so.6 _int_free 4 0.0413 28 0.0060 /lib/tls/libc.so.6 __GI_memcpy 4 0.0413 170 0.0363 /lib/tls/libc.so.6 __cfree 4 0.0413 133 0.0284 /lib/tls/libc.so.6 __read_nocancel 4 0.0413 93 0.0199 /lib/tls/libc.so.6 do_writev 1 0.0103 25 0.0053 /lib/tls/libc.so.6 __GI_memset 1 0.0103 5 0.0011 /lib/tls/libc.so.6 abs 0 0 1 2.1e-04 /lib/tls/libc.so.6 __GI_sigaddset 0 0 1 2.1e-04 /lib/tls/libc.so.6 __GI_sigemptyset 0 0 4 8.5e-04 /lib/tls/libc.so.6 __GI_sigismember 0 0 15 0.0032 /lib/tls/libc.so.6 __GI_strlen 0 0 2 4.3e-04 /lib/tls/libc.so.6 __GI_strncmp 0 0 1 2.1e-04 /lib/tls/libc.so.6 __GI_strncpy 0 0 1 2.1e-04 /lib/tls/libc.so.6 __realloc 0 0 1 2.1e-04 /lib/tls/libc.so.6 __sigprocmask 0 0 3 6.4e-04 /lib/tls/libc.so.6 _int_realloc 0 0 83824 17.9141 /no-vmlinux (no symbols)
I have relatively high X load right now however fat from the usual 70+%: CPU: CPU with timer interrupt, speed 0 MHz (estimated) Profiling through timer interrupt Processes with a thread ID of 14147 Processes with a thread ID of 14558 Processes with a thread ID of all samples % samples % samples % image name symbol name 175 11.8403 68 1.1210 0 0 Xorg XYToWindow 111 7.5101 579 9.5450 0 0 libc-2.3.5.so (no symbols) 83 5.6157 0 0 0 0 vmlinux unix_poll 56 3.7889 0 0 0 0 vmlinux do_select 54 3.6536 0 0 0 0 vmlinux fget 53 3.5859 0 0 0 0 vmlinux sock_poll 39 2.6387 0 0 0 0 vmlinux __copy_to_user_ll 35 2.3681 0 0 0 0 vmlinux add_wait_queue 34 2.3004 0 0 0 0 vmlinux schedule 33 2.2327 127 2.0936 16 0.8408 Xorg StandardReadRequestFromClient 31 2.0974 89 1.4672 0 0 Xorg SecurityLookupIDByType 30 2.0298 156 2.5717 0 0 Xorg SecurityLookupIDByClass 28 1.8945 0 0 0 0 vmlinux remove_wait_queue 22 1.4885 0 0 0 0 vmlinux buffered_rmqueue 21 1.4208 101 1.6650 29 1.5239 Xorg WaitForSomething 20 1.3532 104 1.7145 9 0.4729 Xorg FlushClientCaches
http://bugs.kde.org/show_bug.cgi?id=102733 https://bugs.freedesktop.org/show_bug.cgi?id=3581
Are you using kompmgr or some other compositing method?
Yes. Well, I didn't have had the problem anymore since I uninstalled kooldock, gtk-qt-engine and switched off KDE/kompmgr's windows transparency. Howevery I still use kompmgr for window shadows.
This seems to be a KDE problem then. I haven't been able to reproduce with xcompmgr. I'll mark this as upstream and point to the KDE bug. Thanks.
