Our test environment takes 6-9 seconds to load before any tests get run. I tire of this during the ~30 times I run the test suite a day,¹ so I wanted to make it faster.

For better or worse, the API runs on Sails.js. Before running model/controller tests, a bootstrap file in our tests calls sails.lift.

require('sails').lift(function(err) {
    // Run the tests
});

This lift call generates about 400 queries against Postgres to retrieve database schema, that each look like this:

SELECT x.nspname || '.' || x.relname as "Table", x.attnum
as "#", x.attname as "Column", x."Type", case x.attnotnull
when true then 'NOT NULL' else '' end as "NULL",
r.conname as "Constraint", r.contype as "C", r.consrc,
fn.nspname || '.' || f.relname as "F Key", d.adsrc as "Default"
FROM (SELECT c.oid, a.attrelid, a.attnum, n.nspname, c.relname,
a.attname, pg_catalog.format_type(a.atttypid, a.atttypmod) as "Type",
a.attnotnull FROM pg_catalog.pg_attribute a, pg_namespace n,
pg_class c WHERE a.attnum > 0 AND NOT a.attisdropped
AND a.attrelid = c.oid and c.relkind not in ('S','v')
and c.relnamespace = n.oid and n.nspname
not in ('pg_catalog','pg_toast','information_schema')) x
left join pg_attrdef d on d.adrelid = x.attrelid
and d.adnum = x.attnum left join pg_constraint r on r.conrelid = x.oid
and r.conkey[1] = x.attnum left join pg_class f on r.confrelid = f.oid
left join pg_namespace fn on f.relnamespace = fn.oid
where x.relname = 'credits' order by 1,2;

I'm not really sure what those queries do, since Sails seems to ignore the schema that's already in the database when generating table queries. Since we use the smallest, safest subset of the ORM we can find, I tried commenting out the sails-postgresql module code that makes those queries to see if the tests would still pass, and the tests did pass... but the load time was still slow.

The next step was to instrument the code to figure out what was taking so long. I wanted to have the Sails loader log the duration of each part of the load process, but this would have required a global variable, and a whole bunch of calls to console.log. It turns out the Unix function ts can do this for you, if log lines are generated at the appropriate times. Basically, it's an instant awesome tool for generating insight into a program's runtime, without needing to generate timestamps in the underlying tool.

NAME
       ts - timestamp input

SYNOPSIS
       ts [-r] [-i | -s] [format]

DESCRIPTION
       ts adds a timestamp to the beginning of each line of input.

I set the Sails logging level to verbose and piped the output through ts '[%Y-%m-%d %H:%M:%.S]'. I pretty quickly found a culprit..

[2015-04-19 21:53:45.730679] verbose: request hook loaded successfully.
[2015-04-19 21:53:45.731032] verbose: Loading the app's models and adapters...
[2015-04-19 21:53:45.731095] verbose: Loading app models...
[2015-04-19 21:53:47.928104] verbose: Loading app adapters...
[2015-04-19 21:53:47.929343] verbose: Loading blueprint middleware...

That's a 2 second gap between loading the models and loading the adapters.

I started adding profiling to the code near the "Loading app models..." line. I expected to see that attaching custom functions (findOne, update, etc) to the Sails models was the part that took so long. Instead I found out that a module called include-all accounted for almost all of the 2.5 seconds. That module simply requires every file in the models directory, about 30 files.

Further reading/logging revealed that each require call was being generated in turn. I've found it, I thought, just use different CPU's to require them all at the same time, and see a speedup. Unfortunately, the require operation is synchronous in Node, and runs on one CPU, so the process can still only perform one require at a time.

I tried just loading one model to see how slow that would be. This script took an average of 700 milliseconds to run, on my high end Macbook Pro:

var start = Date.now();
require('api/models/Drivers');
console.log(Date.now() - start);

700 milliseconds to require a model file, and that file's dependencies! I can send a packet to and from New York 8 times in that amount of time. What the hell is it actually doing? For this I turned to good old strace (or dtruss, as it's ported on Macs). First start up a shell to record syscalls for any process that is called node.

# (You'll want to kill any other node processes before running this.)
sudo dtruss -d -n 'node' > /tmp/require.log 2>&1

