windowfilter.focusWindow* methods hang for ~10s

[snarfed]

Hi! First off, thank you all for building and maintaining Hammerspon. It's great! I couldn't live without it.

I've been happily using v0.9.100 with the same unchanged config for a while now. Sometime in the past few days, the windowfilter focusWindow* methods started hanging for 5-10s every time they're called. I'm not sure what suddenly triggered this, but my best guess is that I upgraded to macOS 14.1.2 (23B92) from 14.1.1.

Specifically, this in the console reproduces the hang for me most times I run it and there's a window to the east:

hs.window.filter.default:focusWindowEast(nil, true, true)

Doesn't seem to be CPU or memory, Hammerspoon's memory footprint is only 20-30MB when this happens, and it's not busy-waiting, it's at <1% CPU usage throughout the hang. I assume it's waiting on I/O from something, but I don't know what. Are there any known issues with macOS 14.1.2? Could any window configuration or apps I have open cause this?

Thank you in advance!

[cmsj]

If you open the Hammerspoon console and run:

hs.window._timed_allWindows()

you'll almost certainly see that one application is taking multiple seconds to respond. Either one of your apps added a new helper which doesn't implement accessibility APIs, or one of your apps has gotten internally stuck and has stopped responding to accessibility calls. The latter is a thing that happens from time to time and either restarting that app, or rebooting, clear it up.

[snarfed]

Ah, interesting! Thanks for the tip. This is what I see when I run it a couple times in a row, and then again many hours later:

> hs.window._timed_allWindows()
2023-12-23 08:34:42: took 0.09s for com.apple.quicklook.QuickLookUIService
2023-12-23 08:34:42: took 12.01s for com.apple.WebKit.WebContent
2023-12-23 08:34:42: took 0.06s for N/A
2023-12-23 08:34:42: took 0.09s for com.apple.ViewBridgeAuxiliary
2023-12-23 08:34:42: took 0.05s for com.apple.PressAndHold
table: 0x600002d6d140

> hs.window._timed_allWindows()
2023-12-23 08:35:05: took 12.01s for com.apple.WebKit.WebContent
table: 0x600002d6c040

> hs.window._timed_allWindows()
2023-12-23 17:39:09: took 12.01s for com.apple.WebKit.WebContent
table: 0x600002c931c0

I don't use Safari, so I'm guessing com.apple.WebKit.WebContent is some Electron or similar webview-wrapped app? Also suspicious that it takes exactly 12.01s every time.

I tried rebooting yesterday, and that fixed it for a few minutes but then it started hanging again. I'll try again now.

[snarfed]

Turns out rebooting doesn't fix it after all. I've tried twice now, and it still happens immediately on startup. I may have misremembered it working for a few minutes the first time I tried.

Any other debugging ideas?

[cmsj]

Huh, that's really odd, we're supposed to ignore WebContent because it's known to respond slowly: https://github.com/Hammerspoon/hammerspoon/blob/master/extensions/window/window.lua#L85

[snarfed]

Is this related to #2943?

Also maybe related: #3374, #2970, #2923, #2162

