Keyboard input lag when running key listeners on macOS Ventura

[smackesey]

I have listeners for all key events that I've been using for close to 6 years in Hammerspoon. In all those years, I never noticed any lag at all from having these listeners running. I upgraded to macOS ventura a few days ago and now there is a very noticeable keyboard input lag while typing when I run Hammerspoon.

[justintanner]

I'm seeing the same lag using code like:

hotkeyModal:bind(mods, key, nil, pressKey(), nil, nil)
... and 
hs.eventtap.event.newKeyEvent(mods, key, true):post()
hs.eventtap.event.newKeyEvent(mods, key, false):post()

[smackesey]

Much credit to the developers for building/maintaining such a great tool, but now I'm worried for it's future-- I've seen Hammerspoon is not being updated of late, and this issue basically renders a key feature of Hammerspoon unusable-- surprised it wasn't caught in Ventura beta.

I need to figure out whether to stick with Hammerspoon or migrate to something else-- @cmsj @asmagill do you have any idea what the problem here is and is it likely to be addressed in a Hammerspoon release anytime soon? Thanks!

[cmsj]

@smackesey what kind of key listeners are you using? Are we talking hs.hotkey or hs.eventtap?

[smackesey]

@cmsj thanks for responding-- hs.eventtap.

FWIW I can't be sure but it also seems like the lag gets worse over time the longer HS is running.

[cmsj]

hmm, interesting. I don't use hs.eventtap a huge amount, but I do have one very specific use of it - the AllBrightness spoon, which I use many times a day and it's near-instant.

@latenitefilms have you seen anything like this? I guess you're using hs.eventtap more than I am?

[latenitefilms]

Ummm... I'm not personally using macOS Ventura yet - but we have lots of CommandPost users that are, and no ones mentioned anything... yet. But yes, we use eventtaps a LOT in CommandPost.

Most of the time when people report issues with eventtaps lagging, it turns out to be Hammerspoon is waiting on something else that's working a bit "deeper", like BetterTouchTool, Keyboard Maestro, etc.

@smackesey - Are you using any other apps that might also be using eventtaps?

[justintanner]

Using the code above I'm seeing lag in the range of seconds, switching my script to Karabiner, I have zero lag.

Hope that helps.

[latenitefilms]

@justintanner - As far as I can tell, your code above isn't actually using a hs.eventtap for listening - you're just using hs.eventtap.event to generate a virtual key press, so I think maybe your issue is different than @smackesey's? AFAIK, hs.hotkey doesn't actually use hs.eventtap internally - it uses a different macOS API.

@smackesey - Are you able to share your Lua config? Have you tried adding some debugging code to the start an end of your hs.eventtap callback function to see if it's actually something WITHIN that Lua function that's slowing things down (as opposed to the eventtap itself)?

[smackesey]

Alright I did some investigation and learned some useful information. Here is the code of interest:

  self.characterKeyTap = hs.eventtap.new({hs.eventtap.event.types['keyDown']}, function (event)
    self.log:debug('characterKeyTap start')
    self.flagSwitch = false
    local rawChar = event:getCharacters(true)
    local char = util.normalizeChar(self.state.shift and string.lower(rawChar) or rawChar)
    local code = event:getKeyCode()
    self.log:debug('char: %s code: %d', char, code)
    if self.cache.current.passAll or self.cache.current.passCodes[code] then
      self.log:debug('passing')
      return false
    else
      self.log:debug('consuming')
      local consumed = self.master.SYMBOL_TRACKER:consume{ symbol=char }
      return consumed
    end
  end)

(1) I confirmed that the problem grows worse the longer HS is running. The above function fires on every keystroke. I tracked the average amount of time for this function to execute in blocks of 10 keystrokes. This amount of time increased roughly linearly. For the first 10 keystrokes after starting hammerspoon, the average time was approximately 1ms. By the time I reached 3300 keystrokes, the average time was ~150ms (meaning ~150ms keyboard latency lag).

