Beachballin' (~5s) in LuaSkin when activating `hs.window.filter:subscribe()` during init

[luckman212]

I'm not 100% sure how to document this one properly, so I'll just put down as much as I can here, and I hope that you guys can ask for any further details—I am happy to provide them, test any fixes or basically anything else I can do to help trace this.

Issue: I've been experiencing a problem with Beachballing in Hammerspoon's Main thread for anywhere from 5-10 seconds during config loads (also happens during reloads).

Can't capture a screen recording because no screencapture apps I've tried are able to record the beachball when it's occuring. So I recorded a short video with my phone that shows it in action: IMG_1637b.mov

Findings: I narrowed the problem down to hs.window.filter:subscribe(). It doesn't happen every time, but I'd say about 30-40% of the time. This happens even with just the bare bones init.lua config here:

wf = hs.window.filter.new('TextEdit')
wf:subscribe('windowFocused', function()
  hs.alert('TextEdit active!')
end)

I ran it through Time Profiler (Instruments.app with dSYMs loaded from the github repo). Here are a couple of screenshots from that, again I don't know if this is at all helpful. I don't know how to interpret this.

Test environment

• this was repeatable on multiple computers running both 10.15.7 and 11.0.1
• HS "official" 0.9.81 as well as master branch and A-Ron's new filterFocusDirections fork
• not related to any 3rd party spoons, as I was able to repro it using a practically empty init.lua as given above.

[asmagill]

hs.window.filter is known to be somewhat slow under many conditions... it's spawning a lot of watchers to track all applications and windows as well as space changes, and was written at a time before we had a module with direct access to the accessibility elements for applications and before proper coroutine support, so there were some compromises and work arounds made.

In addition, the original author seems to be unavailable, so it's taking some time to fully understand some of the work-arounds that were originally added, especially for situations that no longer apply (e.g. the issue with tracking the pid value as a way to determine when an application was fully launched and responsive -- this is no longer an issue as the pid is captured at userdata creation now, so it always exists if Hammerspoon is even indirectly aware of the application/window).

I too noticed slowdowns each time I worked with the samples I used to test the fork you refer to above (I usually don't have a window filter running -- it just hasn't been necessary for the types of things I routinely use Hammerspoon for, just lucky I guess  😜)

I've been mulling over a complete rewrite of the module using some of the more powerful modules we have available now to see what can be sped up, changed, removed as no longer needed, or at the very least made more responsive (e.g. a half second delay updating an internal list of active windows would probably seldom be noticed as long as it didn't lock up Hammerspoon for that half second). However, it's going to take some time to get to -- it's going to require digging into the module even deeper than I have so far and probably soliciting some examples of the module in real use, since I don't use it that often myself -- your stripped down example above is exactly the kind of thing that will help me when I get to the point of needing such tests.

And if you ask @latenitefilms, I'm already behind in vetting some additions he wants to make, so... I will get to this (unless someone else wants to tackle it first?) but probably not for a couple of weeks.

[luckman212]

@asmagill Thanks for this really detailed writeup. No rush here, I'm just happy you were able to reproduce this - thought it was another "just me" problem.

[luckman212]

Just wanted to add: I'm seeing this beachball when calling hs.application as well. Seems like hs.window gets lazy-loaded by hs.application, so I guess this is probably the same underlying bug. Anyway, I created this test function to make it easier to reproduce.

