Occasionally some apps (with load) cause the Accessibility API’s to respond slowly

[ontucker]

After updating to El Capitan, some of my keybindings are extremely slow and I've narrowed it down to the fact that they're doing some operations on the entire window list after calling Window.allWindows(), which now takes > 6 seconds (!) to return a list of windows. If I use Window.visibleWindowsMostRecentFirst() it's much, much faster, even if the result is the same set of windows (no windows were minimized). During this 6 seconds, phoenix is frozen. It makes things pretty unusable.

Here's a sample binding that exhibits the problem:

var blah = api.bind('1', ['alt', 'cmd', 'ctrl', 'shift'], function() {
    api.log("getting visible windows");
    var visWindows = Window.visibleWindowsMostRecentFirst();
    api.log("getting all windows...");
    var allwindows = Window.allWindows();
    api.log("done");
});

[kasper]

@ontucker Hi, I’m sorry to hear that! It would seem you’re still using Phoenix 1.x, which isn’t supported anymore. Phoenix 2 has been rewritten and optimised from the ground up. Would you be able to upgrade? Please note that there are breaking changes in the API, see the Changelog for the differences.

[ontucker]

Haha, well, I'm an idiot. :) It has been a long time since I looked at the project and last I did, I thought it was barely maintained, so I didn't expect it to have changed significantly. Happy to hear it's alive and well, and I'll check out v2. Sorry for the dud report. Feel free to close it.

[kasper]

No worries! I took over the project last summer and I’m committed in keeping it alive since I use Phoenix daily.

[ontucker]

Interestingly, in Phoenix 2 on my system, Window.visibleWindows() is now taking 6 seconds. I'll see if I can debug this and provide more info.

This code:

        Phoenix.log("getting windows");
        var windows = Window.visibleWindows();
        Phoenix.log("got " + windows.length + " windows");

Is producing this output:

2/20/16 5:02:33.178 PM Phoenix[12469]: getting windows
2/20/16 5:02:39.279 PM Phoenix[12469]: got 15 windows

[kasper]

Well that’s certainly interesting, especially since you only have a dozen windows! I will obviously investigate this if you notice anything that I might be able to reproduce or optimise.

First of all, if you haven’t, try to restart your computer. Secondly, this might be related to a single program or window hanging/delaying its response to the Accessibility API. Thirdly, are there any errors from Phoenix in the system log?

[ontucker]

A restart helped, and then I attempted to narrow it down to a specific program by testing after every new thing I launched. One time, the problem returned after launching Atom.app, but that wasn't reproducible, so it may be a red herring. I do see the following error in the system log at the same time, but I also see it at many other times so I'm not sure if it's relevant:

2/22/16 9:55:04.794 AM networkd[198]: -[NETProxyLookup url] invalid URL scheme '4243'

One other datapoint is that when this problem is occurring, Phoenix takes a very long time (nearly a minute) to start up, which is presumably related to it gather info about windows on the system and those APIs it's calling being very slow. I will keep an eye on this and try to provide more info.

[kasper]

@ontucker Thanks for looking into this! The error isn’t related. Presumably this is caused at a lower level which subsequently causes the Accessibility API to be slow in certain circumstances. Unfortunately, I’m not sure if we can do much about it. I’ll close this for now, let me know if you notice something!

[kasper]

@ontucker Okay, I now encountered the hanging launch myself. No idea why this is happening, but obviously there is some root cause. I will try to investigate this.

[kasper]

Unfortunately, I cannot reproduce this issue at all. I’ve only encountered the slow start, but even then there doesn’t seem to be any pattern. I’ve done a code review for the relevant parts and can’t see anything that might cause this. This makes me believe that the call to OS X’s Accessibility API itself might be slow in some situations, which obviously means we cannot do much about this. I’ve leave this open for now if someone finds anything reproducible.

[ontucker]

Seems fair. I was getting it reproducing very regularly when I first reported it, but since then it's been pretty rare. When it happens, a restart of phoenix often clears it up, and a reboot always does. So it's irritating but fairly avoidable and there really isn't much to go on as far as fixing it.

BTW, I've switched from Firefox to Chrome as my primary browser on this machine, and it's possible that that's related to the reduction in this problem. Firefox used to go to lunch on me occasionally for high-single-digits seconds at a time, and I finally got fed up and quit using it. The timing of this problem being significantly lessened and me ditching FF does match up, although obviously this is a pretty unscientific correlation and may mean nothing at all.

[kasper]

