FAQ
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

--
Job board: http://jobs.nodejs.org/
New group rules: https://gist.github.com/othiym23/9886289#file-moderation-policy-md
Old group rules: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
---
You received this message because you are subscribed to the Google Groups "nodejs" group.
To unsubscribe from this group and stop receiving emails from it, send an email to nodejs+unsubscribe@googlegroups.com.
To post to this group, send email to nodejs@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/nodejs/etPan.53df23df.66334873.ec1b%40sierra.
For more options, visit https://groups.google.com/d/optout.

Search Discussions

  • Sindre Sorhus at Aug 4, 2014 at 5:02 pm
    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
    --
    Job board: http://jobs.nodejs.org/
    New group rules: https://gist.github.com/othiym23/9886289#file-moderation-policy-md
    Old group rules: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
    ---
    You received this message because you are subscribed to the Google Groups "nodejs" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to nodejs+unsubscribe@googlegroups.com.
    To post to this group, send email to nodejs@googlegroups.com.
    To view this discussion on the web visit https://groups.google.com/d/msgid/nodejs/a7851efb-9e59-4d93-895b-5e7451440921%40googlegroups.com.
    For more options, visit https://groups.google.com/d/optout.
  • Rebecca Turner at Aug 4, 2014 at 11:52 pm
    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

    --
    Job board: http://jobs.nodejs.org/
    New group rules: https://gist.github.com/othiym23/9886289#file-moderation-policy-md
    Old group rules: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
    ---
    You received this message because you are subscribed to the Google Groups "nodejs" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to nodejs+unsubscribe@googlegroups.com.
    To post to this group, send email to nodejs@googlegroups.com.
    To view this discussion on the web visit https://groups.google.com/d/msgid/nodejs/a7851efb-9e59-4d93-895b-5e7451440921%40googlegroups.com.
    For more options, visit https://groups.google.com/d/optout.

    --
    Job board: http://jobs.nodejs.org/
    New group rules: https://gist.github.com/othiym23/9886289#file-moderation-policy-md
    Old group rules: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
    ---
    You received this message because you are subscribed to the Google Groups "nodejs" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to nodejs+unsubscribe@googlegroups.com.
    To post to this group, send email to nodejs@googlegroups.com.
    To view this discussion on the web visit https://groups.google.com/d/msgid/nodejs/etPan.53e00c2c.2eb141f2.ec1b%40sierra.manhunt.local.
    For more options, visit https://groups.google.com/d/optout.
  • Maximilian Brosnahan at Aug 4, 2014 at 5:02 pm
    Awesome. Looks super handy.
    On Monday, 4 August 2014 18:15:44 UTC+12, 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
    --
    Job board: http://jobs.nodejs.org/
    New group rules: https://gist.github.com/othiym23/9886289#file-moderation-policy-md
    Old group rules: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
    ---
    You received this message because you are subscribed to the Google Groups "nodejs" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to nodejs+unsubscribe@googlegroups.com.
    To post to this group, send email to nodejs@googlegroups.com.
    To view this discussion on the web visit https://groups.google.com/d/msgid/nodejs/2690d2fb-5d14-4681-aeb5-61e5b50096b9%40googlegroups.com.
    For more options, visit https://groups.google.com/d/optout.

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
groupnodejs @
categoriesnodejs
postedAug 4, '14 at 6:15a
activeAug 4, '14 at 11:52p
posts4
users3
websitenodejs.org
irc#node.js

People

Translate

site design / logo © 2022 Grokbase