Memory Leak: File watcher and `Pool`

[gasi]

We’ve been using Toffee (version 0.1.3) for a project and struggled with a significant memory leak. An outside consultant (@thlorenz) helped us track down the memory leak and it turned out to originate within Toffee, specifically its file watching mechanism and pool for VM contexts. Due to time constraints, we couldn’t test the latest version (although it does seem to contain both offending parts: file watching and Pool) and had to patch our 0.1.3 version.

At this point, all I can share is our admittedly very invasive patch for containing the problem: https://github.com/FiftyThree/toffee/compare/master...memory-leak-fix

Long-term, if we decide to upgrade Toffee, re-investigate the leak and fix it properly, we’ll share our findings but we’re also considering alternative templating languages.

[aseemk]

Thanks for filing, @gasi!

Just to add a bit more info, we're not changing our files in production at all. Somehow, though, Toffee is re-watching the files every time we render. And the way it's doing that is causing a leak.

On that note, though — and I'm happy to open a separate issue — we were also surprised to discover that Toffee is reading the file from disk every render. That shouldn't be happening though, right? Since Toffee's watching the files and it should be caching them as documented:

https://github.com/malgorithms/toffee#does-it-cache-templates

[malgorithms]

hey guys, this is very interesting. We've been using Toffee in production for a while and aren't seeing this mem leak problem. While I haven't been working on Toffee much in the last year, 0.1.3 is really pretty old (over a year) -- can you see if this problem happens with 0.1.12? What's the reason for using the old one?

Reading the files on every render doesn't make any sense to me. As a test I just went into my own Node.js project using Toffee that monitors for changes, and I threw some logs before ever fs.read* call in there, and they definitely aren't happening unless I change the file. So something is different between your config and mine.

[malgorithms]

I did some testing on a flight last night and wrote a little script that used a Toffee engine to render a file over a million times -- each time with different vars and each call in turn included calls to other partials and a layout. All said it was about 10,000,000 calls to render, outputting over a gigabyte of data. The process didn't grow and it definitely wasn't hitting the filesystem.

Toffee has all kinds of exposed functions because there are lots of different templating engines all requiring different interfaces. So it's possible one use case of Toffee is doing something bad, but I'll need more info to figure out what it is. But I'm happy to help. Whatever it is is likely a quick fix.

Some q's:

1. how are you using Toffee?
2. what system is it? Toffee uses fs.watch to know when files change -- and this is known to be different on different systems, so maybe I have a bug that just isn't showing up for us but is for you?
3. can you at least as a test drop in the latest version of Toffee and make sure it does't fix it? Even if you don't use it in prod?
4. how did you trace the mem leak to the pool creation? memwatch? I've noticed it will sometimes recognize 5 repeat heap increases and announce a leak, but then all of that will be recovered in a later.

I think the most interesting thing is what you said here:

On that note, though — and I'm happy to open a separate issue — we were also surprised to discover that Toffee is reading the file from disk every render.

This just doesn't make sense to me either -- it shouldn't be happening. Which means that it should be a fixable bug.

[malgorithms]

And as a last point - if you can provide me even the most trivial project which has this behavior, I'm happy to explore it.

[gasi]

@malgorithms Thanks for being so responsive. We’re heads down working on a product release so expect us to be radio silent for a while. We’ll try to get back to you this and provide you answers to 1.–4. once we can. Thanks again :+1:

[aseemk]

Major +1 to what @gasi said. You are awesome as always, @malgorithms!

[aseemk]

Quick info if it helps: we (courtesy of @thlorenz) could repro this leak (and sync file read) on our Mac OS X, but the whole reason we started investigating it is because we were having a massive leak on Heroku. We just deployed the patch @gasi linked to above this week, so we'll see over the weekend if our leak goes away. We're running Express 3.2.6 on the latest Node 0.10.