Slow task execution when using gulp.watch with large tasks

[shrink]

[Edit: added a better example as a comment below]

I have a project with a lot of images, I have a gulp task (images) for processing these images that takes 9 seconds to copy the images to a new folder. I have a gulp task called watch that listens for various changes throughout the project and triggers corresponding tasks:

// run phpunit
gulp.task('tests', function() {
  return gulp.src('./app/tests/*.php')
    .pipe(phpunit('/usr/bin/phpunit'));
});

// move all images to the assets dir
gulp.task('images', function () {
  return gulp.src('app/assets/website/images/**/*')
    .pipe(gulp.dest('public/assets/img'));
});

// watch for changes in files and run corresponding tests
gulp.task('watch', function () {
  gulp.watch('app/**/*.php', ['tests']);
});

I run gulp watch and change app/file.php, the task tests (triggered by the watcher) runs as expected and takes ~1 second to complete.

I then update the watch task to include a watcher for the images directory that triggers the images task:

gulp.task('watch', function () {
  gulp.watch('app/assets/website/images/**/*', ['images']);
  gulp.watch('app/**/*.php', ['tests']);
});

Now I change app/file.php again and this time the task tests (triggered by the watcher) takes 10 seconds to run.

If I run gulp tests it completes in 1 second
If I run gulp watch with only a watcher for tests, when a change is detected tests completes in 1 second
If I run gulp watch with a watcher for images, when a change is detected tests completes in 10 seconds.

Any ideas would could be causing this? Bug? Intentional? PEBCAK?

(note: I have tried this with various different tasks in place of tests, the same behaviour happens if I run a task for compiling less, concatenating javascript etc)

The exact gulpfile.js that has this behaviour is as follows:

var gulp        = require('gulp');
var gutil       = require('gulp-util');
var less        = require('gulp-less');
var autoprefix  = require('gulp-autoprefixer');
var minifycss   = require('gulp-minify-css');
var uglify      = require('gulp-uglify');
var include     = require('gulp-include');
var concat      = require('gulp-concat');
var phpunit     = require('gulp-phpunit');
var fs          = require('fs');

gulp.task('images', function () {
  return gulp.src('app/assets/website/images/**/*')
    .pipe(gulp.dest('public/assets/img'));
});

gulp.task('tests', function() {
  return gulp.src('./app/tests/*.php')
    .pipe(phpunit('/usr/bin/phpunit'));
});
gulp.task('watch', function () {
    gulp.watch('app/assets/website/images/**/*', ['images']);
    gulp.watch('app/**/*.php', ['tests']);
});

Thanks!

[shrink]

Here is a better example that doesn't involve any plugins and is easy to reproduce:

1. Create style.css
2. Create images/ and place 500 images in the directory (~1mb of images)
3. Create gulpfile.js with the following:

var gulp        = require('gulp');
var gutil       = require('gulp-util');
var minifycss   = require('gulp-minify-css');

gulp.task('images', function () {
    return gulp.src('images/**/*')
        .pipe(gulp.dest('images-moved'));
});
gulp.task('css', function() {
    return gulp.src('style.css')
        .pipe(gulp.dest('style-moved'));
});
gulp.task('watch', function () {
    // gulp.watch('images/**/*', ['images']);
    gulp.watch('style.css', ['css']);
});

Run gulp watch:

$ gulp watch
[gulp] Using file /vagrant/gulpfile.js
[gulp] Working directory changed to /vagrant
[gulp] Running 'watch'...
[gulp] Finished 'watch' in 19 ms

Modify style.css:

[gulp] Running 'css'...
[gulp] Finished 'css' in 18 ms

Terminate gulp watch and enable the images watcher in gulpfile.js:

gulp.task('watch', function () {
    gulp.watch('images/**/*', ['images']);
    gulp.watch('style.css', ['css']);
});

Run gulp watch:

$ gulp watch
[gulp] Using file /vagrant/gulpfile.js
[gulp] Working directory changed to /vagrant
[gulp] Running 'watch'...
[gulp] Finished 'watch' in 1.58 min

Modify style.css:

[gulp] Running 'css'...
[gulp] Finished 'css' in 654 ms

