Very slow task execution - hundreds of unnecessary system calls

[dexbg]

There is a several seconds delay before starting a gulp task (afterwards the task is executed in ms). When I check the system calls with "strace" I see hundreds of stat/open calls to files in the "/usr/lib/node_modules/gulp/node_modules/gulp-util" folder and its sub folders. It looks like enumeration of all files in the "gulp-util" folder which takes a lot of time making simple task execution to take several seconds instead of milliseconds.

[dashed]

What does your gulpfile.js look like?

[yocontra]

@dexbg That is probably just requires within gulp-util. I'll have to take a look at this

[dexbg]

Well, I tested with a simple one:
var gulp = require('gulp');
gulp.task('test', function() {});

strace -o log.txt gulp test

I noticed that for each additional required module the stat/open calls are duplicated - i.e. the same heavy traversal is done for each required module.

[yocontra]

@dexbg Just overhead of requiring gulp-util which then requires stuff internally. Each different version of gulp-util (plugins can use different ones) will do this. This will only happen on process launch

[dexbg]

So I guess it cannot be fixed? I'm using a lot of gulp modules (and I see that all of them internally use gulp-util) and I'm frequently running tasks (i.e. not using monitors) therefore the task execution is really slow.

[robrich]

gulp-utils is too big. I know I'll get blacklisted for not using it, but I really hesitate promoting it since it's so heavy.

[darsain]

I also dislike gulp-util being required by every plugin. It makes everything way slower that it has to be (initializations, npm installs, updates).

If it is absolutely necessary to have it, can't it just be part of gulp? I understand why it's decoupled, but isn't it doing more harm than good?

[sindresorhus]

Until anyone comes up with hard numbers this is all just speculation. I doubt requiring would noticeably slow down gulp. Use node-inspector or Adobe Theseus and do some real perf testing.

[sindresorhus]

I think everyone agrees gulp-util being bloated. It's just a temporary means to an end to make sure people don't do stupid things. We'll remove the requirement when we can automatically test compliance: https://github.com/gulpjs/acceptance

[dexbg]

I did the following test to measure just the plugins load time:

console.time("Loading plugins"); //start measuring
var gulp = require('gulp');
var concat = require('gulp-concat');
var uglify = require('gulp-uglify');
var csso = require('gulp-csso');
var clean = require('gulp-clean');
var changed = require('gulp-changed');
console.timeEnd("Loading plugins"); //end measuring
gulp.task('test', function() {}); //empty task

The results are (i.e. after executing "gulp test"):

Loading plugins: 2763ms
[gulp] Running 'test'...
[gulp] Finished 'test' in 45 ms

So almost 3 seconds are lost just for loading modules.

[sindresorhus]

For me Loading plugins: 232ms

Getting it consistently after many runs. Node 0.10.25 and OS X 10.9

console.time('Loading plugins');
var gulp = require('gulp');
var concat = require('gulp-concat');
var uglify = require('gulp-uglify');
var csso = require('gulp-csso');
var clean = require('gulp-clean');
var changed = require('gulp-changed');
console.timeEnd('Loading plugins');
gulp.task('default', function() {});

[callumlocke]

I just did a similar test (except I timed individual require calls to see which were the worst offenders), and most gulp plugins took > 500ms each, and I ran this several times to check the results were consistent, and they were consistent... But then about 5 minutes later, I ran the timer script again, and now each require call was now taking 0-30ms, and the whole thing completed instantly. I wonder what's going on there. (This was on separate node runs so it's not require caching.) This explains why gulp's startup time for me ranges from about 300ms to up to 20 seconds sometimes. I'm guessing it's some kind of OS-level caching (I'm on OS X Mavericks), but it's weird that it's so inconsistent.

[callumlocke]

I made a little snippet to easily time require calls in any Node project...

Just run $ node and paste this in:

var modules = require('fs').readdirSync('node_modules').filter(function (name) {return name !== '.bin'});
modules.forEach(function (m) {
  console.time(m);
  require(m);
  console.timeEnd(m);
});

Interestingly bluebird is by far the slowest to require in all my projects.

https://gist.github.com/callumlocke/9089019

[dexbg]

I think it will be good practice to require the specific modules inside the task in order to avoid unnecessary/slow require calls for unused modules:

