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.

Answer 2

Well, there has to be something else going on in parts of your code that you don't show us because if I make your code into a working app by just adding three more lines at the end like this and changing the res.render() to a res.send() so we don't have to have a template and template engine configured (for simplicity of the example):

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.send("hello");
}

const app = express();
app.use(router);
app.listen(80);

And, then I request http://localhost in the browser, this is all I see in the server console:

finish: 11.708ms

There's just one of them.

So, something else in the code you don't show us is apparently causing your issue. I am wondering what's in index.html? Is there by any chance an Ajax call to / or any other resource requests in that HTML file?

Apparently, there is something else that is making another request to your server. I'd suggest you instrument that route like I show below to just prove that the route is getting called twice:

const express = require("express");

let router = express.Router();

router.get("/", getAllPosts);

let cntr = 1;                                        // add this
async function getAllPosts(req, res, next) {

    console.log(`cntr = ${cntr++}`);                 // add this

    console.time('finish');

    setTimeout(end, 10);

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

    let posts = [];
    res.send("hello");
}

const app = express();
app.use(router);
app.listen(80);

Answer 3

After removing all my extraneous code line by line, I finally figured out the cause, without the understanding. If anyone can explain why it's happening, I will mark it as the answer.

The problem turns out to be in my bin/www file, which looks like this:

#!/usr/bin/env node

var app = require("../app");

app.listen(3000);

I set up the app using express-generator, which use bin\www JavaScript file to configure the app.

// app.js

var express = require("express");

var app = express();

app.use("/", function getAllPosts(req, res, next) {

  console.time('finish');

  setTimeout(end, 10);

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

  res.send("hello");
});

module.exports = app;

If I run the app without using www, console.timeEnd() works as expected.

For example, this code works fine:

var express = require("express");

var app = express();

app.use("/", function getAllPosts(req, res, next) {

  console.time('finish');

  setTimeout(end, 10);

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

  res.send("hello");
});

app.listen(3000);

Answer 4

I was able to demonstrate both of your outcomes from the answer you posted.

The issue is that you're using .use() instead of .get() in your route definition:

app.use("/", function getAllPosts(req, res, next) {...}

When you use app.use("/", ...), that will match ALL possible routes. So, when you first do the www version, you will get two requests from the browser:

/
/favicon.ico

Both of those will match app.use("/", ...). .use() matches any route that starts with what you specify.

---

Then, when you remove the www file from the equation, you're still executing the exact same code EXCEPT that the browser has cached the fact that there's no favicon.ico so it doesn't request it. If you do a shift reload on the single file version, it shows the same problem because the browser again requests the favicon.ico and you get two requests.

---

Change this:

app.use("/", function getAllPosts(req, res, next) {...}

to:

app.get("/", function getAllPosts(req, res, next) {...}

and this particular problem goes away in the code you show in your 2nd answer. I don't know why you changed this route to app.use() because you used to have it as app.get(). This was clear to me when I added this:

console.log("in route", req.url);

to the start of the route handler. That's where I clearly saw the /favicon.ico request causing the extra output.