• save as beachball.lua
• add require("beachball") to your init.lua
• to test, run e.g. bb(5) from console (# of loops)

function epochtime()
  local et = os.time(os.date("!*t"))
  return et
end

function bb(n)
  local e
  local a
  local st
  local loop_start_time
  st = epochtime()
  if (n == nil or n < 1) then
    print("requires positive integer as a parameter")
    return
  end
  print("running " .. n .. " loops")
  for c=1,n do
    loop_start_time = epochtime()
    a = hs.application("com.apple.Terminal")
    e = epochtime() - loop_start_time
    print("loop: " .. c .. " elapsed: " .. e)
    if e > 1 then
      print(string.format("we just beachballed in loop %d for %.0f seconds!", c, e))
      break
    end
    os.execute("sleep 0.1")
  end
  print("end of run, total elapsed: " .. epochtime() - st) 
end

hs.application.enableSpotlightForNameSearches(true)

[asmagill]

I haven't had a chance to try out your code here to examine it fully, but I do note that you include hs.application.enableSpotlightForNameSearches(true) in what I'm assuming is a snippit of your init.lua (or similar) file... per the documentation notes at http://www.hammerspoon.org/docs/hs.application.html#enableSpotlightForNameSearches this persists through reloads/relaunches and issuing it each time Hammerspoon loads causes it to purge the database and rebuild it... this could certainly be contributing to slow reload times.

When I added the spotlight support to hs.application, it was with the expectation that you'd enable/disable it once in your console, not in your config files, and then basically forget about it. I guess I need to make that more clear in the documentation, or come up with another way to trigger a cache purge/rebuild... I'll give it some thought.

[luckman212]

The hs.application.enableSpotlightForNameSearches isn't actually needed here, I just included it because without that, it was cluttering the console with this message:

Some applications have alternate names which can also be checked if you enable Spotlight support with hs.application.enableSpotlightForNameSearches(true).

I actually don't use that option in my config, and this beachball test is fine without it. 🙂

[cmsj]

@luckman212 how often do you run into this? On one of the times you do hit it, could you capture the output of hs.inspect(hs.window._timed_allWindows()) please?

[luckman212]

thanks @cmsj - I can replicate it consistently, so I'm just avoid using these methods for now.

Even just running the hs.window._timed_allWindows() you asked for gets me a beachball about 80% of the time.

Here's a sample output. I note that Alfred's main window (com.runningwithcrayons.Alfred) spun for ~5 seconds here. But, to test if there was any pattern to that, I quit Alfred completely and re-ran the command. This just caused the spin to show up in another process (TimingHelper) After quitting that, the delay migrated to Bartender. Rinse and repeat.

> hs.inspect(hs.window._timed_allWindows())
2021-02-16 09:34:34: took 5.11s for com.runningwithcrayons.Alfred
2021-02-16 09:34:34: took 0.69s for N/A
{
  ["N/A"] = 0.69000458717346,
  ["build.bru.MacGladys"] = 0.00035190582275391,
  ["com.ScooterSoftware.BeyondCompare.BCFinder"] = 0.0053818225860596,
  ["com.adobe.AdobeIPCBroker"] = 0.0020618438720703,
  ["com.adobe.CCLibrary"] = 0.00016093254089355,
  ["com.adobe.CCXProcess"] = 0.00014185905456543,
  ["com.adobe.acc.AdobeDesktopService"] = 0.0025670528411865,
  ["com.adobe.acc.ads.helper"] = 0.0024001598358154,
  ["com.adobe.accmac"] = 0.0020639896392822,
  ["com.apple.AirPlayUIAgent"] = 0.0022320747375488,
  ["com.apple.AppSSOAgent"] = 0.00049901008605957,
  ["com.apple.CalendarAgent"] = 0.00013399124145508,
  ["com.apple.CalendarNotification.CalNCService"] = 0.00022006034851074,
  ["com.apple.CoreLocationAgent"] = 0.00072193145751953,
  ["com.apple.CoreSimulator.CoreSimulatorService"] = 0.0040490627288818,
  ["com.apple.CoreSimulator.SimulatorTrampoline"] = 0.0035538673400879,
  ["com.apple.FolderActionsDispatcher"] = 0.0041048526763916,
  ["com.apple.LocalAuthentication.UIAgent"] = 0.00020813941955566,
  ["com.apple.MobileDeviceUpdater"] = 0.0022058486938477,
  ["com.apple.NowPlayingTouchUI"] = 0.0028448104858398,
  ["com.apple.OSDUIHelper"] = 0.001986026763916,
  ["com.apple.PressAndHold"] = 0.012943029403687,
  ["com.apple.RemoteDesktopAgent"] = 0.00020289421081543,
  ["com.apple.SSMenuAgent"] = 0.00038409233093262,
  ["com.apple.SoftwareUpdateNotificationManager"] = 0.00046300888061523,
  ["com.apple.Spotlight"] = 0.00069212913513184,
  ["com.apple.TextInputMenuAgent"] = 0.00036787986755371,
  ["com.apple.TextInputSwitcher"] = 0.00044393539428711,
  ["com.apple.UIKitSystemApp"] = 0.00027894973754883,
  ["com.apple.UserNotificationCenter"] = 0.00028800964355469,
  ["com.apple.ViewBridgeAuxiliary"] = 0.009958028793335,
  ["com.apple.accessibility.AXVisualSupportAgent"] = 0.00047397613525391,
  ["com.apple.appkit.xpc.openAndSavePanelService"] = 0.028470993041992,
  ["com.apple.automator.xpc.workflowServiceRunner"] = 0.0022780895233154,
  ["com.apple.controlcenter"] = 0.00040483474731445,
  ["com.apple.controlstrip"] = 0.0055668354034424,
  ["com.apple.coreservices.uiagent"] = 0.0059809684753418,
  ["com.apple.ctkbind"] = 0.00056886672973633,
  ["com.apple.dock"] = 0.0020020008087158,
  ["com.apple.dock.external.extra.x86_64"] = 0.0021572113037109,
  ["com.apple.dock.extra"] = 0.00041294097900391,
  ["com.apple.dock.helper"] = 0.0020210742950439,
  ["com.apple.finder"] = 0.0014309883117676,
  ["com.apple.iCal.CalendarNotificationContentExtention-OSX"] = 0.0056710243225098,
  ["com.apple.inputmethod.EmojiFunctionRowItem"] = 0.0021889209747314,
  ["com.apple.locationmenu"] = 0.00043487548828125,
  ["com.apple.loginwindow"] = 0.00041818618774414,
  ["com.apple.nbagent"] = 0.0022308826446533,
  ["com.apple.notificationcenterui"] = 0.00033998489379883,
  ["com.apple.quicklook.QuickLookUIService"] = 0.023781538009644,
  ["com.apple.security.Keychain-Circle-Notification"] = 0.0021071434020996,
  ["com.apple.storeuid"] = 0.019598960876465,
  ["com.apple.studentd"] = 0.0059809684753418,
  ["com.apple.systemuiserver"] = 0.0025711059570312,
  ["com.apple.talagent"] = 0.00043201446533203,
  ["com.apple.wifi.WiFiAgent"] = 0.0023891925811768,
  ["com.aptonic.Dropzone-setapp"] = 0.00036001205444336,
  ["com.brettterpstra.marked2"] = 0.00081896781921387,
  ["com.dejal.timeout.free"] = 0.00018405914306641,
  ["com.disc-soft.DAEMONToolsLite.ContextMenu"] = 0.0028507709503174,
  ["com.econtechnologies.backgrounder.chronosync"] = 0.00033283233642578,
  ["com.fujitsu.pfu.SSMenuBar"] = 0.0022821426391602,
  ["com.fujitsu.pfu.ScanSnap.AOUMonitor"] = 0.00042891502380371,
  ["com.fujitsu.pfu.SshImgMonitor"] = 0.0024170875549316,
  ["com.fujitsu.pfu.SshImgProc"] = 0.0020890235900879,
  ["com.fujitsu.pfu.SshRegister"] = 0.0030910968780518,
  ["com.fujitsu.pfu.SshResident"] = 0.0042800903320312,
  ["com.fujitsu.pfu.SshSCloudWatch"] = 0.00042486190795898,
  ["com.getcleanshot.app-setapp"] = 0.00014805793762207,
  ["com.github.xor-gate.syncthing-macosx"] = 0.0020389556884766,
  ["com.google.Chrome"] = 0.0018019676208496,
  ["com.googlecode.iterm2"] = 0.0007481575012207,
  ["com.hnc.Discord"] = 0.00078201293945312,
  ["com.knurling.ServiceStation.Attendant"] = 0.00044798851013184,
  ["com.knurling.ServiceStation.FinderSync"] = 0.0024681091308594,
  ["com.macitbetter.betterzip.findersyncextension"] = 0.0025060176849365,
  ["com.mowglii.ItsycalApp"] = 0.00034999847412109,
  ["com.patricebecker.FastFace"] = 0.002251148223877,
  ["com.robinlu.mac.Tooth-Fairy"] = 0.00016307830810547,
  ["com.runningwithcrayons.Alfred"] = 5.1102659702301,
  ["com.runningwithcrayons.Alfred-Preferences"] = 0.00099301338195801,
  ["com.setapp.DesktopClient.SetappAgent"] = 0.00035285949707031,
  ["com.sublimetext.3"] = 0.00073099136352539,
  ["com.surteesstudios.Bartender-setapp"] = 0.00021696090698242,
  ["com.theron.UnnaturalScrollWheels"] = 0.00033998489379883,
  ["com.valerijs.boguckis.TextSniper-setapp"] = 0.00041294097900391,
  ["com.viscosityvpn.Viscosity"] = 0.0024521350860596,
  ["eu.exelban.Stats"] = 0.0022878646850586,
  ["info.eurocomp.Timing-setapp.TimingHelper"] = 0.0021169185638428,
  ["info.eurocomp.TimingHelper.InfoExtractorService"] = 0.00018501281738281,
  ["io.fadel.Batteries-setapp.Helper"] = 0.0003049373626709,
  ["org.gpgtools.updater"] = 0.00036907196044922,
  ["org.hammerspoon.Hammerspoon"] = 0.00077104568481445,
  ["pl.maketheweb.pixelsnap2-setapp"] = 0.00035595893859863
}

(quit Alfred)

> hs.inspect(hs.window._timed_allWindows())
2021-02-16 09:41:13: took 1.97s for info.eurocomp.Timing-setapp.TimingHelper
2021-02-16 09:41:13: took 0.39s for N/A
{...

(quit Timing.app)

> hs.inspect(hs.window._timed_allWindows())
2021-02-16 09:42:24: took 5.98s for com.surteesstudios.Bartender-setapp
2021-02-16 09:42:24: took 0.42s for N/A
{...

[cmsj]

Ok, well at least we know what the beachballing is being caused by, but it's kinda weird that there's always a slow responder, and different ones become slow as you quit them.

Does this start happening immediately after a fresh boot? Usually when there's a slow responder in that list it's either a weird process that just doesn't respond to accessibility events, which we have to blacklist, or it's a program that's gotten into a weird state.

[luckman212]

Ok, I just ran some additional tests on a freshly booted 11.2 system.

The deadlock is still there on fresh boot. But, I found out that it only occurs when one or more of the following 3 apps are running:

App	Bundle ID	Version
Alfred 4	com.runningwithcrayons.Alfred	4.3.2.1221
Bartender 4	com.surteesstudios.Bartender-setapp	4.0.36
Timing Tracker/Helper	info.eurocomp.Timing-setapp.TimingHelper	2021.2

~~Once I quit all of these, hs.inspect(hs.window._timed_allWindows()) runs all day in <0.5s~~.

edit: that seems wrong. see below.

[luckman212]

Ok, well my last comment may not be fully accurate. Even after quitting all 3 of those apps, I can still generate 1-3s spinlocks. Right now it's coming from something called "N/A". That's helpful, hah.

> hs.inspect(hs.window._timed_allWindows())
2021-02-18 19:37:44: took 1.71s for N/A
{
  ["N/A"] = 1.7142793083191,

I had a thought of trying to use hs.window.filter.ignoreAlways to just blacklist these problematic apps, but it doesn't seem to have the desired effect. Even after this...

hs.window.filter.ignoreAlways[Alfred] = true
hs.window.filter.ignoreAlways[Bartendeer 4] = true
hs.window.filter.ignoreAlways[Timing Tracker] = true

It had no effect on the beachballing. Not quite sure where to go from here. ☹   Would any spindumps or Time Profiles from Instruments.app help?

[luckman212]

I saw this post on AskDifferent the other day and it reminded me of this issue. I wonder if it's related? If so, there's a chance it's been fixed in 12.2.

[crisidev]

I am experiencing the same and for me the beachballing is caused by

["com.apple.WebKit.WebContent"] = 4.5058789253235

which, as you can see, takes around 4.5 seconds.

This webkit process is a child of MS outlook and, of course, if I restart Outlook, everything goes back to normality.