//var csso = require('gulp-csso'); - i.e. avoid
gulp.task('default', function() {
    var csso = require('gulp-csso'); //i.e. internal
    return gulp.src('./main.css')
        .pipe(csso())
        .pipe(gulp.dest('./out'));
});

[yocontra]

Yes gulp-util is a piece of shit. No, I am not deprecating it until:

1. All of it's contents are split into modules
2. We have some kind of acceptance tests

As for the require times I don't really care and this isn't something I plan on fixing. I break my code up into tiny modules. This helps organization, testing, separation of concerns, etc. I'm not going to start inlining all of my shit into one file just to save a couple of disk reads.

[dexbg]

Well, as I can see from the strace log file most of the "unnecessary" stat/open file calls are made by the "lodash" module (e.g. lodash.template, lodash.defaults, lodash.keys ...). I think the real problem is in the big fragmentation of the lodash module itself and not in the gulp-utils.

[darsain]

I'd say the problem is every gulp plugin depending on gulp-util, creating a crazy dependency tree with gigantic waste.

I hoped that npm dedupe would help, but every time I try running it, the tree stays the same, and no optimizations nor nothing of consequence happens o.O ... dunno what's up with that.

Also the fact that people usually use ~ instead of ^ when declaring dependencies with major version higher than 0 wouldn't help dedupe do its job efficiently anyway :/

[yocontra]

@darsain Node modules always have insane dependency graphs. This isn't going to change. Even if I inlined all of the gulp-util shit into one file - it still has dependencies, and it's dependencies dependencies, etc.

This isn't a problem that can be solved by me. Overhead on process start for module loading is just something we have to deal with when using npm + node.

[dexbg]

I agree, the problem is exactly as @darsain wrote. Well, I see it is not gulp related.

[dalssoft]

This is the first time I heard require is the problem. It can be the problem if your required module is doing unnecessary work when loaded.

My scenario:
Host OS X 10.9.2
Guest (vagrant via NFS) precise32 / ubuntu

console.time('Loading plugins')
gulp    = require "gulp"
jade    = require "gulp-jade"
coffee  = require "gulp-coffee"
watch   = require "gulp-watch"
clean   = require "gulp-clean"
gettext = require "gulp-angular-gettext"
plumber = require "gulp-plumber"
less    = require "gulp-less"
ngmin   = require "gulp-ngmin"
console.timeEnd('Loading plugins')

For me, Loading plugins: 14653ms

Trying to find whats is wrong, I did a test with this:

console.time('Loading plugins')
gulp    = require "gulp"
console.timeEnd('Loading plugins')

And now we have Loading plugins: 993ms

It's pretty weird. It's taking almost 1s just to require "gulp". What's going on?

[tomasdev]

I bet it's something with your particular node / vm setup @dalssoft I just did the same on my Ubuntu (also vagrant via VirtualBox) and

$ gulp          
[gulp] Using file .../gulpfile.js
[gulp] Working directory changed to .../test
a: 0ms
[gulp] Running 'default'...
[gulp] Finished 'default' in 62 μs

And this is my gulpfile.js

console.time('a');
var gulp = require('gulp');
console.timeEnd('a');
gulp.task('default', []);                            

[yocontra]

This is just the side effect of a very deep dependency tree, this is not seen as a problem and won't be fixed. We are getting rid of gulp-util in gulp 4 anyways so this issue is barking up the wrong tree

[dalssoft]

We are getting rid of gulp-util in gulp 4 anyways

great news!

[robrich]

See also gulpjs/gulp-util#23

[sergeymorkovkin]

For me loading takes under a second:

console.time('Loading plugins');

var gulp = require('gulp'),
    minifyHtml = require('gulp-minify-html'),
    minifyCss = require('gulp-minify-css'),
    uglify = require('gulp-uglify'),
    concat = require('gulp-concat'),
    usemin = require('gulp-usemin');

console.timeEnd('Loading plugins');

Loading plugins: 716ms (Gulp 3.6.2)

What I've noticed is that when task finishes, the process is still busy for at least 2 seconds. Any clues what's happening?

[robrich]

Typically if you get "tasks finished" but node doesn't exit it's because you've not told gulp how to know when your async task is finished. See https://github.com/gulpjs/gulp/blob/master/docs/API.md#async-task-support.