Delay between the modals about spacehammer HOT 16 CLOSED

@valrus yeah, that sounds exactly like my issue. It really looks like an upstream bug in Hammerspoon itself. Drives me nuts. For now, I bound this to a key:

(fn reset-hs []
  (io.popen "killall Hammerspoon && open -a Hammerspoon &"))

(hs.hotkey.bind [:cmd :shift :ctrl] "0" reset-hs)

I would simply restart it and it keeps steady for a bit. Sometimes (very rarely) even that doesn't hold for too long, then I'd have to do the trick with the screen rotation described above.

from spacehammer.

I don't get that issue, but I sometimes get an issue where the first modal won't pop up for a while, but it's clearly mapping hotkeys. Then at some point it all catches up and shoots through different menus based on my inputs. I get the feeling that this is mostly a hammerspoon issue, though.

We should look into their debug functionality regardless and see if we can figure out a reliable way to reproduce either of these issues.

from spacehammer.

Yes, I don't think that's us, it's most likely upstream. I think this has something to do with me having an ultra-wide display 5120x1440. There's a bug in Hammerspoon where it doesn't properly place things with hs.grid. It annoyed me for a very long time and I wanted to sit down and study the Lua code. Imagine my surprise when after reinstalling the system the grid started working just fine.

from spacehammer.

Just to confirm, I lowered the resolution. First, nothing happened, even after re-loading the config. Then I killed and restarted Hammerspoon. Issue is no longer there. I scaled back to 4K, restarted HS, and again - it looks fine. But I'm sure, at some point things get wonky again.

I wonder if I can use hs.screen and write some kind of "reset" function to help me deal with this shit.

from spacehammer.

This is beyond stupid but I can't come up with anything better. LOL

(fn reset-screen []
  "For some stupid reason things sometiems get really in ultra-wide.
see:
https://github.com/agzam/spacehammer/issues/171 and
https://github.com/Hammerspoon/hammerspoon/issues/3320"
  (: (hs.screen.mainScreen) :rotate 90)
  (hs.timer.doAfter 0.1 (fn [] (: (hs.screen.mainScreen) :rotate 0))))

(hs.hotkey.bind [:cmd :shift :option :ctrl] "0" reset-screen)

The funniest thing is that it appears to work.

from spacehammer.

FWIW I am pretty reliably getting delays between modals on two different machines after upgrading to Ventura. Let me know if there's anything I can do to help diagnose.

ETA that in both cases the screens are 4K or bigger.

from spacehammer.

I think I found something! Installed opensuse on an old mbp but last night decided to switch it back to OS X as I was missing spacehammer too much on my personal computer.

While getting spacehammer running, noticed it is logging a lot of text. Even after using it for a few minutes it really piles up. Anyway, coming back to my work computer today I noticed I was experiencing the slow modals issue too. I opened the hammerspoon console, cleared the log, and then modals seemed to be fast and responsive again.

Can someone please try to confirm that hypothesis?

from spacehammer.

I have definitely noticed slow downs, even to the point where the activator (my most used feature) slows down. I noticed that even reloading the config doesn't fix it, but I also noticed that that doesn't clear the log. I see that I have logs in my buffer from 2-14, and that's probably about when I got it working snappily again, but I am not sure. But that also means that I can go a week of daily use without it become an issue. I'll try to be cognizant of the next time I feel slow down and see if clearing the console fixes the issue.

Now, what would be the cause? Why would writing to a large buffer cause these hangs? We might be responsible for logging to the console, but we aren't responsible for the console causing slow downs. If we find it to be the culprit, we could probably just clear the console automatically every day or something, but we should probably escalate the issue as well.

I don't have the time to check right now, but we could also just artificially fill the console log and see if that degrades performance.

from spacehammer.

Ah so interestingly, my logs do clear when I reload my config but I realized that's because I have the following in my ~/.spacehammer/init.fnl

(hs.console.clearConsole)

Which gives this hypothesis some legs as it explains why I did not experience that slowdown as often.

If it turns out logging is the cause, I think there are 2 actions:

1. Create an issue on hammerspoon as you suggested. Could be anything from storing the log data in memory instead of a file, to how messages are appended, perhaps in-efficient table look ups to get to the newest entry?
2. Remove logging and cut a release. Then can draft or use a logging library (got some ideas I can propose) so it can be opt'd into (perhaps with some heirarchical filtering for finer-grain control)

EDIT: I like the idea of artificially filling up the log, might be able to set that up tonight or afternoon tomorrow.

from spacehammer.

Tested that hypothesis. Created a small async test function that repeatedly sets a timeout and logs more and more data. In order to not go too crazy, I increase the delay by doubling it every 100 iterations.

