JavaScript in Node: Unexpected behavior for console.timeEnd()

Question

I am trying to find the elapsed time in JavaScript. The most common approach suggested is to use console.time(label) and console.timeEnd(label).

For example, see: https://stackoverflow.com/a/18427652/5192528

This solution works if I try it on the client-side JavaScript, i.e.

console.time('task');

setTimeout(end, 10);

function end() {
  console.timeEnd('task');
}

prints

finish: 11ms

which is the correct time elapsed.

However, when I try the same code in my express app running on Node, I get a different output:

finish: 30.714111328125ms
finish: 31.104ms

That is, console.timeEnd('task') prints both the lines above. So it's printing the start time and end time, which is different from the documentation.

Here's my code and the output in the console.

const express = require("express");

let router = express.Router();

router.get("/", getAllPosts);

async function getAllPosts(req, res, next) {

    console.time('finish');

    setTimeout(end, 10);

    function end() {
        console.timeEnd('finish');
    }

    let posts = [];
    res.render("index", {
        posts,
        isLoggedIn: false
    });
}

// Output in Console (in debug mode):

finish: 15.8291015625ms
finish: 16.218ms

This is the output when I am not in debug mode:

node ./bin/www

express-session deprecated undefined resave option; provide resave option 
app.js:24:3
express-session deprecated undefined saveUninitialized option; provide 
saveUninitialized option app.js:24:3
app started on http://localhost:3000/
cntr = 1
GET / 304 26.882 ms - -
finish: 26.566ms
GET /stylesheets/style.css 304 4.196 ms - -
GET /javascripts/script.js 304 1.367 ms - -
GET /javascripts/file-upload.js 304 2.229 ms - -
GET /favicon.ico 200 3.718 ms - 15086

Note: both the values are printed on console.timeEnd(). I have verified this by stepping through each line, i.e. console.time didn't log anything, and console.timeEnd logged the output in the console. I am on node version 12.16.1.

Why am I getting different results for the same code snippet?

Answer 1

Looks like this is an issue with using Visual Studio Code in the Debug mode.

https://github.com/Microsoft/vscode/issues/38376

and something I have to live with till VS Code team decides to do something about it.

I have opened a new issue on VS Code's Github repository that details the steps to reproduce this behavior.