Sometimes PDF generation with exportJob takes too long time

[mishatrinex]

I am trying to create service for generating PDF built on Express Js and electron-pdf:

const express = require('express')
const router = express.Router()
const crypto = require('crypto')

/**
 * Generating PDF-file by URL
 */
router.get('/generate', function (req, res, next) {
  const endpoint = 'https://en.wikipedia.org/wiki/New_York_State_Route_308'

  const hash = crypto.createHash('md5').update(endpoint).digest('hex')
  const target = 'wiki-' + hash + '.pdf'

  const jobOptions = {
    inMemory: true,
    closeWindow: false
  }

  const options = {
    pageSize: 'A4',
    marginsType: 1,
    disableCache: true,
    printBackground: true,
    landscape: false,
    printSelectionOnly: false,
    waitForJSEvent: 'view-ready',
    outputWait: 1000
  }

  req.app.locals.exporter.createJob(endpoint, target, options, jobOptions).then(job => {
    job.on('job-complete', (r) => {
      res.contentType('application/octet-stream')
      res.attachment(target)
      res.end(r.results[0], 'binary')
      job.destroy()
    })
    job.render()
  })
})
module.exports = router

Destroying jobs manually, I am able to disable windowMaid cleaner:

// Use the maid to ensure we don't leak windows
//setInterval(WindowMaid.cleanupHungWindows, HUNG_WINDOW_CLEANUP_INTERVAL)

Average time for generation the example PDF is 3 secs, but after several tests I found some strange behavior – every 30 seconds generation hungs on 10 seconds at this place of exportJob.js:_executeJSListener:

const timeout = setTimeout(f, maxWait)

After 2-3 sec response time is back to 3 sec. I was trying to inject dispatching event 'view-ready' at local html file instead of wiki test page, but it didn't help.

Some additional information, starting server:

NODE_ENV=production electron --prof ./pdf-generator/bin/www

www.js:

#!/usr/bin/env node

/**
 * Module dependencies.
 */

var app = require('../app')
var debug = require('debug')('pdf-generator:server')
var http = require('http')
var ElectronPDF = require('electron-pdf')

var exporter = new ElectronPDF()
app.locals.exporter = exporter

/**
 * Get port from environment and store in Express.
 */

var port = normalizePort(process.env.PORT || '5000')
app.set('port', port)

/**
 * Create HTTP server.
 */

var server = http.createServer(app)

/**
 * Listen on provided port, on all network interfaces.
 */

exporter.on('charged', () => {
  // Only start the express server once the exporter is ready
  server.listen(port)
  server.on('error', onError)
  server.on('listening', onListening)
})
exporter.start()
/**
 * Normalize a port into a number, string, or false.
 */

function normalizePort (val) {
  var port = parseInt(val, 10)

  if (isNaN(port)) {
    // named pipe
    return val
  }

  if (port >= 0) {
    // port number
    return port
  }

  return false
}

/**
 * Event listener for HTTP server "error" event.
 */

function onError (error) {
  if (error.syscall !== 'listen') {
    throw error
  }

  var bind = typeof port === 'string'
    ? 'Pipe ' + port
    : 'Port ' + port

  // handle specific listen errors with friendly messages
  switch (error.code) {
    case 'EACCES':
      console.error(bind + ' requires elevated privileges')
      process.exit(1)
      break
    case 'EADDRINUSE':
      console.error(bind + ' is already in use')
      process.exit(1)
      break
    default:
      throw error
  }
}

/**
 * Event listener for HTTP server "listening" event.
 */

function onListening () {
  var addr = server.address()
  var bind = typeof addr === 'string'
    ? 'pipe ' + addr
    : 'port ' + addr.port
  debug('Listening on ' + bind)
}

[codecounselor]

Thanks for the detailed issue.

Something doesn't seem to be adding up. You show that you are setting outputWait: 1000. But the default is 10 seconds and that would match the behavior you are seeing.

Can you set a breakpoint on

const timeout = setTimeout(f, maxWait)

and see what the maxWait is?

If the page you're loading is not emitting view-ready properly what should happen is that every request takes the full maxWait time.

[mishatrinex]

logger('maxWait', maxWait)
const timeout = setTimeout(f, maxWait)

The maxWait is 1 second:

  electronpdf:info: maxWait 1000 +0ms

