[nodejs] Tracking module load times

Nice! I've used a similar one
before https://github.com/jaguard/time-require and it was very helpful in
improving the startup time of some of my CLI apps.

Oh, that's quite lovely! I somehow didn't see it when I was searching prior to starting the module.  I'm not sure why I missed it (other then that searching for more than one word with npm's search is... ah, let's say, less then ideal. ;)

They're different in some interesting ways:

* time-require is MUCH prettier, with its ansi, bar charts, configurable verbosity and sorting.

* require-timer shows your module loading time less any sub modules they load, as such, your top level script won't show up at as the slowest thing running. This are times when one is preferable to another of course.

* require-timer shows you the require stack, that is which modules loaded which modules. Where as time-require shows you the string that was passed to the require function, along with the full path of the file being loaded.

* require-timer is a little more machine friendly, not truncating its output, putting its data in fixed locations in the output line, and being able to direct its output to any stream.

* time-require hooks by monkey patching the _load method of the core module library. require-timer hooks by using the deprecated extensions system. YMMV as to which you find more distasteful. =p

-- Rebecca


On August 4, 2014 at 1:02:28 PM, Sindre Sorhus (sindresorhus@gmail.com) wrote:

Nice! I've used a similar one before https://github.com/jaguard/time-require and it was very helpful in improving the startup time of some of my CLI apps.

On Monday, August 4, 2014 8:15:44 AM UTC+2, Rebecca Turner wrote:
So for server software, trading longer startup times for shorter execution time is almost always a win. But for command line tools, this isn't true– when a program's startup becomes perceptible (at ~200-250ms) it begins to feel laggy.  Now, this raises the question: If my program is starting slowly, how do I track down the culprit? (Beyond "stop loading everything on npm at start!" =p) The profiler is useful for a lot of things, but in this case it'll just tell you that, yup, modile.compile and sync filesystem calls are taking all the time.

So I wrote a tool to provide this information.  I present to you:

https://www.npmjs.org/package/require-timer

Once loaded it tracks all require calls (including the one to load itself) and then, after your program completes, prints out a report to stderr (or whatever stream you specify).  The report tells you what led to each module being loaded, when it was loaded and how long it took to load (not including the modules it loaded).

So, for example, the first few lines from running it on npm:
   295.038 msec from start, 1.542 msec to load: cli.js
     1.322 msec from start, 1.322 msec to load: cli.js -> require-timer
   294.891 msec from start, 35.301 msec to load: cli.js -> bin/npm-cli.js
    35.164 msec from start, 3.728 msec to load: cli.js -> bin/npm-cli.js -> npmlog
    34.485 msec from start, 1.189 msec to load: cli.js -> bin/npm-cli.js -> npmlog -> ansi
    34.131 msec from start, 0.205 msec to load: cli.js -> bin/npm-cli.js -> npmlog -> ansi -> lib/newlines.js

Cheat sheet: The order is the order requires were called. The first number is when the rquire finished and the second number is how much time was spent doing stuff in that module besides loading other modules.

(It's implemented by hooking the now deprecated require.extensions, but its done in such a way that it's unlikely to run into anything *too* weird.)

-- Rebecca

Awesome. Looks super handy.