JavaScript в узле: непредвиденное поведение для console.timeEnd ()

Question

Я пытаюсь найти истекшее время в JavaScript. Наиболее распространенным подходом является использование console.time(label) и console.timeEnd(label).

Например, см .: { ссылка }

Это решение работает, если я попробую его на стороне клиента JavaScript, то есть

console.time('task');

setTimeout(end, 10);

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

печатает

finish: 11ms

, что является правильным истекшим временем.

Однако, когда я пытаюсь использовать тот же код в моем express приложении, работающем на Node, я получаю другой вывод:

finish: 30.714111328125ms
finish: 31.104ms

То есть console.timeEnd('task') печатает обе строки выше , Таким образом, он печатает время начала и время окончания, которое отличается от документации .

Вот мой код и вывод в консоль.

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

Это вывод, когда я не в режиме отладки:

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

Примечание: оба значения напечатаны на console.timeEnd(). Я проверил это, пройдя по каждой строке, то есть console.time ничего не регистрировал, а console.timeEnd зарегистрировал вывод в консоли. Я использую версию узла 12.16.1.

Почему я получаю разные результаты для одного и того же фрагмента кода?

Answer 1

Похоже, это проблема использования кода Visual Studio в режиме отладки.

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

и , с которыми мне приходится жить пока команда VS Code не решит что-то с этим сделать.

Я открыл новый выпуск в репозитории VS Code Github, в котором подробно описываются шаги для воспроизведения этого поведения.

Answer 2

После удаления всего постороннего кода построчно я выяснил причину без понимания. Если кто-нибудь может объяснить, почему это происходит, я отмечу это как ответ.

Проблема оказывается в моем файле bin/www, который выглядит следующим образом:

#!/usr/bin/env node

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

app.listen(3000);

Я настроил приложение, используя express-generator, в котором используется bin\www JavaScript файл для настройки приложения.

// 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;

Если я запускаю приложение без использования www, console.timeEnd() работает как положено.

Например, этот код работает нормально:

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 3

Мне удалось продемонстрировать оба ваших результата из ответа, который вы опубликовали.

Проблема в том, что вы используете .use() вместо .get() в своем определении маршрута:

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

Когда вы используете app.use("/", ...), это будет соответствовать ВСЕМ возможным маршрутам. Итак, когда вы впервые делаете версию www, вы получите два запроса от браузера:

/
/favicon.ico

Оба из них будут соответствовать app.use("/", ...). .use() соответствует любому маршруту, который начинается с того, что вы укажете.

---

Затем, когда вы удаляете www file из уравнения, вы все равно выполняете тот же код, КРОМЕ которого кэшируется браузером тот факт, что нет favicon.ico, поэтому он не запрашивает его. Если вы выполняете сменную перезагрузку для одной версии файла, это показывает ту же проблему, потому что браузер снова запрашивает favicon.ico, и вы получаете два запроса.

---

Измените это:

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

to:

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

и эта конкретная проблема исчезает в коде, который вы показываете во втором ответе. Я не знаю, почему вы изменили этот маршрут на app.use(), потому что раньше он был app.get(). Это было ясно для меня, когда я добавил это:

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

в начало обработчика маршрута. Вот где я ясно увидел запрос /favicon.ico, вызывающий дополнительный вывод.

Answer 4

Ну, в некоторых частях вашего кода должно быть что-то еще, что вы нам не показываете, потому что если я превращу ваш код в работающее приложение, просто добавив еще три строки в конце, как это, и изменив * От 1001 * до res.send(), поэтому нам не нужно настраивать шаблон и механизм шаблонов (для простоты примера):

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);

И затем я запрашиваю http://localhost в браузере, это все, что я вижу в консоли сервера:

finish: 11.708ms

только один из них.

Итак, что-то еще в коде, который вы нам не показываете, явно вызывает вашу проблему. Мне интересно, что в index.html? Есть ли какой-нибудь случайный Ajax вызов / или любые другие запросы ресурсов в этом HTML файле?

По-видимому, есть что-то еще, что делает еще один запрос к вашему серверу. Я бы посоветовал вам использовать этот маршрут, как показано ниже, чтобы доказать, что маршрут вызывается дважды:

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);