[arch-general] Why is clock_gettime called when the mouse moves?
I don't know what is the best place to ask the following question, if here, in the Arch forums (which ?) or in the X.org mailing list. I will ask here first. I am open to suggestions. I have two Arch desktops. Desktop #1: MSI motherboard, Nvidia graphics with proprietary driver, Xfce on top of openbox. Desktop #2: Dell, Intel graphics, Xfce on top of openbox. If I run strace <GUI app> where <GUI app> could be for example Mousepad or Emacs, and move the mouse I get lots of stuff in the trace in both desktops. In desktop #1 however most of trace consists of calls to clock_gettime. This seems weird to me. In the excerpt below which shows both seconds and nano seconds, in the same second there are lots of messages. Why? As far as I know there is nothing wrong with the clock, and there is no special X configuration, so why does one desktop shows calls to clock_gettime and the other not? Any ideas? clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=338313354}) = 0 poll([{fd=3, events=POLLIN}, {fd=8, events=POLLIN}, {fd=9, events=POLLIN}], 3, 0) = 0 (Timeout) clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=338370693}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=338397792}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=338425239}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=338452337}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=338479505}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=338506324}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=338532794}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=338559683}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=338586432}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=338617162}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=338651035}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=338686654}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=338721993}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=338762990}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=338799447}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=338836812}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=338872989}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=338909307}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=338942411}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=338971326}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339001287}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339030900}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339061700}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339090335}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339122531}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339152283}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339181826}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339212696}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339243915}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339273527}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339305864}) = 0 poll([{fd=3, events=POLLIN}, {fd=8, events=POLLIN}, {fd=9, events=POLLIN}], 3, 0) = 0 (Timeout) clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339372701}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339404270}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339436117}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339467196}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339498276}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339530402}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339562878}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339604015}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339639424}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339670364}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339701722}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339732871}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339764649}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339803620}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339835398}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339866337}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339897975}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339929683}) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339959715}) = 0
Hi Piscium,
I have two Arch desktops.
Desktop #1: MSI motherboard, Nvidia graphics with proprietary driver, Xfce on top of openbox. Desktop #2: Dell, Intel graphics, Xfce on top of openbox.
If I run strace <GUI app> where <GUI app> could be for example Mousepad or Emacs, and move the mouse I get lots of stuff in the trace in both desktops. In desktop #1 however most of trace consists of calls to clock_gettime. This seems weird to me. In the excerpt below which shows both seconds and nano seconds, in the same second there are lots of messages. Why? As far as I know there is nothing wrong with the clock, and there is no special X configuration, so why does one desktop shows calls to clock_gettime and the other not? Any ideas?
clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=338313354}) = 0 poll([{fd=3, events=POLLIN}, {fd=8, events=POLLIN}, {fd=9, events=POLLIN}], 3, 0) = 0 (Timeout)
It's normal to call clock_gettime() just before poll() as part of the calculation for poll()'s last parameter which is the time-out in milliseconds. Running xclock(1), I see this as poll() gets called for the next event after the enter and leave window events arrive, with the timeout getting shorter as the time to update the clock draws near.
clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=338370693}) = 0 ... clock_gettime(CLOCK_MONOTONIC, {tv_sec=36619, tv_nsec=339305864}) = 0 poll([{fd=3, events=POLLIN}, {fd=8, events=POLLIN}, {fd=9, events=POLLIN}], 3, 0) = 0 (Timeout)
It looks like something is looping, calling clock_gettime(), until a millisecond has passed and then another zero-time-out poll() is called. I suggest using the simplest X client you can which shows the issue, e.g. xev(1). strace can be told to not trace its write(2) output with ‘-e \!write’, assuming the exclamation mark of shell history needs escaping. I found a couple of pages which may be of interest. The first shows others having similar issues with Nvidia's driver. https://forums.developer.nvidia.com/t/high-cpu-usage-on-xorg-when-the-extern... The second, if you read the two other emails in the thread, fixes the problem by changing the kernel's clock source which may differ between your two test machines? -- Cheers, Ralph.
0. Check that the two installations are both up-to-date and the installed packages come from the official repos 1. Run ldd "$(which GUI_APP)" on both systems, and compare. GUI_APP should be one of your reproducers 2. Maybe try the stack trace option for strace? Maybe try ltrace? Regards, Neven
participants (3)
-
Neven Sajko
-
Piscium
-
Ralph Corderoy