Fix "Your system has run out of application memory" bug

[latenitefilms]

No description provided.

[latenitefilms]

As discussed on Facebook @randomeizer - I THINK this might have something to do with cp.app.prefs:prop() watchers triggering repeatedly when nothing has actually changed.

[latenitefilms]

I'm going to close this issue for now as it's too broad.

[latenitefilms]

Kevin reports:

Before:

After Force Quitting:

[latenitefilms]

The highlighted values are constantly increasing, even with Final Cut Pro closed:

[latenitefilms]

This is what happens when I click the little arrow icon next to the _NSArrayM item:

[latenitefilms]

Before opening Final Cut Pro:

After opening and using Final Cut Pro:

[latenitefilms]

[randomeizer]

What are you gleaning from this?

[latenitefilms]

[latenitefilms]

I left my computer running overnight with CommandPost running via the Leaks Instrument in Xcode, and Final Cut Pro playing a timeline on loop whilst also running the following code:

chaosTimer = hs.timer.doEvery(30, function()
	 _fcp:inspector():show()
	 hs.timer.doAfter(5, function()
	 	_fcp:inspector():hide()
	 end)
end)

When I came back to it 04:56:35 later, I was presented with the dreaded "Out of application memory" error - although Activity Monitor looked fine - but Xcode Instruments had stopped because "An error occurred trying to capture Leaks data - Error retrieving leak information".

Here's a photo of what my computer looked like when I came back to it:

Here's what Instruments showed:

[latenitefilms]

[latenitefilms]

Probably not related - but FYI:

[latenitefilms]

Leak from Kevin on 19th June:

[latenitefilms]

Leak from Kevin on 21st June:

[latenitefilms]

Leak from Kevin on 13th July:

[latenitefilms]

Leak from Kevin on 13th July:

[latenitefilms]

@cmsj - As suggested, I left my computer running overnight with CommandPost running via the Leaks Instrument in Xcode, and Final Cut Pro playing a timeline on loop whilst also running the following code:

local timer = require("hs.timer")
local fcp = require("cp.apple.finalcutpro")
chaosTimer = timer.doEvery(30, function()
	fcp:inspector():show()
	timer.doAfter(5, function()
		fcp:inspector():hide()
	end)	 
	local file = io.open("/Users/chrishocking/Desktop/CommandPost.log", "a")
	io.output(file)
	io.write(os.date() .. " - " .. collectgarbage("count") .. "\n")
	io.close(file)
end)

For this test, I also disabled the AX cache, by adjusting:

function axutils.cache(source, key, finderFn, verifyFn)
    local value = source and source[key]
    if value == nil or not axutils.isValid(value) or verifyFn and not verifyFn(value) then
        value = finderFn()
        if axutils.isValid(value) and source then
            -- Don't cache.
            --source[key] = value
        else
            return nil
        end
    end
    return value
end

The log file I was writing to the Desktop ended up as follows:

Wed Aug 15 23:35:43 2018 - 34016.487304688
Wed Aug 15 23:36:25 2018 - 46473.979492188
Wed Aug 15 23:37:02 2018 - 51819.454101562
Wed Aug 15 23:37:40 2018 - 40086.653320312
Wed Aug 15 23:39:19 2018 - 56778.796875
Wed Aug 15 23:40:20 2018 - 79220.682617188
Wed Aug 15 23:40:55 2018 - 49283.708007812
Wed Aug 15 23:41:15 2018 - 60838.08203125
Wed Aug 15 23:41:54 2018 - 70667.78125
Wed Aug 15 23:43:35 2018 - 85593.2109375
Wed Aug 15 23:44:52 2018 - 95993.771484375
Wed Aug 15 23:45:13 2018 - 50060.25
Wed Aug 15 23:46:22 2018 - 59470.7890625
Wed Aug 15 23:46:54 2018 - 76264.412109375
Wed Aug 15 23:47:20 2018 - 84014.870117188
Wed Aug 15 23:49:39 2018 - 99457.670898438
Wed Aug 15 23:50:42 2018 - 102134.66503906
Wed Aug 15 23:53:29 2018 - 58178.86328125
Thu Aug 16 00:07:48 2018 - 104832.80957031
Thu Aug 16 00:15:05 2018 - 73225.069335938
Thu Aug 16 00:31:25 2018 - 112716.94628906
Thu Aug 16 00:45:18 2018 - 89645.551757812
Thu Aug 16 01:08:30 2018 - 113587.12792969
Thu Aug 16 01:58:38 2018 - 130937.41699219
Thu Aug 16 02:14:50 2018 - 135066.65136719
Thu Aug 16 02:20:58 2018 - 154472.53222656
Thu Aug 16 02:30:12 2018 - 85716.178710938