According docs (https://nodejs.org/api/timers.html#timers_settimeout_callback_delay_args):

The callback will likely not be invoked in precisely delay milliseconds. Node.js makes no guarantees about the exact timing of when callbacks will fire, nor of their ordering. The callback will be called as close as possible to the time specified.

But 10 seconds delay is too much:

  electronpdf:info: cancelReadyEvent call +10s

[codecounselor]

Interesting, I have not seen this behavior before.

If you can publish your entire project to a repo I can try to reproduce what you're seeing.

[mishatrinex]

https://github.com/mishatrinex/pdf-generator

[codecounselor]

I added some additional logging right before the timer is set and right after the _generate function is invoked. The results mirror your findings.

  electronpdf:info: _waitForPage called... +3s
  electronpdf:info: _waitForPage Timeout set:  100 +0ms
  electronpdf:info: _waitForPage Timeout expired +102ms

  electronpdf:info: _waitForPage called... +373ms
  electronpdf:info: _waitForPage Timeout set:  100 +0ms
  electronpdf:info: _waitForPage Timeout expired +101ms

  electronpdf:info: _waitForPage called... +204ms
  electronpdf:info: _waitForPage Timeout set:  100 +0ms
  electronpdf:info: _waitForPage Timeout expired +105ms

  electronpdf:info: _waitForPage called... +364ms
  electronpdf:info: _waitForPage Timeout set:  100 +0ms
  electronpdf:info: _waitForPage Timeout expired +101ms

  electronpdf:info: _waitForPage called... +364ms
  electronpdf:info: _waitForPage Timeout set:  100 +0ms
  electronpdf:info: _waitForPage Timeout expired +101ms

  electronpdf:info: _waitForPage called... +1s
  electronpdf:info: _waitForPage Timeout set:  100 +1ms
  electronpdf:info: _waitForPage Timeout expired +8s

  electronpdf:info: _waitForPage called... +3s
  electronpdf:info: _waitForPage Timeout set:  100 +1ms
  electronpdf:info: _waitForPage Timeout expired +7s

  electronpdf:info: _waitForPage called... +4s
  electronpdf:info: _waitForPage Timeout set:  100 +0ms
  electronpdf:info: _waitForPage Timeout expired +10s

  electronpdf:info: _waitForPage called... +177ms
  electronpdf:info: _waitForPage Timeout set:  100 +0ms
  electronpdf:info: _waitForPage Timeout expired +3s

  electronpdf:info: _waitForPage called... +394ms
  electronpdf:info: _waitForPage Timeout set:  100 +0ms
  electronpdf:info: _waitForPage Timeout expired +4s

  electronpdf:info: _waitForPage called... +362ms
  electronpdf:info: _waitForPage Timeout set:  100 +0ms
  electronpdf:info: _waitForPage Timeout expired +101ms

  electronpdf:info: _waitForPage called... +4s
  electronpdf:info: _waitForPage Timeout set:  100 +0ms
  electronpdf:info: _waitForPage Timeout expired +10s

  electronpdf:info: _waitForPage called... +4s
  electronpdf:info: _waitForPage Timeout set:  100 +0ms
  electronpdf:info: _waitForPage Timeout expired +10s

Unfortunately this appears to be a bug inside Electron (or Chromium)
electron/electron#7079

I tried to use the flag mentioned in this comment:
electron/electron#7079 (comment)

Which can be set using the browserConfig option like this:

const options = {
...
    outputWait: 100,
    browserConfig: '{"webPreferences": {"backgroundThrottling": false}}'
  }

I suspect it doesn't have any effect because the timer is on the main process, and that setting applies to the renderer process.

This isn't an issue for my use case because the pages being exported all emit the ready-event so under normal circumstances and timers that are created get removed before they fire.

If you have similar control over the content I recommend this approach. If you are exporting pages (like wikipedia) outside your control you're kind of stuck.

I'm sure you can get creative :)

[mishatrinex]

This isn't an issue for my use case because the pages being exported all emit the ready-event so under normal circumstances and timers that are created get removed before they fire.

I run test with local page (https://raw.githubusercontent.com/fraserxu/electron-pdf/master/test/event-test.html) and get same results with delaying rendering from 100 ms up to 10 s. So this approach doesn't work too.
I've updated https://github.com/mishatrinex/pdf-generator, you can run the test too.
Thank you.