Memory leak on repeat requests to PDF rendered by server

[adamperelman]

We're running into an issue rendering PDFs on the server, where each rendered PDF seems to be creating a memory leak.

Here's a small demo Express server that demonstrates the issue:
https://gist.github.com/adamperelman/f80c6f8afcc90753187d

The memory allocated by the server increases with every request.

[ashelley]

I can confirm that when you call document.end() there is a memory leak detected by node-memwatch. it's even detected if you use memwatch.on('leak', function(){})

i haven't seen it leak yet until I call document.end though.

{ start: Wed Jul 30 2014 14:55:16 GMT-0700 (PDT),
  end: Wed Jul 30 2014 14:55:16 GMT-0700 (PDT),
  growth: 85262720,
  reason: 'heap growth over 5 consecutive GCs (0s) - -2147483648 bytes/hr' }
{ start: Wed Jul 30 2014 14:55:16 GMT-0700 (PDT),
  end: Wed Jul 30 2014 14:55:16 GMT-0700 (PDT),
  growth: 403146464,
  reason: 'heap growth over 5 consecutive GCs (0s) - -2147483648 bytes/hr' }

[devongovett]

It doesn't seem obvious to me where the leak is occurring. Does it happen if you just make a bunch of empty documents every request rather than adding content? Trying to deduce where it may be happening. Could even be at the Node stream level, but that's less likely.

[ashelley]

I didn't notice it until I did a large document and ran my computer out of memory forcing lots of gc's... will try to look into it more.

[ashelley]

I haven't been able to isolate the problem. it is possible my problem is unrelated to pdfkit but i'm still trying to figure it out. my above statement where memwatch only shows leak after calling document.end also may be a red herring. I think this is possibly the only chance where the js event loop lets memwatch output the stats in my sample program.

[adamperelman]

After a bit of poking around, it seems that the leak is occurring in addPage().

Here's a much simpler server that leaks memory every time a request is made:

var express = require('express');
var PDFDocument = require('pdfkit');
var memwatch = require('memwatch');
var router = express.Router();

router.get('/', function(req, res) {
  var hd = new memwatch.HeapDiff();

  console.log("creating document...");

  var doc = new PDFDocument();
  for (var i = 0; i < 1000; i++) {
    doc.addPage();
  }
  doc.end();

  var diff = hd.end();
  console.log("diff:", diff);

  res.send(diff);
});

module.exports = router;

If I take out the call to addPage(), there's no leak, even if I add a bunch of text and graphics.

[adamperelman]

Here's another interesting behavior:

If I run the server above (which creates a blank 1000-page PDF doc each time), the heap shows the following pattern:

• after 1 request: ~25mb of memory are used by the heap
• after 2 requests: ~50mb of memory are used
• after 3 requests: ~75mb of memory are used
• after more than 3 requests: still about ~75mb of memory are used; the heap never seems to grow beyond that, even if I continue refreshing the page

I'm not sure what would explain this behavior -- it seems like the first 3 requests leak memory, but subsequent requests don't.

Could there be some kind of cache in the global state of PDFKit that eventually starts filling up and purging old objects?

I tried calling the global v8 garbage collector at the start of every request, to make sure this wasn't just a problem with lazily collecting garbage objects, but that didn't change the behavior at all.

[devongovett]

No, there should be no global state anywhere within PDFKit. addPage creates a PDFPage object each time it is called, which would obviously allocate memory. However, this page object only stays around until it is written to the file, which would be whenever another page is added.

I can look into this more this weekend. In the mean time, have you tried disabling compression? You can do so when you create the document:

var doc = new PDFDocument({ compress: false });

Just trying to weed out all possible external factors.

[ashelley]

Hello,

I'm still trying to blame my own code for the issue but I'm doing a comparison of heap snapshots using node-webkit-agent and i'm seeing a lot of retained closures

below are some screen shots of what i'm looking at. in the final image i've highlighted classes that I figure that i'm leaking.

^ all of the closures leaked look to be of the same type

[ashelley]

Okay....

I'm not sure if the issue i'm reporting is same issue as the OP any more but after some diagnostics I believe that fs.createWriteStream is the problem for me.

I removed PDFKit completely from my project and simply wrote out text data using the same stream i piped into the pdf document.

var stream = fs.createWriteStream('output.pdf');
doc.pipe(stream);

Essentially instead of writing

doc.text() 

I called stream.write directly (no pdfkit involved)

stream.write() 

I ran into the same issue: the program runs and eventually leaks enough memory to start thrashing on the node garbage collector.

To further diagnose the issue I replaced the stream in my program with a regular file descriptor and used it to write out my text instead;

fd.write(new Buffer()) 

The program ran successfully.

In conclusion I actually don't think my problem is caused by pdfkit itself but rather fs.createWriteStream.

I'm looking at ways of working around this issue now.

[devongovett]

Which version of node are you running? You should report this bug to node if it hasn't already been fixed in a newer version.

[ashelley]

I'm running 10.29... i'm gonna try upgrading to 10.30 and see if it helps.

[ashelley]

to confirm i'm seeing the same thing on node 10.30, going to try to make a minimum test case for fs.createWriteStream to make certain it's not me doing something weird.

[ashelley]

I've created a test case and filed a bug here:

nodejs/node-v0.x-archive#8048

[ashelley]

Okay, so i created a new file stream that doesn't have the issues i ran into:
https://github.com/ashelley/writable-filestream

It'll still be slow if you don't set a sane growth pattern but doesn't die completely like fs.createWriteStream. Now that I can write out my pdf I did notice an issue with compress: true vs compress: false but I will open a new topic and post there.

[adamperelman]

@devongovett, here's the simplest possible example I can come up with to reproduce the leak. There's no server or anything -- it's just creating a bunch of PDFDocuments in a loop.

If I turn compression off, the memory usage shrinks, but there's still a leak.

# Run with: coffee --nodejs --expose-gc demo.coffee

PDFDocument = require 'pdfkit'
memwatch = require 'memwatch'

for i in [1..20]
  # Force garbage collection.
  gc()

  # Capture a snapshot of the heap.
  hd = new memwatch.HeapDiff()

  # Create a doc with a bunch of blank pages.
  console.log "creating document #{i}"
  doc = new PDFDocument compress: false
  for j in [1..500]
    doc.addPage()
  doc.end()

  # Voila -- a leak!
  # The size of the heap increases by about 10mb
  # with each iteration of the loop (if compression is on),
  # or about 1.5mb per iteration (if compression is off).
  diff = hd.end()
  console.log diff