At the start of the test:

At the end of the test:

[latenitefilms]

I know @randomeizer is sick of my screenshots, but here's another set.

This is on one of our iMac's.

All of a sudden, the Mac will popup the out of application memory error - notice the memory pressure graph and application memory value:

CommandPost is still accessible, so I run some garbage collection commands - it doesn't really help:

However, when I gracefully quit CommandPost, everything goes back to normal:

It seems like "kernel_task" is the biggest memory hog - but I'm not sure why or how it's connected.

Before & After:

[latenitefilms]

Note to self - another test. This time just running CommandPost normally - without Xcode Instruments.

Before:

During:

After:

Garbage Collection Count values:
https://gist.github.com/latenitefilms/1ccb2f32fb8de13751a0423c9916906d

[latenitefilms]

An earlier test...

Before:

During:

First Sign of Trouble:

Just before CommandPost quit:

[latenitefilms]

For comparison, I just left Beta 29 running all night. Unfortunately a few hours after I started it weirdly got a Lua error, which broke my test hs.timer:

> local timer = require("hs.timer")
local fcp = require("cp.apple.finalcutpro")

local file = io.open("/Users/chrishocking/Desktop/CommandPost.log", "a")
io.output(file)
io.write(os.date() .. " - " .. collectgarbage("count") .. "\n")
io.close(file)

chaosTimer = timer.doEvery(10, function()
	fcp:inspector():show()
	timer.doAfter(5, function()
		fcp:inspector():hide()
	end)	 
	local file = io.open("/Users/chrishocking/Desktop/CommandPost.log", "a")
	io.output(file)
	io.write(os.date() .. " - " .. collectgarbage("count") .. "\n")
	io.close(file)
end)

2018-08-18 01:10:56: ********
2018-08-18 01:10:56: 01:10:56 ERROR:   LuaSkin: hs.timer callback error: .../extensions/cp/apple/finalcutpro/inspector/Inspector.lua:283: attempt to index a boolean value
stack traceback:
	.../extensions/cp/apple/finalcutpro/inspector/Inspector.lua:283: in function 'cp.apple.finalcutpro.inspector.Inspector.show'
	[string "local timer = require("hs.timer")..."]:10: in function <[string "local timer = require("hs.timer")..."]:9>
2018-08-18 01:10:56: ********

FYI: This bug has already been fixed in Beta 30.

However, that aside, it still ran all night without any "Out of application memory" errors by the morning.

Before:

After:

Here's the garbage collection test results prior to the timer failing:

https://gist.github.com/latenitefilms/37336803ea99ec6b9883f39ef083162d

[latenitefilms]

Ok, so I had a minor victory last night. I made the following minor change to latest develop branch:

With the CommandPost Grid Viewer Overlay enabled, Scrolling Timeline enabled, and Final Cut Pro playing, I then executed the following test code:

local timer = require("hs.timer")
local fcp = require("cp.apple.finalcutpro")

local file = io.open("/Users/chrishocking/Desktop/CommandPost.log", "a")
io.output(file)
io.write(os.date() .. " - " .. collectgarbage("count") .. "\n")
io.close(file)

chaosTimer = timer.doEvery(10, function()
	fcp:inspector():show()
	timer.doAfter(5, function()
		fcp:inspector():hide()
	end)	 
	local file = io.open("/Users/chrishocking/Desktop/CommandPost.log", "a")
	io.output(file)
	io.write(os.date() .. " - " .. collectgarbage("count") .. "\n")
	io.close(file)
end)

Here's the output of the log file:
https://gist.github.com/latenitefilms/987fe5fddb37b6496f79a6dccedea3a3

Here's what everything looked like before I executed that code:

Here's what everything looked like when I woke up:

The minor victory was, that despite the fact that the memory pressure graph in Activity Monitor was looking very sad, CommandPost was still running and there was no "out of application memory" error - which is the first test this has happened for after running overnight.

I stopped the timer, then checked the garbage collection values:

What's most interestingly though, is that I then pressed the "Reload" button in the Error Log, and when CommandPost reloaded, the memory pressure graph went back to normal - as did the kernel_task real memory usage:

It seems collectgarbage("count") isn't what we should be monitoring - it's the hs.crash.residentSize() (i.e. an integer containing the amount of RAM in use by Hammerspoon in bytes).

This makes me think that the issue is still that we're creating too many AX objects (or too many AX observer objects?), that aren't being properly destroyed/released - which is why kernel_task is using up so much RAM, as I ASSUME the Accessibility Framework uses kernel tasks to do it's thing.

[latenitefilms]

I'm going to close this issue for now - in the HOPE that the recent changes have fixed this issue.

Fingers and toes crossed!