How to measure Event loop blocking in Nodejs?

Question

I can't get real an event loop blocking time. I have searched in Google answers (here), but they didn't help for me. I got different results.

I have created Node/Express app. And try to detect event loop blocking with different tools. I used hrtime, pm2, blocked_at.

1 test:

server.js

require('./routes')(app, passport, mongoData)

routes/index.js

router
  .get('/articles/:articleId(\\d+)', (req, res, next) => { 
      const blockedAt = require('blocked-at')
      blockedAt((time, stack) => {
         console.log(`Blocked for ${time}ms, operation started here:`, stack)
            },  {threshold:12})

      // my blocking script
      for (let i = 0; i <= 1000000000; i++) {
          let z = 10000 / Math.random()         
      }

      let ArticleController = require(path + 'app/controllers/ArticleController')
      let articleController = new ArticleController()
      articleController.index(req, res, next)
    })

I got:

Blocked for 15.5994921875ms, operation started here: [ ' at ', ' at ArticleService.getArticle (/app/services/article/ArticleService.js:79:44)' ] Blocked for 14.0350537109375ms, operation started here: [ ' at Promise.then ()', ' at ExpressHandlebars.render (node_modules/express-handlebars/lib/express-handlebars.js:157:8)', ' at ExpressHandlebars. (node_modules/express-handlebars/lib/express-handlebars.js:226:29)' ]

But nothing about my blocking script!

2 test:

With pm2:

• Event Loop Latency - 0.56ms
• Event Loop Latency p95 - 4.5ms

After remove my blocking script I get same results.

3 test:

With hrtime I measure inside ArticleController.index. Index method loads 3 services in async mode. There are a lot of I/O operations, and there works worker_threads. Some code created into setImmediate.

inside into index:

let hrstart = process.hrtime()

// there works all my services 
//...

let hrend = process.hrtime(hrstart)
 console.info('Execution time (hr): %ds ir ms: %dms', hrend[0], hrend[1] / 1000000)

res.render('home', data)

There I got 1s, 233ms. I got big time, but I confused - because there all operations work in async mode, Event loop ain't blocking?

How I can measure Event loop blocks?

I expect the output: "event loop blocking in routes/index.js:12 for 5000ms", but actual output doesn't catch my blocking script.

Answer 1

The amount of time you block the event loop is the amount of time you spend sequentially processing. Which for your example will be the body of that function. So you could just time that and add it on to a variable.

let totalBlocked = 0;

router
  .get('/articles/:articleId(\\d+)', (req, res, next) => { 
      const start = new Date().getTime();

      // my blocking script
      for (let i = 0; i <= 1000000000; i++) {
          let z = 10000 / Math.random() ;        
      }

      let ArticleController = require(path + 'app/controllers/ArticleController');
      let articleController = new ArticleController();
      articleController.index(req, res, next);

      const total = new Date().getTime() - start;
      totalBlocked += total;
      console.log(`Blocked for ${total}. Total blocked time is ${totalBlocked}`);
    });

You can also use the Node perf_hooks for high resolution timing.

const {performance } = require('perf_hooks');

let totalBlocked = 0;

router
  .get('/articles/:articleId(\\d+)', (req, res, next) => { 
      const start = performance.now();
      // Do stuff
      const total = performance.now() - start;
      totalBlocked += total;
      console.log(`Blocked for ${total}. Total blocked time is ${totalBlocked}`);
   });