(2) I performed the same procedure more granularly to see if I could determine what component of the function was slowing it down. I measured event:getCharacters, event:getKeyCode, and util.normalizeChar. There was no increase in any of them.

(3) This left logging. My code generates a ton of log messages (many of which are not shown here). I'd also noticed that other HS functionality (which was alos generating log messages) was also slowing down. So I turned off logging (raised level to info) and found this basically eliminated the problem.

So looks like something has changed in how logging is happening-- the time required to log a message seems to be growing roughly linearly in the size of the HS log (my log object above just massages the input and calls print). I never had this problem prior to Ventura.

[latenitefilms]

Interesting! Is your debug code just been written to the Console, or are you also writing it to disk using some other method?

[latenitefilms]

Could you try using hs.logger instead of just print and see if it makes any difference?

[smackesey]

Is your debug code just been written to the Console, or are you also writing it to disk using some other method?

Just to the console (I'm 90% sure...-- set this up a long time ago)

Could you try using hs.logger instead of just print and see if it makes any difference?

Tried it, behavior is identical.

[latenitefilms]

Weird. Can you share your logging code just to be sure?

If you just trigger print in a loop does the loop eventually get slower?

[smackesey]

If you just trigger print in a loop does the loop eventually get slower?

Yes-- I just put this at the start of my HS config and restarted HS:

local LINE = 'abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789'

local times = {}

for i = 1, 1000 do
  if i % 100 == 0 then
    local start = os.clock()
    print(LINE)
    times[i] = os.clock() - start
  else
    print(LINE)
  end
end

print(hs.inspect(times))

And here are the results, which square with what I was observing from my logging:

2022-11-03 14:14:49: {
  [100] = 0.000554,
  [200] = 0.000777,
  [300] = 0.00104,
  [400] = 0.001284,
  [500] = 0.0015660000000001,
  [600] = 0.0018090000000001,
  [700] = 0.002119,
  [800] = 0.002435,
  [900] = 0.002942,
  [1000] = 0.0030910000000002
}

[latenitefilms]

Legend, thanks! @cmsj might have some better ideas, but I'm guessing it's not print that's the root cause, I'm guessing something has changed in the way Xcode is handling the view for the Console. It's entirely possible that just build Hammerspoon with the latest Xcode build might fix?

[cmsj]

Thanks @smackesey for the neat little reproducer. I'll play with it and see what I can find. Wild initial guess - console scrollback might have a poor algorithm choice in it somewhere.

[cmsj]

Hrm, I'm not seeing the same thing. I even bumped it up to 5000 lines and this was a second consecutive run:

2022-11-04 13:18:06: {
  [100] = 0.00031900000000018,
  [200] = 0.00031800000000004,
  [300] = 0.00031200000000009,
  [400] = 0.00034200000000073,
  [500] = 0.00031599999999976,
  [600] = 0.000354999999999,
  [700] = 0.00030499999999911,
  [800] = 0.00031300000000023,
  [900] = 0.00031200000000098,
  [1000] = 0.00031399999999948,
  [1100] = 0.00032099999999957,
  [1200] = 0.00034499999999937,
  [1300] = 0.00032000000000032,
  [1400] = 0.00035399999999974,
  [1500] = 0.00032100000000135,
  [1600] = 0.00030800000000042,
  [1700] = 0.00033700000000003,
  [1800] = 0.00031399999999948,
  [1900] = 0.00030499999999911,
  [2000] = 0.00032700000000041,
  [2100] = 0.00032500000000013,
  [2200] = 0.00032799999999966,
  [2300] = 0.00036400000000114,
  [2400] = 0.00031499999999873,
  [2500] = 0.00031399999999948,
  [2600] = 0.0003239999999991,
  [2700] = 0.00032900000000069,
  [2800] = 0.00031800000000004,
  [2900] = 0.00032500000000013,
  [3000] = 0.00033099999999919,
  [3100] = 0.00032099999999957,
  [3200] = 0.00031800000000004,
  [3300] = 0.00034099999999881,
  [3400] = 0.00035000000000096,
  [3500] = 0.00031399999999948,
  [3600] = 0.00031500000000051,
  [3700] = 0.00031599999999976,
  [3800] = 0.0003119999999992,
  [3900] = 0.0003119999999992,
  [4000] = 0.00035899999999955,
  [4100] = 0.00033999999999956,
  [4200] = 0.00032099999999957,
  [4300] = 0.00030199999999958,
  [4400] = 0.00030999999999892,
  [4500] = 0.00030699999999939,
  [4600] = 0.00032500000000013,
  [4700] = 0.00032900000000069,
  [4800] = 0.00031899999999929,
  [4900] = 0.00030199999999958,
  [5000] = 0.00030699999999939
}

[smackesey]

@cmsj Interesting-- just to confirm, you're running HS Version 0.9.97 (6267) on macOS Ventura 13.0?

[cmsj]

yup

[smackesey]

Not sure if this would make a difference, but I'm on a Mac Studio M1.

[smackesey]

Would be useful for some others to try to repro the problem and see if they get @cmsj results or mine-- all you have to do is paste the code block at the beginning of your HS config file, restart HS, and see what table is printed. @latenitefilms @justintanner?

[dafalcon]

I ran the test a few different ways:

From a blank init.lua and a full restart of Hammerspoon:

{
  [100] = 0.002263,
  [200] = 0.001322,
  [300] = 0.0021680000000001,
  [400] = 0.002758,
  [500] = 0.0034970000000001,
  [600] = 0.0038819999999999,
  [700] = 0.0045459999999999,
  [800] = 0.0049350000000001,
  [900] = 0.0054660000000002,
  [1000] = 0.0057849999999999
}

About 30s later I hit Reload Config on the Hammerspoon context menu:

{
  [100] = 0.0063519999999997,
  [200] = 0.0066369999999996,
  [300] = 0.0072489999999998,
  [400] = 0.0078839999999998,
  [500] = 0.010009,
  [600] = 0.0086509999999986,
  [700] = 0.0089399999999991,
  [800] = 0.010007,
  [900] = 0.010524,
  [1000] = 0.015183
}

I also ran it after I had been experiencing noticeable lag from my normal Hammerspoon config - I have a pathwatcher that calls hs.reload when it detects changes in my init files, so I pasted the snippet in and saved the file to trigger a reload:

{
  [100] = 0.032866999999996,
  [200] = 0.040362999999999,
  [300] = 0.038044999999997,
  [400] = 0.036779999999993,
  [500] = 0.036756999999994,
  [600] = 0.038983999999999,
  [700] = 0.040357999999998,
  [800] = 0.036335000000008,
  [900] = 0.035603000000009,
  [1000] = 0.044919999999991
}

On that last run Hammerspoon was locked up and at 100% cpu for about 40 seconds. I'm on a 2019 Intel MacBook Pro running Ventura 13.0 and Hammerspoon 0.9.97 (6267).

[smackesey]

Thanks @dafalcon-- looks like your results are broadly consistent with mine.

Your last trial is about an order of magnitude worse than the preceding ones. If the issue is logging, that would suggest that the performance disparity is because the log had grown a lot larger by the time you ran the last trial. Do you recall if that's correct?

[dafalcon]

I didn't check to see how large the log was after the last trial, but I do log a fair amount during normal operation so it would make sense.

[nmlc]

Have the same issue.

What I've noticed is that it becomes slower and slower over time and restart of the application helps. As if there is some kind of a leak in place.

macOS Ventura, air m1, hamerspoon 0.9.97

[smackesey]

@nmlc Can you post a result from the test snippet?

[nmlc]

@smackesey I ran the test two times.

First one without restarting the app (app was running for multiple days), just by reloading config:

{
  [100] = 0.011839000000009,
  [200] = 0.012060000000019,
  [300] = 0.012291999999889,
  [400] = 0.012782000000016,
  [500] = 0.013776000000007,
  [600] = 0.013469000000214,
  [700] = 0.014112000000068,
  [800] = 0.016315999999961,
  [900] = 0.014859999999999,
  [1000] = 0.015161000000035
}

Second one right after restarting the app:

{
  [100] = 0.00042,
  [200] = 0.00064700000000001,
  [300] = 0.00089899999999998,
  [400] = 0.001153,
  [500] = 0.001439,
  [600] = 0.001669,
  [700] = 0.0019980000000001,
  [800] = 0.002405,
  [900] = 0.0025629999999999,
  [1000] = 0.002888
}

[rafaelliu]

Also noticing this, also gets worst with time and restarting helps. Previous HammerSpoon versions was also working fine.

Result of the snippet:

   [100] = 0.027176000000011,
  [200] = 0.027490999999998,
  [300] = 0.029940999999994,
  [400] = 0.02946399999999,
  [500] = 0.03003799999999,
  [600] = 0.031985000000006,
  [700] = 0.032883999999996,
  [800] = 0.031813,
  [900] = 0.042952000000014,
  [1000] = 0.031247000000008

Subsequent run:

  [100] = 0.033963,
  [200] = 0.03285600000001,
  [300] = 0.033233999999993,
  [400] = 0.03398199999998,
  [500] = 0.033278999999993,
  [600] = 0.034742999999992,
  [700] = 0.033985999999999,
  [800] = 0.035032999999999,
  [900] = 0.038806999999991,
  [1000] = 0.035764

MacOS 13.2 M1 chip HammerSoon 0.9.97 (6267)

[cmsj]

@smackesey (and everyone else)... so, we did find a Console logging issue, basically the log was allowed to grow infinitely and it would take more and more time for the text field to process it.

This was resolved in https://github.com/Hammerspoon/hammerspoon/pull/3400 which sets a maximum length for the scrollback history.

I'd be super interested to know if that has helped with this issue! I'm trying to get some other bits done before releasing 0.9.98, but you can download a signed build with that console logging fix from here, to try: https://github.com/Hammerspoon/hammerspoon/actions/runs/4355425658 (near the bottom in the Artifacts section).

[oniatsu]

This problem does not seem to have been resolved.

I have confirmed that setting the log level to nothing or clearing the console periodically improves the problem.

My environment:

• macOS 13.3.1
• Hammerspoon 0.9.100

[smackesey]

I can report that the issue does seem to have been solved for me. This is now my test result:

2023-05-01 08:41:32: {
  [100] = 1.1000000000011e-05,
  [200] = 5.000000000005e-06,
  [300] = 4.000000000004e-06,
  [400] = 4.9999999999772e-06,
  [500] = 5.000000000005e-06,
  [600] = 5.000000000005e-06,
  [700] = 4.9999999999772e-06,
  [800] = 5.000000000005e-06,
  [900] = 4.000000000004e-06,
  [1000] = 3.9999999999762e-06
}

For comparison, my result when I initially discovered this problem:

2022-11-03 14:14:49: {
  [100] = 0.000554,
  [200] = 0.000777,
  [300] = 0.00104,
  [400] = 0.001284,
  [500] = 0.0015660000000001,
  [600] = 0.0018090000000001,
  [700] = 0.002119,
  [800] = 0.002435,
  [900] = 0.002942,
  [1000] = 0.0030910000000002
}

So it's a couple of orders of magnitude faster now with no apparent slowdown.

I'm on Ventura 13.3.1 and HS 0.9.100.

[qaisjp]

I can confirm that commenting out all my print statements (that were running inside an eventtap callback) makes Hammerspoon no longer get stuck at 100% CPU usage.

> hs.processInfo.version
0.9.100