The execution time of the css task when triggered by the watcher has now increased from 19ms to 650ms, the only difference is that the watch task now contains a watcher for the images folder, running the task directly is still fast:

$ gulp css
[gulp] Using file /vagrant/gulpfile.js
[gulp] Working directory changed to /vagrant
[gulp] Running 'css'...
[gulp] Finished 'css' in 16 ms

[yocontra]

How large is the folder tree inside the images folder?

[shrink]

The example above used 500 images at one level (images/1.png, images/2.png etc) and in my real world case there is 100 images split across 2 sub-folders:

images
|-- icons
|   |-- android1.svg
|   |-- android.svg
|   |-- app-store.svg
|   |-- arrow.svg
|   |-- art.svg
|   |-- bag.svg
|   |-- basket.svg
|   |-- book.svg
|   |-- bowling.svg
|   |-- box.svg
|   |-- brush.svg
|   |-- building.svg
|   |-- bulb.svg
|   |-- button.svg
|   |-- calculator.svg
|   |-- calendar.svg
|   |-- camera.svg
|   |-- card.svg
|   |-- car.svg
|   |-- chair.svg
|   |-- chat.svg
|   |-- clipboard.svg
|   |-- clocks.svg
|   |-- compas.svg
|   |-- converse.svg
|   |-- cup.svg
|   |-- dj.svg
|   |-- donut.svg
|   |-- dude.svg
|   |-- dynamite.svg
|   |-- earth.svg
|   |-- egg.svg
|   |-- eye.svg
|   |-- file.svg
|   |-- fit.svg
|   |-- flag.svg
|   |-- flask.svg
|   |-- flower.svg
|   |-- games.svg
|   |-- gift-box.svg
|   |-- girl.svg
|   |-- goal.svg
|   |-- google .svg
|   |-- graph.svg
|   |-- icecream.svg
|   |-- imac.svg
|   |-- ipad.svg
|   |-- iphone.svg
|   |-- key.svg
|   |-- lettersymbol.svg
|   |-- lock.svg
|   |-- loop.svg
|   |-- macbook.svg
|   |-- magicmouse.svg
|   |-- magic.svg
|   |-- mail.svg
|   |-- map.svg
|   |-- medal.svg
|   |-- mic.svg
|   |-- money.svg
|   |-- mortarboard.svg
|   |-- mountain.svg
|   |-- news.svg
|   |-- paper-bag.svg
|   |-- pc.svg
|   |-- pencils.svg
|   |-- pencil.svg
|   |-- picture.svg
|   |-- pig.svg
|   |-- pills.svg
|   |-- play.svg
|   |-- printer.svg
|   |-- responsive.svg
|   |-- retina.svg
|   |-- ring.svg
|   |-- rocket.svg
|   |-- rss.svg
|   |-- safe.svg
|   |-- save.svg
|   |-- search.svg
|   |-- settings.svg
|   |-- shield.svg
|   |-- shirt.svg
|   |-- skateboard.svg
|   |-- spray.svg
|   |-- storage.svg
|   |-- support.svg
|   |-- ticket.svg
|   |-- toilet-paper.svg
|   |-- touch.svg
|   |-- trash.svg
|   |-- trip-bag.svg
|   |-- trunk.svg
|   |-- ubmrella.svg
|   |-- user-interface.svg
|   |-- video.svg
|   |-- weather.svg
|   |-- wi-fi.svg
|   |-- wine.svg
|   `-- yinyang.svg
`-- switch
    |-- mask.png
    `-- mask-square.png

[yocontra]

@shama does gaze start globbing immediately or does it nextTick that process? It looks like starting a watch blocks the main thread

[shama]

Immediately but we could push it to nextTick if you think it would help.

[yocontra]

@shama The internals of watch should also be setImmediate/nextTick-ing to not block the event loop for extended periods of time - I'll take a look at the code and see if I can find some trouble points

[yocontra]

Benchmarks: shama/gaze#79

[shama]

It looks like this will be yet another thing fixed in the next version of gaze. The current version does a lot of fs traversing where the next version avoids it whenever it can. See this comment: shama/gaze#79 (comment)

[yocontra]

Since this is a gaze issue I will close this. When @shama releases the next version of gaze, this problem will be fixed.