Either it’s something that’s not obvious or some app is doing something weird that causes the WindowServer to lag. Maybe even a change or bug in El Capitan. Hard to know. I’ll keep on observing if I see something consistent. I have seen this very rarely, mostly only when running Phoenix from Xcode.

[kasper]

@ontucker I now have a theory… Do you bind to any events in your configuration?

[kasper]

@ontucker Actually, I think you are right. The root cause seems to be an app performing an intensive task or hanging at that specific time. This causes the Accessibility API’s to hang. It seems, we can set a timeout value for these calls, but I’m still trying to figure out specifically how this is happening.

[ontucker]

If you mean using Phoenix.on, then nope, I don't.

[kasper]

Okay, so after some digging around, I think occasionally some apps (with load) cause the Accessibility API’s to simply timeout. This causes the slowness. It’s the responsibility for each app developer to implement most of the Accessibility support for their apps. If something is slow at their end, it unfortunately cascades through the API.

Reducing the timeout would improve this, but as a side effect could result in unsuccessful API calls. This in my opinion is not a good direction to go. Also it’s rather hard to determine what a good timeout rate would be since this could change. Maybe a possible solution is to run some of the tasks in threads?

[ontucker]

Ick. I suppose you could convert those potentially-blocking phoenix APIs to return promises and do their work async. A fairly straightforward conversion but involves a lot of caller changes that would ripple all over user code.

[kasper]

Yes, I don’t really want to do that either and for the most part the low level APIs are sequential by design. It seems the main culprits are in fact apps that don’t have (any) user facing elements, such as Safari’s background workers. So there might be a way to determine these cases.

[kasper]

@ontucker Actually, these might be separate issues. I just noticed that Window.windows() seems to be slow in even normal circumstances and this cascades to the other functions. This obviously needs to be optimised (#100).

[tphalp]

I've experienced this slowness as well. It seems to get worse the longer I go without rebooting my macbook. The last time I experienced this, by coincidence, I needed to restart my machine, and upon reboot, I noticed the window resizing algorithms I use were as snappy as could be.

But now, a couple of weeks later, they take several seconds to complete, upwards of 10 - 15 seconds most of the time.

I'm on Phoenix 2.1.1, and OS X 10.11.5.

[kasper]

@tphalp By any chance, do you have a browser open with many tabs?

[tphalp]

I usually do. Right now I have Safari open with 9 tabs, and Chrome open with 4, and I'm experiencing the slowness. Does that count as a lot?

UPDATE: I just closed both browsers, and tried one of my hotkeys again. I'm still experiencing about 10 - 15 second delays in moving windows.

[kasper]

@tphalp Indeed that’s not a lot. Did you close the windows or quit the apps completely? What I’ve noticed occasionally is that even one Safari tab (background worker) can drigger this, but it’s never reproducible. I haven’t found any other apps that would signal the same effects.

If quitting the browsers completely doesn’t work, when you encounter this again, would you be able to try and restart Phoenix and see if this is enough to fix the issue?

I always shut down my Mac, but even then I sometimes run into this issue, but it’s still rare. I would like to know what app (if any) causes this in the most minimal steps…

[tphalp]

I closed both browsers completely.

I'll try what you suggested and post back with the results. Thanks.

[tphalp]

I initially read your message incorrectly. I have tried restarting Phoenix, to no avail--unless I also restart my machine.

The strange thing is, I've been using Phoenix for a couple of years, and it only recently started doing this. Not sure if it was a change to OS X or Phoenix that introduced this behavior.

[kasper]

@tphalp I’m not sure either, though this was first reported as a behaviour introduced in the older versions previous to the refactor and presuming launching Phoenix again doesn’t fix this, I would assume this is caused by some lower level behaviour. This is obviously undesirable, so once this gets a root cause, we can hopefully fix this.

[kasper]

The issue related to Phoenix starting up slowly should be fixed in #114 and will be released in 2.2.

[kasper]

This should now be fixed! 😄 Indeed the cause is that when an app is under load it will cause the Accessibility API for the element of the app to not respond or to be extremely slow. As many of you have noticed, the default timeout seems to be around 6 seconds. As the API is blocking, all other Accessibility API calls for any other apps will be blocked until the previous completes or timeouts.

I’ve now set the timeout for all elements to be 500 ms (could probably be even lower, but this is a safe bet). Any call to the Accessibility API will not exceed 500 ms. Apps that are responding should be able to answer within this time. Those apps that are under load will fail faster. Therefor every API will now respond within ~0,5 seconds. Note that if you are for example accessing all windows with Window.all() the result will/may omit any windows for apps that are under load until the app is again responsive.