(Apologies for the spam; I'm idly poking at this here and there since I miss my hs.window.filter operations 😁)

[snarfed]

As another data point, I rebooted yesterday evening, and that did indeed fix the problem again...for a while, like before. It was back when I opened the computer again this morning though. I didn't start any new apps between it working and breaking, but the computer did sleep overnight. Maybe that's related?

[Rhys-T]

Huh, that's really odd, we're supposed to ignore WebContent because it's known to respond slowly: master/extensions/window/window.lua#L85

I'm not sure whether this is relevant or not, but looking at that code, it looks like SKIP_APPS is only used by the normal allWindows, not _timed_allWindows, so the fact that it was printing com.apple.WebKit.WebContent doesn't necessarily mean that allWindows is failing to ignore it properly… although the fact that it's not showing any other apps as being that slow is a bit suspicious.

[snarfed]

Hmm! If it helps, I tried _timed_allWindows after reboot when the hang wasn't happening, and com.apple.WebKit.WebContent didn't show up. After the hangs restarted though, it was back and taking exactly 12.01s again.

[smackesey]

FWIW I have been using Hammerspoon for ~5 years and have never been able to get window functionality to work consistently without lag, even having added a bunch of items to hs.window.filter.ignoreAlways. Even if I get it working smoothly for a little bit, it inevitably becomes unusably slow soon again and I have to do more detective work.

What I have ended up doing, which has worked well, is building a thin Lua API on top of yabai. You can then just call yabai, which is super-fast, from HS.

Example for anyone interested in a similar approach-- credit to @asmagill and @cmsj for helping out with the taskExec() code some years ago:

local m = {}

local function taskExec(cmd)
  local parts = m.split(cmd, " ")
  local path = parts[1]
  local args = m.slice(parts, 2)
  local tsStart = os.clock()
  print(string.format("EXECUTING COMMAND: %s", cmd))
  local taskIsDone = false
  local output
  if not coroutine.isyieldable() then
    error("this function cannot be invoked on the main Lua thread")
  end
  local task = hs.task.new(path, function(_, stdOut, stdErr)
    output = stdOut
    taskIsDone = true
  end, args)
  task:start()
  while not taskIsDone do
    -- print('YIELD')
    coroutine.applicationYield()
  end
  local tsEnd = os.clock()
  print(string.format("FINISHED COMMAND: (%.3f sec) %s", tsEnd - tsStart, cmd))
  return output
end

function m.command(cmd)
  local fullCmd = string.format('/opt/homebrew/bin/yabai -m %s', cmd)
  return taskExec(fullCmd)
end

function m.getWindows()
  local windows = m.command('query --windows')
  return hs.json.decode(windows)
end

function m.focusWindow(windowId)
  m.command(string.format('window --focus %d', windowId))
end

function m.minimizeWindow(windowId)
  m.command(string.format('window %d --minimize', windowId))
end

-- ...

return m

[muescha]

I have the same delay with Webkit - and the same problem with a delay in:

• hs.window.filter.new(nil) - first subscribe: 30s delay #3670 hs.window.filter.new(nil) - first subscribe: 30s delay

> hs.window._timed_allWindows()
2024-08-15 19:33:09: took 0.06s for 2BUA8C4S2C.com.agilebits.onepassword4-helper
2024-08-15 19:33:09: took 0.05s for com.apple.dock
2024-08-15 19:33:09: took 0.12s for com.apple.appkit.xpc.openAndSavePanelService
2024-08-15 19:33:09: took 0.05s for mo.com.sleeplessmind.Wooshy
2024-08-15 19:33:09: took 0.07s for com.apple.HeadphoneSettings
2024-08-15 19:33:09: took 0.09s for com.apple.Family-Settings.extension
2024-08-15 19:33:09: took 0.09s for com.agilebits.onepassword4
2024-08-15 19:33:09: took 0.14s for org.pqrs.Karabiner-Elements.Settings
2024-08-15 19:33:09: took 0.08s for com.apple.wifi.WiFiAgent
2024-08-15 19:33:09: took 0.09s for com.apple.systempreferences.AppleIDSettings
2024-08-15 19:33:09: took 0.07s for N/A
2024-08-15 19:33:09: took 0.06s for com.apple.PressAndHold
2024-08-15 19:33:09: took 0.07s for com.apple.FollowUpSettings.FollowUpSettingsExtension
2024-08-15 19:33:09: took 0.06s for com.apple.NetworkExtensionSettingsUI.NESettingsUIExtension
2024-08-15 19:33:09: took 33.15s for com.apple.WebKit.WebContent
table: 0x60000268a800

> hs.window._timed_allWindows()
2024-08-15 19:35:06: took 24.03s for com.apple.WebKit.WebContent
table: 0x6000026f4240

> hs.window._timed_allWindows()
2024-08-15 19:38:38: took 24.04s for com.apple.WebKit.WebContent
table: 0x6000026cd480
```lua