espruino / Espruino

The Espruino JavaScript interpreter - Official Repo
http://www.espruino.com/
Other
2.73k stars 741 forks source link

console.log may be causing a very small memory leak #2471

Closed tnyeanderson closed 4 months ago

tnyeanderson commented 4 months ago

I've been following the instructions here under "Testing Afterwards" to test my app for memory leaks, etc.

I've made a minimally reproducible example to show what happens, called memleak-test.app.js:

{
  console.log("test");
}

Copy it to the watch's memory, then run in the console:

Bangle.loadWidgets();Bangle.drawWidgets();
process.memory().usage
eval(require("Storage").read("memleak-test.app.js"))
process.memory().usage
Bangle.setUI()
process.memory().usage

This produces the following results:

>Bangle.loadWidgets();Bangle.drawWidgets();
=undefined
>process.memory().usage
=903
>eval(require("Storage").read("memleak-test.app.js"))
test
=undefined
>process.memory().usage
=906
>Bangle.setUI()
=undefined
>process.memory().usage
=906

What this indicates is that calling console.log() in any app will allocate 3 blocks of memory which will not be reclaimed when the app exits. In my testing, apps which do not call console.log() will get the same usage before and after, so the extra 3 blocks of memory are not allocated when performing these same steps. The memory allocation is one-time only, it does not increase with further calls to console.log().

For fun, I tried another app:

{
  console.log("test");
  console = undefined;
}

This results in only 2 blocks of memory still allocated. I'm still not sure where those are coming from.

By my reading of the documentation linked above, this looks like a memory leak. If this is expected behavior, I think the docs should mention it (and any other "unsolveable" caveats) so app devs aren't trying to solve non-problems :)

Is this what the docs are talking about below?

If the library registers for input and can't be unloaded then it may not be suitable for 'fast load'.

Or is it this?

Well, if modules are loaded into memory then they will stay loaded, and we're using require("locale"), which is using memory. We don't actually care about 'losing' this memory, but we just need to check we're not leaking memory anywhere else.

We can get an idea of how much memory modules are using with E.getSizeOf(global["\xff"].modules) (although this may not be accurate if the modules reference user code).

If I run E.getSizeOf(global["\xff"].modules) just before the eval command loading my app, and then after running Bangle.setUI() and re-checking memory usage, the numbers are the same (494), so it looks like it isn't a modules thing (which I expected since require() isn't used).

Thanks for the hard work on espruino/bangle, it's fun to dev on so far!

gfwilliams commented 4 months ago

Hi,

What you're seeing isn't a leak but is just the way Espruino works. Espruino contains a bunch of functions/methods but it can't keep those in a symbol table in RAM all the time because it'd use up memory.

Normally you access something from this list of functions in flash, it's momentarily in RAM, but then it's freed. But when you access something that's a member of something else, that first symbol table entry gets loaded into RAM. In this case what you're seeing is twofold:

>process.memory().usage
=290
>process.memory().usage
=292 <----------------- here
>process.memory().usage
=292
>console.log("foo");
foo
=undefined
>process.memory().usage
=295  <-------------- console defined now
>console.log("foo");
foo
=undefined
>process.memory().usage
=295

You can set console to undefined as you note, but actually you've still got a variable called console which is set to undefined (so one var). You could remove it with delete completely and free the memory though (although this is kindof non-standard).

I'm happy to add a note about this behaviour as yes, it can be a bit confusing. Where exactly would you have expected to see info on this? In Testing Afterwards on https://www.espruino.com/Bangle.js+Fast+Load ?

tnyeanderson commented 4 months ago

Hi @gfwilliams, I had a feeling that's what was happening :)

Since this is expected behavior, I think there should be a section underneath "Other libraries", maybe called "Other symbols/builtins", which explains these expectations. I think it would also be best to show examples of how to determine if this is happening in your own app.

For context, I am working on a fork of Anton Clock and wanted to make sure I didn't cause any memory leaks (while allowing Fast Loading). Turns out that Anton Clock has (what appears to be) the same memory "leak" that I do. The supposed leak is much larger than these 3 blocks we are talking about above, and I am confident that it doesn't have anything to do with console specifically, but it leaves me questioning. What I really need answered by that page is: how can I be positive that my app isn't leaking memory, and that any leftovers are expected? Checking the module size with E.getSizeOf(global["\xff"].modules) is a good example of the kind of procedure I would want if I was trying to find out whether I have an unexpected memory leak at all. I'm still not sure if my app (or Anton Clock) actually is leaking memory unexpectedly, or if this is all well-defined behavior.

In conclusion, it would greatly benefit devs like me if any additional known caveats to the debugging procedures in the Fast Load instructions were documented there clearly, with concrete steps that will prove whether you have an unexpected memory leak (since right now, a lot of the phrasing on the page leaves you feeling uncertain).

tnyeanderson commented 4 months ago

Also, follow up question: can I still take advantage of Fast Load if I call Bangle.setUI() twice in my app? The first one shows the watchface, and the second one shows a different "screen" of the watch. Unfortunately, when the second one is called, it runs the remove function I provided in the first one, which should clean everything up, which means that some resources are no longer available. So it seems like you can't have a clock that calls setUI() more than once and allows for Fast Load. Is that correct?

gfwilliams commented 4 months ago

Ok, cool - I'll add something.

The easy way to check for leaks (which I'll document) is to run your app more than once by repeatedly flicking between the loader and the clock. After the first time a few things (like console) would be allocated, and maybe the launcher would do something too, but after you've done it a few times you shouldn't be seeing the memory usage rise any more.

can I still take advantage of Fast Load if I call Bangle.setUI() twice in my app?

Yes - so you're right that remove is called and that should remove everything global, but you don't have to worry about 'local' variables (eg. defined with let inside a block {}):

{
  let myVariable = { ... };
  let myVariable2 = { ... };

  function changeToScreen1() {
    Bangle.setUI(...);
  }

  function changeToScreen2() {
    Bangle.setUI(...);
  }

  changeToScreen1();  
}

Anything inside that block can use myVariable, and you don't have to delete it when remove is called. You can swap between different setUI and remove will be called and should clear up, but you don't have to worry about myVariable since as long as no function defined in that scope it is used by Espruino after you've cleared up, it will be freed automatically.