(local state
  {:loop-count 0
   :delay      10
   :entries    []})

(fn start!
  []
  (let [tick (fn [f]
               (hs.timer.doAfter
                 (/ state.delay 1000)
                (fn []
                  (print "debug-modal-delay"
                         (hs.inspect state))
                  (table.insert state.entries (.. "" (os.time)))
                  (set state.loop-count (+ state.loop-count 1))
                  (when (= (% state.loop-count 100) 0)
                    (set state.delay (* state.delay 2)))
                  (f f))))]
    (tick tick)))



{: start!}

Here's a recording of clearing the console output, and me navigating to the media menu. The marker is when my recording shows I pressed "m" vs when the modal appears. It's pretty quick.

Here's after running the expanding log:

There is a really noticeable delay between when I press m and the media menu opens. Then after, I use my binding to clear the hs log, and do it again and it goes back to opening nearly instantly.

from spacehammer.

Nice work! Let's file a ticket.

On my end, I did notice it started getting sluggish with a normal amount of logging, I could measure about a second between modals, and clearing the console seems to do the trick as well!

from spacehammer.

Great find, everyone! I can try changing my "restart hammerspoon" binding to just clear the log now :)

from spacehammer.

Hammerspoon/hammerspoon#3389

Created upstream issue, next step will be a PR to remove current logging to prevent this issue. May or may not include an opt-in logging system with it.

from spacehammer.

Not sure if removing the logging is the right solution. Some of the logging is unavoidable since it's done by the hammerspoon module e.g. the keymap stuff logs whether we want to or not. Maybe we make it so that we automatically periodically clear the buffer?

from spacehammer.

That is true, there is a lot we can't control. Though there is a global log level option so may be able to reduce that.

Doing a search though, there's a good amount we can trim.

 > ag 'log'
core.fnl
27:(local log (hs.logger.new "\tcore.fnl\t" "debug"))
106:    (log.d (.. "Copying " example-path " to " target-path))

config.example.fnl
9:        :logf logf} (require :lib.functional))

docs/advice.org
802:** Log Advisable Functions

lib/bind.fnl
7:(local log (hs.logger.new "bind.fnl" "debug"))
24:          (log.wf "Could not dispatch action %s: Function \"%s\" was not found in module \"%s\".\nEnsure the correct action is referenced in config.fnl."
51:  Returns a function to perform that action or logs an error and returns
58:                (log.wf "Could not create action handler for %s"

lib/lifecycle.fnl
2:(local log (hs.logger.new "lifecycle.fnl" "debug"))
30:                (log.wf "Could not call lifecycle method %s on %s"

lib/modal.fnl
34:(local log (hs.logger.new "modal.fnl" "debug"))
175:        (log.w "No trigger could be found for item: "
427:;; Watchers, Dispatchers, & Logging
431:(fn start-logger
434:  Start logging the status of the modal state machine.
437:  Creates a watcher of our state atom to log state changes reactively.
440:   fsm.state :log-state
441:   (fn log-state
444:       (log.df (hs.inspect (map #(. $1 :title) state.context.history)))))))
473:  Causes side effects to start the state machine, show the modal, and logging.
482:                  :log "modal"}
486:    (start-logger fsm)

lib/utils.fnl
7:    (: filter :setAppFilter :Emacs {:allowRoles [:AXUnknown :AXStandardWindow :AXDialog :AXSystemDialog]})))

lib/statemachine.fnl
84:              (if fsm.log
85:                  (fsm.log.df "Action :%s does not have a transition function in state :%s"
127:              :log (if template.log (hs.logger.new template.log "info"))}]

lib/apps.fnl
5:Uses a state machine to better organize logic for entering apps we have config
25:(local log (hs.logger.new "apps.fnl" "debug"))
237:;; Watchers, Dispatchers, & Logging
286:(fn start-logger
290:  state atom to log changes over time.
293:   fsm.state :log-state
294:   (fn log-state
296:     (log.df "app is now: %s" (and state.context.app state.context.app.key)))))
426:                  :log "apps"}
430:    (start-logger fsm)

lib/functional.fnl
60:(fn logf
258: : logf

vim.fnl
14:(local log (hs.logger.new "vim.fnl" "debug"))
374:;; Watchers & Logging
377:(fn log-updates
379:  (atom.add-watch fsm.state :logger
381:                    (log.f "Vim mode: %s" state.current-state))))
389:;; (fn log-key
398:;;                            log-key)]
425:    (log-updates fsm)

from spacehammer.

This was "fixed" in hammerspoon by applying a max log size. Can we close this?

from spacehammer.