Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Print statements hanging Hammerspoon and triggering memory leak #3565

Closed
gab-john opened this issue Nov 28, 2023 · 15 comments
Closed

Print statements hanging Hammerspoon and triggering memory leak #3565

gab-john opened this issue Nov 28, 2023 · 15 comments

Comments

@gab-john
Copy link

gab-john commented Nov 28, 2023

Hello, after I've upgraded from Sonoma 14.0 to 14.1, my script stops responding a few times a day. Hammerspoon becomes unresponsive, the console becomes blank, and the memory starts increasing indefinitely to several GB.

I've worked around the issue by removing all print statements, and now it no longer crashes, but I spent some time anyway trying to isolate the reason.

This snippet should reproduce the issue when pasted on the console:

hs.console.setConsole("")
local i = 1
local length = 0

T = hs.timer.doEvery(0.005, function ()
    print(i .. ": " .. string.rep(".", length))
    length = (length + 1) % 40
    i = i + 1
end)

On an M1 and on an Intel (both Sonoma 14.1), it hangs after 2000-3000 iterations.

Interestingly, it doesn't happen if all the strings after some point are the same length, such as with just print(i). Then it crashes a few numbers after 10000 (because i changed from 4 to 5 digits). That holds true even if i starts at -1000 or -5000, it would still crash a bit after 10000.

It also doesn't happen when disabling the history limit with hs.console.maxOutputHistory(0) so it could be related to the characters being deleted on #3400.

@jkroes
Copy link

jkroes commented Nov 29, 2023

I've been having the same issue. Tried running your code for a couple minutes, and indeed HS hung and its memory usage suddenly shot up >1GB and rising. Looks like a CPU issue. Here's the start of the issue per the console:

default	09:26:03.812424-0800	kernel	process Hammerspoon[45528] thread 831168 caught burning CPU! It used more than 50% CPU over 180 seconds
default	09:26:03.816067-0800	symptomsd	Received CPU usage trigger: 
  Hammerspoon[45528] () used 90.00s of CPU over 110.10 seconds (averaging 81%), violating a CPU usage limit of 90.00s over 180 seconds.