Open up another shell session and run your little script that calls require and prints the startup time and then exits. You should have a few thousand lines in a file called /tmp/require.log. Here's what I found near the start:

   1186335 stat64("/Users/burke/code/api/api/models/node_modules/async\0", 0x7FFF5FBFE608, 0x9)             = -1 Err#2
   1186382 stat64("/Users/burke/code/api/api/models/node_modules/async.js\0", 0x7FFF5FBFE5B8, 0x9)          = -1 Err#2
   1186405 stat64("/Users/burke/code/api/api/models/node_modules/async.json\0", 0x7FFF5FBFE5B8, 0x9)                = -1 Err#2
   1186423 stat64("/Users/burke/code/api/api/models/node_modules/async.node\0", 0x7FFF5FBFE5B8, 0x9)                = -1 Err#2
   1186438 stat64("/Users/burke/code/api/api/models/node_modules/async.coffee\0", 0x7FFF5FBFE5B8, 0x9)              = -1 Err#2
   1186473 open("/Users/burke/code/api/api/models/node_modules/async/package.json\0", 0x0, 0x1B6)           = -1 Err#2
   1186501 stat64("/Users/burke/code/api/api/models/node_modules/async/index.js\0", 0x7FFF5FBFE5B8, 0x1B6)          = -1 Err#2
   1186519 stat64("/Users/burke/code/api/api/models/node_modules/async/index.json\0", 0x7FFF5FBFE5B8, 0x1B6)                = -1 Err#2
   1186534 stat64("/Users/burke/code/api/api/models/node_modules/async/index.node\0", 0x7FFF5FBFE5B8, 0x1B6)                = -1 Err#2
   1186554 stat64("/Users/burke/code/api/api/models/node_modules/async/index.coffee\0", 0x7FFF5FBFE5B8, 0x1B6)              = -1 Err#2
   1186580 stat64("/Users/burke/code/api/api/node_modules/async\0", 0x7FFF5FBFE608, 0x1B6)          = -1 Err#2
   1186598 stat64("/Users/burke/code/api/api/node_modules/async.js\0", 0x7FFF5FBFE5B8, 0x1B6)               = -1 Err#2
   1186614 stat64("/Users/burke/code/api/api/node_modules/async.json\0", 0x7FFF5FBFE5B8, 0x1B6)             = -1 Err#2
   1186630 stat64("/Users/burke/code/api/api/node_modules/async.node\0", 0x7FFF5FBFE5B8, 0x1B6)             = -1 Err#2
   1186645 stat64("/Users/burke/code/api/api/node_modules/async.coffee\0", 0x7FFF5FBFE5B8, 0x1B6)           = -1 Err#2
   1186670 open("/Users/burke/code/api/api/node_modules/async/package.json\0", 0x0, 0x1B6)          = -1 Err#2
   1186694 stat64("/Users/burke/code/api/api/node_modules/async/index.js\0", 0x7FFF5FBFE5B8, 0x1B6)                 = -1 Err#2
   1186712 stat64("/Users/burke/code/api/api/node_modules/async/index.json\0", 0x7FFF5FBFE5B8, 0x1B6)               = -1 Err#2
   1186727 stat64("/Users/burke/code/api/api/node_modules/async/index.node\0", 0x7FFF5FBFE5B8, 0x1B6)               = -1 Err#2
   1186742 stat64("/Users/burke/code/api/api/node_modules/async/index.coffee\0", 0x7FFF5FBFE5B8, 0x1B6)             = -1 Err#2
   1186901 stat64("/Users/burke/code/api/node_modules/async\0", 0x7FFF5FBFE608, 0x1B6)              = 0 0
   1186963 stat64("/Users/burke/code/api/node_modules/async.js\0", 0x7FFF5FBFE5B8, 0x1B6)           = -1 Err#2
   1187024 stat64("/Users/burke/code/api/node_modules/async.json\0", 0x7FFF5FBFE5B8, 0x1B6)                 = -1 Err#2
   1187050 stat64("/Users/burke/code/api/node_modules/async.node\0", 0x7FFF5FBFE5B8, 0x1B6)                 = -1 Err#2
   1187074 stat64("/Users/burke/code/api/node_modules/async.coffee\0", 0x7FFF5FBFE5B8, 0x1B6)               = -1 Err#2
      1656 __semwait_signal(0x10F, 0x0, 0x1)                = -1 Err#60
   1187215 open("/Users/burke/code/api/node_modules/async/package.json\0"0x0, 0x1B6)              = 11 0

That's a lot of wasted open()'s, and that's just to find one dependency.² To load the single model, node had to open and read 300 different files,³ and every require which wasn't a relative dependency did the same find-the-node-module-folder dance. The documentation seems to indicate this is desired behavior, and it doesn't seem like there is any way around this.

Now, failed stat's are not the entire reason require is slow, but if I am reading the timestamps correctly in the strace log, they are a fair amount of it, and the most obviously wasteful thing. I could rewrite every require to be relative, e.g. require('../../node_modules/async') but that seems cumbersome and wasteful, when I can define the exact rule I want before hand: if it's not a relative file path, look in node_modules in the top level of my project.

So that's where we are; require for a single model takes 700 milliseconds, require for all the models takes 2.5 seconds, and there don't seem to be great options for speeding that up. There's some discouraging discussion here from core developers about the possibility of speeding up module import.

You are probably saying "load fewer dependencies", and you are right and I would love to, but that is not an option at this point in time, since "dependencies" basically equals Sails, and while we are trying to move off of Sails, we're stuck on it for the time being. Where I can, I write tests that work with objects in memory and don't touch our models/controllers, but Destroy All Software videos only get you so far.

I will definitely think harder about importing another small module vs. just copying the code/license wholesale into my codebase, and I'll definitely look to add something that can warn about unused imports or variables in the code base.

I'm left concluding that importing modules in Node is dog slow. Yes, 300 imports is a lot, but a 700ms load time seems way too high. Python imports can be slow, but as far as I remember, it's mostly for things that compile C on the fly, and for everything else you can work around it by rearranging sys.path to match the most imports first (impossible here). If there's anything I can do - some kind of compile option, or saving the V8 bytecode or something, I'm open to suggestions.

^{1. If you follow along with the somewhat-crazy convention of crashing your Node process on an error and having a supervisor restart it, that means that your server takes 6-9 seconds of downtime as well.}

^{2. The story gets even worse if you are writing Coffeescript, since require will also look for files matching .litcoffee and .coffee.md at every level. You can hack require.extensions to delete these keys.}

^{3. For unknown reasons, node occasionally decided not to stat/open some imports that were require'd in the file.}

Liked what you read? I am available for hire.