Re: 1000x slowdown in simple tk prog on Mac OS X 10.10.1 (XQuartz 2.7.7)
Re: 1000x slowdown in simple tk prog on Mac OS X 10.10.1 (XQuartz 2.7.7)
- Subject: Re: 1000x slowdown in simple tk prog on Mac OS X 10.10.1 (XQuartz 2.7.7)
- From: Marty Sereno <email@hidden>
- Date: Mon, 08 Dec 2014 06:03:53 -0800 (PST)
hi jeremy
I filed a bug report with Apple.
I tried a number of different things but
always reliably experience the 1000x
slowdown.
Here are 3 lines that get written to
/var/log/system.log on XQuartz startup:
### from /var/log/system.log on startup XQuartz.app
Dec 8 11:47:34 buc06 com.apple.xpc.launchd[1] (org.macosforge.xquartz.privileged_startx[11043]): Endpoint has been activated through legacy launch(3) APIs. Please switch to XPC or bootstrap_check_in(): org.macosforge.xquartz.privileged_startx
Dec 8 11:47:35 buc06.psychol.ucl.ac.uk org.macosforge.xquartz.startx[11027]: xauth: file /Users/sereno/.serverauth.11028 does not exist
Dec 8 11:47:37 buc06.psychol.ucl.ac.uk org.macosforge.xquartz.startx[11027]: /opt/X11/bin/xinit: XFree86_VT property unexpectedly has 0 items instead of 1
The DISPLAY variable in this case was:
DISPLAY=/private/tmp/com.apple.launchd.zRop57LYiu/org.macosforge.xquartz:0
The file, ~/.serverauth.11028, that is complained about
does in fact exist, and looks normal (some non-ASCII
chars in it, looked normal).
The ~/.Xauthority file was there and contained
some similar byte strings to ~/.serverauth.11028
cheers,
marty
On Tue, 2 Dec 2014, Jeremy Huddleston Sequoia wrote:
Thanks Marty,
That rules out xauth's timeout as influencing your metrics and thus does continue to point to a changes in OS X causing the regression. Please do file a radar at http://bugreport.apple.com and include the information you just included in this email.
Thanks,
Jeremy
On Dec 2, 2014, at 04:49, Marty Sereno <email@hidden> wrote:
hi jeremy
All of your tests are still using the launchd socket. I want to know if
the issue is due to xauth with the new launchd socket path in Yosemite,
so to test that, please use the *traditional* socket rather than the
launchd socket. Please set DISPLAY to ":0" or ":1" or ":2" depending
on what your server is using. You can check the running processes with
ps to see the arguments passed to Xquartz to figure out what it should
be set to for testing.
sorry for not understanding
the first time.
I just now did the test you
originally asked for in bash:
DISPLAY=:0 /full/path/wish zz.tcl
Same 10 sec draw time.
I've appended (probably mailer-mangled) outputs
of ps and taskinfo.
cheers,
marty
Here is ps that suggested using DISPLAY=:0
##########################################################################
% ps auxwww | grep X11
319 ?? S 0:01.68 /Applications/Utilities/XQuartz.app/Contents/MacOS/X11.bin
329 ?? S 0:00.02 /opt/X11/bin/xterm -sb -sl 10000 -geometry 80x12+10+600
330 ?? S 0:00.00 /opt/X11/lib/X11/xinit/launchd_startx /opt/X11/bin/startx -- /opt/X11/bin/Xquartz
331 ?? S 0:00.01 /bin/sh /opt/X11/bin/startx -- /opt/X11/bin/Xquartz
396 ?? S 0:00.00 /opt/X11/bin/xinit /opt/X11/lib/X11/xinit/xinitrc -- /opt/X11/bin/Xquartz :0 -nolisten tcp -auth /Users/sereno/.serverauth.331
399 ?? S 0:00.00 /opt/X11/bin/Xquartz :0 -nolisten tcp -auth /Users/sereno/.serverauth.331
485 ?? S 0:00.06 /opt/X11/bin/quartz-wm
Here are taskinfo outputs (with wish8.5 running)
##########################################################################
root# taskinfo wish8.5
process: "wish8.5" [672]
coalition ID: 188
suspend count: 0
virtual bytes: 2.39 GB; resident bytes: 5.74 MB
run time: 1 s
user/system time (current threads): 0.032529 s / 0.014386 s
user/system time (terminated threads): 0.000000 s / 0.000000 s
interrupt wakeups: 0 (0 / nan% from platform idle)
default sched policy: POLICY_TIMESHARE
dirty tracking: untracked
boosts: 0 (0 externalized)
requested policy (0x50200):
req apptype: TASK_APPTYPE_APP_DEFAULT
req role: TASK_UNSPECIFIED
req qos clamp: THREAD_QOS_UNSPECIFIED
req base/override latency qos: LATENCY_QOS_TIER_UNSPECIFIED / LATENCY_QOS_TIER_UNSPECIFIED
req base/override thruput qos: THROUGHPUT_QOS_TIER_UNSPECIFIED / THROUGHPUT_QOS_TIER_UNSPECIFIED
req darwin BG: NO
req internal/external iotier: THROTTLE_LEVEL_TIER0 (IMPORTANT) / THROTTLE_LEVEL_TIER0 (IMPORTANT)
req darwin BG iotier: THROTTLE_LEVEL_TIER2 (UTILITY)
req managed: NO
req other:
suppression behaviors:
effective policy (0x40000200):
eff role: TASK_UNSPECIFIED
eff latency qos: LATENCY_QOS_TIER_UNSPECIFIED
eff thruput qos: THROUGHPUT_QOS_TIER_UNSPECIFIED
eff darwin BG: NO
eff iotier: THROTTLE_LEVEL_TIER0 (IMPORTANT)
eff managed: NO
eff other:
imp_donor: YES
imp_receiver: DE-NAP
adaptive daemon: NO (boosted: NO)
##########################################################################
root# taskinfo quartz-wm
process: "quartz-wm" [485]
coalition ID: 189
suspend count: 0
virtual bytes: 2.47 GB; resident bytes: 7.05 MB
run time: 3152 s
user/system time (current threads): 0.055803 s / 0.049353 s
user/system time (terminated threads): 0.001216 s / 0.001540 s
interrupt wakeups: 25 (14 / 56.00% from platform idle)
default sched policy: POLICY_TIMESHARE
dirty tracking: untracked
boosts: 0 (0 externalized)
requested policy (0x100000120200):
req apptype: TASK_APPTYPE_DAEMON_STANDARD
req role: TASK_UNSPECIFIED
req qos clamp: THREAD_QOS_UNSPECIFIED
req base/override latency qos: LATENCY_QOS_TIER_0 / LATENCY_QOS_TIER_UNSPECIFIED
req base/override thruput qos: THROUGHPUT_QOS_TIER_0 / THROUGHPUT_QOS_TIER_UNSPECIFIED
req darwin BG: NO
req internal/external iotier: THROTTLE_LEVEL_TIER0 (IMPORTANT) / THROTTLE_LEVEL_TIER0 (IMPORTANT)
req darwin BG iotier: THROTTLE_LEVEL_TIER2 (UTILITY)
req managed: NO
req other:
suppression behaviors:
effective policy (0x51010201):
eff role: TASK_UNSPECIFIED
eff latency qos: LATENCY_QOS_TIER_0
eff thruput qos: THROUGHPUT_QOS_TIER_0
eff darwin BG: NO
eff iotier: THROTTLE_LEVEL_TIER1 (STANDARD)
eff managed: NO
eff other:
imp_donor: YES
imp_receiver: NO
adaptive daemon: NO (boosted: NO)
##########################################################################
root# taskinfo X11.bin
process: "X11.bin" [319]
coalition ID: 188
suspend count: 0
virtual bytes: 2.58 GB; resident bytes: 56.20 MB
run time: 3179 s
user/system time (current threads): 2.211459 s / 1.456876 s
user/system time (terminated threads): 0.128282 s / 0.207724 s
interrupt wakeups: 10413 (9042 / 86.83% from platform idle)
default sched policy: POLICY_TIMESHARE
dirty tracking: untracked
boosts: 0 (0 externalized)
requested policy (0x100001152200):
req apptype: TASK_APPTYPE_APP_DEFAULT
req role: TASK_FOREGROUND_APPLICATION
req qos clamp: THREAD_QOS_UNSPECIFIED
req base/override latency qos: LATENCY_QOS_TIER_0 / LATENCY_QOS_TIER_UNSPECIFIED
req base/override thruput qos: THROUGHPUT_QOS_TIER_0 / THROUGHPUT_QOS_TIER_UNSPECIFIED
req darwin BG: NO
req internal/external iotier: THROTTLE_LEVEL_TIER0 (IMPORTANT) / THROTTLE_LEVEL_TIER0 (IMPORTANT)
req darwin BG iotier: THROTTLE_LEVEL_TIER2 (UTILITY)
req managed: NO
req other: boosted
suppression behaviors:
effective policy (0x81110200):
eff role: TASK_FOREGROUND_APPLICATION
eff latency qos: LATENCY_QOS_TIER_0
eff thruput qos: THROUGHPUT_QOS_TIER_0
eff darwin BG: NO
eff iotier: THROTTLE_LEVEL_TIER0 (IMPORTANT)
eff managed: NO
eff other:
imp_donor: CURRRENTLY
imp_receiver: DE-NAP
adaptive daemon: NO (boosted: NO)
On Mon, 1 Dec 2014, Jeremy Huddleston Sequoia wrote:
Hi Marty,
All of your tests are still using the launchd socket. I want to know if the issue is due to xauth with the new launchd socket path in Yosemite, so to test that, please use the *traditional* socket rather than the launchd socket. Please set DISPLAY to ":0" or ":1" or ":2" depending on what your server is using. You can check the running processes with ps to see the arguments passed to Xquartz to figure out what it should be set to for testing.
Thanks,
Jeremy
On Dec 1, 2014, at 10:28, Marty Sereno <email@hidden> wrote:
hi jeremy
thanks much for the response.
the DISPLAY var on my 10.10.1 machine (Mac Pro, 6-core, D700's) looked OK:
DISPLAY=/private/tmp/com.apple.launchd.clFuL77xZD/org.macosforge.xquartz:0
and here is the socket:
buc06:sereno[7] ls -al /tmp/com.apple.launchd.clFuL77xZD
total 0
drwx------ 3 sereno wheel 102 Dec 1 18:09 ./
drwxrwxrwt 9 root wheel 306 Dec 1 18:09 ../
srw-rw-rw- 1 sereno wheel 0 Dec 1 18:09 org.macosforge.xquartz:0
For comparison, on my non-slow 10.6.8 machine (2011
MacBook Pro 17"), the DISPLAY var looks like this:
DISPLAY=/tmp/launch-MhYGZd/org.macosforge.xquartz:0
All the following uniformly take 10 sec (I assume you
meant a ';' in between DISPLAY= and /path/...),
on the 10.10.1 Mac Pro machine:
DISPLAY=/private/tmp/com.apple.launchd.clFuL77xZD/org.macosforge.xquartz:0
/Users/sereno/Developer/csurfsrc/tcltktix/bin/Darwin-x86_64/wish8.5
[source <script_below>, or paste script into wish prompt]
or
DISPLAY=/private/tmp/com.apple.launchd.clFuL77xZD/org.macosforge.xquartz:0
/tmp/zz.tcl # zz.tcl is wish script below
or
env \
DISPLAY=/private/tmp/com.apple.launchd.clFuL77xZD/org.macosforge.xquartz:0 \
/Users/sereno/Developer/csurfsrc/tcltktix/bin/Darwin-x86_64/wish8.5
or
env \
DISPLAY=/private/tmp/com.apple.launchd.clFuL77xZD/org.macosforge.xquartz:0 \
/Users/sereno/Developer/csurfsrc/tcltktix/bin/Darwin-x86_64/wish8.5 \
zz.tcl # zz.tcl is wish script below
Back in XQuartz 2.7.4, on my 10.6.8 machine, I noticed that
occasionally, the normally zippy tk/tix widget drawing would
suddenly slow way down after XQuartz had been running a while
(often through several sleeps). Again this was a 100x to 1000x
slowdown).
It would only be fixed by a reboot (logout/login restart win server
not enough). After XQuartz 2.7.6 or 2.7.7 (not sure which), the slowdown
never happened again (on 10.6.8). I never figured out what was causing
it then either. There were no system updates in between broken
and fixed.
I won't email you again unless I actually figure
something out :-}
cheers,
marty
On Sun, 30 Nov 2014, Jeremy Huddleston Sequoia wrote:
I wonder if this is related to the xauth timeout because it doesn't know about the new Yosemite launchd socket path. If you launch XQuartz and then do 'DISPLAY=:0 /path/to/program', does it experience the delay. Note that your DISPLAY may not actually be :0, so if that doesn't work, check what DISPLAY the running X server is.
--Jeremy
On Nov 29, 2014, at 22:06, Tom Lane <email@hidden> wrote:
Marty Sereno <email@hidden> writes:
In XQuartz 2.7.7, running on Mac OS X 10.6.8,
the following program (source'd in a wish8.5.12
compiled on 10.6.8) takes about 10 milliseconds to
finish/display:
# display 400 buttons
for {set j 0} {$j < 20} {incr j} {
frame .f$j
pack .f$j -side top
for {set i 0} {$i < 20} {incr i} {
button .f$j.b$i -text asdf
pack .f$j.b$i -side left
}
}
On XQuartz 2.7.7 runnng on Mac OS X 10.10.1,
the same program (whether X11 tcl/tk was
compiled on 10.6.8 or on 10.10.1) takes
about 10 sec to display (1000x slowdown).
Hm ... I see a similar delay if I run this as a script file,
but if I copy/paste it into an interactive wish, it seems to be
about a second or so. Which is still a lot, but the context
makes a difference.
Also, I use exmh (a tcl/tk email handler) constantly, and I've not
noticed any particular slowdown in it with Yosemite. So it's not
true that tk is broken completely. You'll probably need to do some
sleuthing ...
regards, tom lane
_______________________________________________
Do not post admin requests to the list. They will be ignored.
X11-users mailing list (email@hidden)
This email sent to email@hidden
_______________________________________________
Do not post admin requests to the list. They will be ignored.
X11-users mailing list (email@hidden)
This email sent to email@hidden