default	09:26:03.819713-0800	symptomsd	RESOURCE_NOTIFY trigger for Hammerspoon [45528] (90000000041 nanoseconds of CPU usage over 110.00s seconds, violating limit of 90000000000 nanoseconds of CPU usage over 180.00s seconds)
default	09:26:04.182218-0800	spindump	Saved cpu_resource.diag report for Hammerspoon version 0.9.100 to Hammerspoon_2023-11-29-092603_Justins-MacBook-Air.cpu_resource.diag
default	09:26:12.071459-0800	spindump	Hammerspoon [45528]: hang likely: not sampling due to conditions 0x400000000
default	09:26:13.204859-0800	Activity Monitor	Hammerspoon [45528] force quit
default	09:26:13.226929-0800	runningboardd	Invalidating assertion 415-403-34710 (target:[app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>:45528]) from originator [osservice<com.apple.WindowServer(88)>:403]
default	09:26:13.219631-0800	WindowManager	Connection invalidated | (45528) Hammerspoon
default	09:26:13.227031-0800	runningboardd	XPC connection invalidated: [app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>:45528]
default	09:26:13.227526-0800	runningboardd	Invalidating assertion 415-403-34709 (target:[app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>:45528]) from originator [osservice<com.apple.WindowServer(88)>:403]
default	09:26:13.425726-0800	runningboardd	[app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>:45528] termination reported by launchd (2, 15, 15)
default	09:26:13.425786-0800	runningboardd	Removing process: [app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>:45528]
default	09:26:13.426033-0800	runningboardd	Removed last relative-start-date-defining assertion for process app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>
default	09:26:13.426142-0800	runningboardd	Removing launch job for: [app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>:45528]
default	09:26:13.426609-0800	runningboardd	Removed job for [app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>:45528]
default	09:26:13.430299-0800	runningboardd	Removing assertions for terminated process: [app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>:45528]
default	09:26:13.437990-0800	runningboardd	Calculated state for app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>: none (role: UserInteractiveNonFocal)
default	09:26:13.438972-0800	runningboardd	Calculated state for app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>: none (role: None)
default	09:26:13.439666-0800	runningboardd	Calculated state for app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>: none (role: None)
default	09:26:13.446367-0800	gamepolicyd	Received state update for 45528 (app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>, none-NotVisible
default	09:26:13.446744-0800	launchservicesd	Hit the server for a process handle 10f8f88a0000b1d8 that resolved to: [app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>:45528]
default	09:26:13.454308-0800	loginwindow	-[PersistentAppsSupport applicationQuit:] | for app:Hammerspoon, _appTrackingState = 2
default	09:26:13.454343-0800	loginwindow	-[PersistentAppsSupport applicationQuit:] | App: Hammerspoon, quit, updating active tracking timer
default	09:26:15.920463-0800	spindump	 [45528]: Displaying hang dialog for Hammerspoon
default	09:26:15.920603-0800	spindump_agent	Presenting hang dialog to user for app Hammerspoon
default	09:26:17.674204-0800	spindump_agent	User chose (Ignore) for app Hammerspoon
default	09:26:18.456521-0800	loginwindow	-[PersistentAppsSupport saveLogoutPersistentState:finalSnapshot:] |      previouslyRunningApps: (
        {
        BackgroundState = 0;
        BundleID = "com.apple.console";
        Hide = 0;
        Path = "/System/Applications/Utilities/Console.app";
    },
        {
        BackgroundState = 2;
        BundleID = "com.google.chrome";
        Hide = 0;
        Path = "/Applications/Google Chrome.app";
    },
        {
        BackgroundState = 2;
        BundleID = "com.apple.activitymonitor";
        Hide = 0;
        Path = "/System/Applications/Utilities/Activity Monitor.app";
    },
        {
        BackgroundState = 3;
        BundleID = "org.hammerspoon.hammerspoon";
        Hide = 0;
        Path = "/Applications/Hammerspoon.app";
    },
        {
        BackgroundState = 2;
        BundleID = "com.microsoft.vscode";
        Hide = 0;
        Path = "/Applications/Visual Studio Code.app";
    },
        {
        BackgroundState = 2;
        BundleID = "com.googlecode.iterm2";
        Hide = 0;
        Path = "/Applications/iTerm.app";
    },
        {
        BackgroundState = 2;
        BundleID = "com.apple.systempreferences";
        Hide = 0;
        Path = "/System/Applications/System Settings.app";
    },
        {
        BackgroundState = 2;
        BundleID = "com.apple.textedit";
        Hide = 0;
        Path = "/System/Applications/TextEdit.app";
    },
        {
        BackgroundState = 2;
        BundleID = "com.apple.finder";
        Hide = 0;
        Path = "/System/Library/CoreServices/Finder.app";
    }
)
default	09:27:29.470602-0800	Console	update collaboration items for activityItems:(
    "default\t09:26:03.812424-0800\tkernel\tprocess Hammerspoon[45528] thread 831168 caught burning CPU! It used more than 50% CPU over 180 seconds\n"
)
default	09:27:29.470659-0800	Console	request collaboration items for activity items:(
    "default\t09:26:03.812424-0800\tkernel\tprocess Hammerspoon[45528] thread 831168 caught burning CPU! It used more than 50% CPU over 180 seconds\n"
)
default	09:28:28.672517-0800	Console	update collaboration items for activityItems:(
    "default\t09:26:03.812424-0800\tkernel\tprocess Hammerspoon[45528] thread 831168 caught burning CPU! It used more than 50% CPU over 180 seconds\n"
)
default	09:28:28.672555-0800	Console	request collaboration items for activity items:(
    "default\t09:26:03.812424-0800\tkernel\tprocess Hammerspoon[45528] thread 831168 caught burning CPU! It used more than 50% CPU over 180 seconds\n"
)
default	09:28:53.160623-0800	Console	update collaboration items for activityItems:(
    "default\t09:26:03.812424-0800\tkernel\tprocess Hammerspoon[45528] thread 831168 caught burning CPU! It used more than 50% CPU over 180 seconds\n"
)
default	09:28:53.160674-0800	Console	request collaboration items for activity items:(
    "default\t09:26:03.812424-0800\tkernel\tprocess Hammerspoon[45528] thread 831168 caught burning CPU! It used more than 50% CPU over 180 seconds\n"
)

@benediktwerner
Copy link

Also have been running into this issue, my hotkeys suddenly stop working and memory usage starts increasing rapidly (usually I catch it at ~10-50 GB but just now I only noticed it at several hundred GB).

I only have one print but I guess it's triggered on every focus change, I'll try removing it. Though HS also prints stuff every time hotkeys get enabled and disabled, which also happens quite often for me, hopefully that doesn't matter, since hs.console.maxConsoleHistory(0) doesn't seem like a great solution either.

@Write
Copy link

Write commented Dec 10, 2023

Can confirm the issue here.

Indeed if Toggling hotkey use the same function as print, I don't really have any workaround for that.
@benediktwerner I think you meant hs.console.maxOutputHistory(0). If set to 0, the output will be normal. Minimum required is 1. Which may trigger the issue too in the end.

For now I'm trying hs.console.maxOutputHistory(1), w/ a custom code to rewrite console to file

hammerspoonLogFile = assert(io.open('hammerspoon-console.log','a'))
hammerspoonLogFile:setvbuf("line")
-- Override Hammerspoon's print with print that logs to file, not just HS console
-- See print() definition in https://github.com/Hammerspoon/hammerspoon/blob/master/extensions/_coresetup/init.lua
local old_print, tostring = print, tostring
local tconcat, pack = table.concat, table.pack
print = function(...)
    local vals = pack(...)

    for k = 1, vals.n do
      vals[k] = tostring(vals[k])
    end

    local l = tconcat(vals, "\t")
    hammerspoonLogFile:write(l, '\n')
    return old_print(l)
end

@Rhys-T
Copy link

Rhys-T commented Dec 10, 2023

Though HS also prints stuff every time hotkeys get enabled and disabled, which also happens quite often for me

Indeed if Toggling hotkey use the same function as print, I don't really have any workaround for that.

It's not documented1 (Edit: yet - see comments below), but there's actually an hs.hotkey.setLogLevel function that can control the enable/disable messages for hotkeys. (It's actually the setLogLevel method of the hs.logger instance used by hs.hotkey internally. getLogLevel is exposed too.) Enable/disable messages are logged at info level2, so setting the logger's level to nothing, error, or warning should hide them.

(Also, by default, entering/exiting an hs.hotkey.modal is silent - as long as none of the hotkeys conflict with ones that were already enabled before the modal was entered.)

Footnotes

  1. Or rather, it is documented in the source code for hs.hotkey, but it doesn't seem to be making it into the rendered documentation for some reason. Edit: Apparently the docs just got added, and haven't made it into a release yet. The specifics of what gets logged at what level really aren't documented, though.

  2. Or debug if the hotkey is being toggled as part of a modal.

@Write
Copy link

Write commented Dec 10, 2023

Though HS also prints stuff every time hotkeys get enabled and disabled, which also happens quite often for me

Indeed if Toggling hotkey use the same function as print, I don't really have any workaround for that.

It's not documented1, but there's actually an hs.hotkey.setLogLevel function that can control the enable/disable messages for hotkeys. (It's actually the setLogLevel method of the hs.logger instance used by hs.hotkey internally. getLogLevel is exposed too.) Enable/disable messages are logged at info level2, so setting the logger's level to nothing, error, or warning should hide them.

(Also, by default, entering/exiting an hs.hotkey.modal is silent - as long as none of the hotkeys conflict with ones that were already enabled before the modal was entered.)

Footnotes

  1. Or rather, it is documented in the source code for hs.hotkey, but it doesn't seem to be making it into the rendered documentation for some reason. The specifics of what gets logged at what level really aren't documented, though.
  2. Or debug if the hotkey is being toggled as part of a modal.

Thanks, hs.hotkey.setLogLevel("warning") indeed works to hide hotkey message set at launch, and also for those set disabled / enabled dynamically.

As for modal, indeed no message is shown.

@latenitefilms
Copy link
Contributor

Related:

Add setLogLevel documentation for each extension #2248

@Rhys-T
Copy link

Rhys-T commented Dec 11, 2023

Whoops. I just realized how recent that commit I linked was - it's not actually in a release yet, so of course it's not showing up in the documentation.

@pierrebailletsonos
Copy link

Thank you for this report, I've run into the same "mysterious" freezing issue for a while, although I did not really change my configuration. I've removed a lot of logging from my codebase and hopefully, this should lessen the issue.

@HerbCSO
Copy link

HerbCSO commented Jan 31, 2024

FWIW I had the same issue, reduced logging to almost nothing and at least it's not crashing anymore. Would still like to be able to get my logging back though. ;]

thenoseman added a commit to thenoseman/zsh_config that referenced this issue Feb 10, 2024
@muescha
Copy link
Contributor

muescha commented Mar 7, 2024

Though HS also prints stuff every time hotkeys get enabled and disabled, which also happens quite often for me, hopefully that doesn't matter, since hs.console.maxConsoleHistory(0) doesn't seem like a great solution either.

I have created a helper to disable the logging for some hotkeys:
https://github.com/muescha/dot_hammerspoon/blob/master/Helpers/HotkeySilence.lua#L17-L22

usage in:
https://github.com/muescha/dot_hammerspoon/blob/master/Helpers/HotkeyBindSafe.lua#L27-L29

https://github.com/muescha/dot_hammerspoon/blob/master/Helpers/SendKeysOnlyInApp.lua#L123-L125

@zgqq
Copy link

zgqq commented May 21, 2024

Same issue.

@lingium
Copy link

lingium commented Jun 23, 2024

Same issue for me! and this seems only happens on apple silicon not intel based mac, any suggestions up to now?

@HerbCSO
Copy link

HerbCSO commented Jun 23, 2024

FWIW this is happening on my Intel Mac. I did manage to mitigate it by reducing the print/logging statements to almost nothing.

@cmsj
Copy link
Member

cmsj commented Aug 5, 2024

So the behaviour here is really interesting. With the default console history length of 100,000 characters, I can also reliably repeat the hang using @gab-john 's test snippet, after about 2100 iterations. Dropping the history length to 50,000 characters raises the hang point to about 38,000 iterations, by which point Hammerspoon is using 20GB of RAM.

I think it's pretty clear that the current methodology for truncating scrollback is a complete disaster that will eventually fail at any length limit (although it looks like the scaling is non-linear, so a limit like 5,000 ought to hold crashes off for a very long time) because something is leaking.

I've quickly profiled a debug build and it looks like the majority of the RAM allocations are coming from text related classes in AppKit.

So, this is either a generic bug in AppKit that eventually an infinitely growing NSTextView will just hang, or there is something more subtle going on. One hypothesis I had was that because we just delete characters off the front of the underlying NSTextStorage, we would be confusing the fact that they were added as NSAttributedStrings, but I don't think that can be it because the hang doesn't seem to be happening very close to where that happens.

I'll keep poking at this and see what I can come up with.

@cmsj
Copy link
Member

cmsj commented Aug 5, 2024

Ok, I've restructured the way text is written to the console, and it will now be batched up and only actually committed to the NSTextView every 0.2 seconds. I've also changed some settings on the NSTextView to turn off a lot of the fancy things that make no sense for a log viewer (things like spell checking) and while I'm not super happy with the RAM usage, the situation overall appears to be dramatically improved.

After 20,000 iterations of the snippet, with the default 100,000 character history limit, Hammerspoon is still running fine, and RAM usage has "only" grown to 1.9GB. I suspect there is still a hang lurking out there in the future, but it should now be far less likely to be hit in any reasonable session. I'll push the code up shortly and I'm hoping to get a release out in the next couple of days.

Thanks all for your contributions here, and apologies it's taken so long to address!

cmsj added a commit that referenced this issue Aug 5, 2024
…se leaking/hanging when lots of output is happening. Fixes #3565
@cmsj cmsj closed this as completed in 4494358 Aug 5, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests