【问题标题】:How do I measure the execution time of JavaScript code with callbacks?如何使用回调测量 JavaScript 代码的执行时间?
【发布时间】:2012-05-23 22:17:45
【问题描述】:

我正在使用 node.js 解释器执行一段 JavaScript 代码。

for(var i = 1; i < LIMIT; i++) {
  var user = {
    id: i,
    name: "MongoUser [" + i + "]"
  };
  db.users.save(user, function(err, saved) {
    if(err || !saved) {
      console.log("Error");
    } else {
      console.log("Saved");
    }
  });
}

如何测量这些数据库插入操作所用的时间?我可以计算这段代码前后日期值的差异,但由于代码的异步性质,这是不正确的。

【问题讨论】:

  • 只读取db调用之前的开始时间,以及回调内部的结束时间..
  • 有可能DB完成插入的时间和回调执行的时间不一样,会导致测量出错?
  • 不,您不必担心,如果 db 库代码设计良好并且在触发回调之前没有处理任何其他操作,您应该得到一个很好的衡量标准。您还可以通过将时间戳放在实际执行插入的库代码中来分析插入,而不是您自己的,但是,我也不担心
  • 我建议您尝试NodeTime,这似乎很适合您尝试做的事情。
  • 我写了timerlog,它类似于console.time(),但有额外的功能; github.com/brillout/timerlog

标签: javascript node.js profiling


【解决方案1】:

使用 Node.js console.time()console.timeEnd()

var i;
console.time("dbsave");

for(i = 1; i < LIMIT; i++){
    db.users.save({id : i, name : "MongoUser [" + i + "]"}, end);
}

end = function(err, saved) {
    console.log(( err || !saved )?"Error":"Saved");
    if(--i === 1){console.timeEnd("dbsave");}
};

【讨论】:

  • 干净的内置节点解决方案。
  • >我想知道如何测量这些数据库插入操作所花费的时间。 --- console.timeEnd("dbsave") 只是输出控制台时间。您不能进一步使用它,而且灵活性较低。如果您需要实际的计时值,就像在原始问题中一样,您不能使用 console.timeEnd("dbsave")
  • 那么下面答案中的console.time() 和process.hrtime() 有什么区别?
  • 值得添加一个注释,然后打印出执行时间,以便现在新用户使用。
  • 仅供参考,计时器已被 timeEnd 杀死,因此您以后无法再次调用它,这是一个新的错误修复,曾经是一个意外功能。
【解决方案2】:

有一种为此设计的方法。查看process.hrtime();

所以,我基本上把它放在我的应用程序的顶部。

var start = process.hrtime();

var elapsed_time = function(note){
    var precision = 3; // 3 decimal places
    var elapsed = process.hrtime(start)[1] / 1000000; // divide by a million to get nano to milli
    console.log(process.hrtime(start)[0] + " s, " + elapsed.toFixed(precision) + " ms - " + note); // print message + time
    start = process.hrtime(); // reset the timer
}

然后我用它来查看函数需要多长时间。这是一个打印名为“output.txt”的文本文件内容的基本示例:

var debug = true;
http.createServer(function(request, response) {

    if(debug) console.log("----------------------------------");
    if(debug) elapsed_time("recieved request");

    var send_html = function(err, contents) {
        if(debug) elapsed_time("start send_html()");
        response.writeHead(200, {'Content-Type': 'text/html' } );
        response.end(contents);
        if(debug) elapsed_time("end send_html()");
    }

    if(debug) elapsed_time("start readFile()");
    fs.readFile('output.txt', send_html);
    if(debug) elapsed_time("end readFile()");

}).listen(8080);

这是一个可以在终端(BASH shell)中运行的快速测试:

for i in {1..100}; do echo $i; curl http://localhost:8080/; done

【讨论】:

  • 它在任何方面都优于 console.time 解决方案?
  • 是的,它更精确,您可以将结果存储在变量中
  • 这个对我有用,因为我想多次调用计时器
  • 为什么要给process.hrtime(start)打两次电话?有什么特别的原因吗?
  • process.hrtime([time]),其中 time 是一个可选参数,它必须是先前 process.hrtime() 调用的结果,以便与当前时间进行比较。它给出了当前调用和上一个 hrtime 调用之间的差异。
【解决方案3】:

调用console.time('label') 将以毫秒为单位记录当前时间,然后调用console.timeEnd('label') 将显示从该点开始的持续时间。

以毫秒为单位的时间将自动打印在标签旁边,因此您不必单独调用 console.log 来打印标签:

console.time('test');
//some code
console.timeEnd('test'); //Prints something like that-> test: 11374.004ms

有关详细信息,请参阅Mozilla's developer docs on console.time

【讨论】:

  • 这对the accepted answer 有什么好处?
  • @DanDascalescu 这比公认的答案更简洁、易读和易懂——其中充斥着嘈杂的“示例”代码。我个人更喜欢这个答案。
【解决方案4】:

很惊讶还没有人提到新的内置库:

在 Node >= 8.5 中可用,并且应该在 Modern 浏览器中

https://developer.mozilla.org/en-US/docs/Web/API/Performance

https://nodejs.org/docs/latest-v8.x/api/perf_hooks.html#

节点 8.5 ~ 9.x (Firefox, Chrome)

// const { performance } = require('perf_hooks'); // enable for node
const delay = time => new Promise(res=>setTimeout(res,time))
async function doSomeLongRunningProcess(){
  await delay(1000);
}
performance.mark('A');
(async ()=>{
  await doSomeLongRunningProcess();
  performance.mark('B');
  performance.measure('A to B', 'A', 'B');
  const measure = performance.getEntriesByName('A to B')[0];
  // firefox appears to only show second precision.
  console.log(measure.duration);
  // apparently you should clean up...
  performance.clearMarks();
  performance.clearMeasures();         
  // Prints the number of milliseconds between Mark 'A' and Mark 'B'
})();

https://repl.it/@CodyGeisler/NodeJsPerformanceHooks

节点 12.x

https://nodejs.org/docs/latest-v12.x/api/perf_hooks.html

const { PerformanceObserver, performance } = require('perf_hooks');
const delay = time => new Promise(res => setTimeout(res, time))
async function doSomeLongRunningProcess() {
    await delay(1000);
}
const obs = new PerformanceObserver((items) => {
    console.log('PerformanceObserver A to B',items.getEntries()[0].duration);
      // apparently you should clean up...
      performance.clearMarks();
      // performance.clearMeasures(); // Not a function in Node.js 12
});
obs.observe({ entryTypes: ['measure'] });

performance.mark('A');

(async function main(){
    try{
        await performance.timerify(doSomeLongRunningProcess)();
        performance.mark('B');
        performance.measure('A to B', 'A', 'B');
    }catch(e){
        console.log('main() error',e);
    }
})();

【讨论】:

【解决方案5】:

对于任何想要获取经过时间值而不是控制台输出的人:

使用process.hrtime() 作为@D.Deriso 的建议,下面是我更简单的方法:

function functionToBeMeasured() {
    var startTime = process.hrtime();
    // do some task...
    // ......
    var elapsedSeconds = parseHrtimeToSeconds(process.hrtime(startTime));
    console.log('It takes ' + elapsedSeconds + 'seconds');
}

function parseHrtimeToSeconds(hrtime) {
    var seconds = (hrtime[0] + (hrtime[1] / 1e9)).toFixed(3);
    return seconds;
}

【讨论】:

    【解决方案6】:
    var start = +new Date();
    var counter = 0;
    for(var i = 1; i < LIMIT; i++){
        ++counter;
        db.users.save({id : i, name : "MongoUser [" + i + "]"}, function(err, saved) {
              if( err || !saved ) console.log("Error");
              else console.log("Saved");
              if (--counter === 0) 
              {
                  var end = +new Date();
                  console.log("all users saved in " + (end-start) + " milliseconds");
              }
        });
    }
    

    【讨论】:

    • 我必须查看语法“+new Date()”才能弄清楚它的含义。根据 cmets 在这个答案 (stackoverflow.com/a/221565/5114) 上的说法,出于性能和可读性的原因,使用这种形式并不是一个好主意。我更喜欢一些更冗长的东西,这样对读者来说更清楚。另请参阅此答案:stackoverflow.com/a/5036460/5114
    • 我经常使用var start = process.hrtime(); ... var end = process.hrtime(start); 来获得高分辨率时间(如果我需要期望亚毫秒精度)
    【解决方案7】:

    老问题,但需要一个简单的 API 和轻量级解决方案;你可以使用perfy,它在内部使用高分辨率实时(process.hrtime)。

    var perfy = require('perfy');
    
    function end(label) {
        return function (err, saved) {
            console.log(err ? 'Error' : 'Saved'); 
            console.log( perfy.end(label).time ); // <——— result: seconds.milliseconds
        };
    }
    
    for (var i = 1; i < LIMIT; i++) {
        var label = 'db-save-' + i;
        perfy.start(label); // <——— start and mark time
        db.users.save({ id: i, name: 'MongoUser [' + i + ']' }, end(label));
    }
    

    请注意,每次调用 perfy.end(label) 时,都会自动销毁该实例。

    披露:写了这个模块,灵感来自D.Deriso's answer。文档here.

    【讨论】:

      【解决方案8】:

      你也可以试试exectimer。它会为您提供如下反馈:

      var t = require("exectimer");
      
      var myFunction() {
         var tick = new t.tick("myFunction");
         tick.start();
         // do some processing and end this tick
         tick.stop();
      }
      
      // Display the results
      console.log(t.timers.myFunction.duration()); // total duration of all ticks
      console.log(t.timers.myFunction.min()); // minimal tick duration
      console.log(t.timers.myFunction.max()); // maximal tick duration
      console.log(t.timers.myFunction.mean()); // mean tick duration
      console.log(t.timers.myFunction.median()); // median tick duration
      

      [edit] 现在有一种更简单的方式来使用 exectime。您的代码可以这样包装:

      var t = require('exectimer'),
      Tick = t.Tick;
      
      for(var i = 1; i < LIMIT; i++){
          Tick.wrap(function saveUsers(done) {
              db.users.save({id : i, name : "MongoUser [" + i + "]"}, function(err, saved) {
                  if( err || !saved ) console.log("Error");
                  else console.log("Saved");
                  done();
              });
          });
      }
      
      // Display the results
      console.log(t.timers.myFunction.duration()); // total duration of all ticks
      console.log(t.timers.saveUsers.min()); // minimal tick duration
      console.log(t.timers.saveUsers.max()); // maximal tick duration
      console.log(t.timers.saveUsers.mean()); // mean tick duration
      console.log(t.timers.saveUsers.median()); // median tick duration
      

      【讨论】:

        【解决方案9】:

        你可以试试Benchmark.js。它支持许多平台,其中还有 node.js。

        【讨论】:

        • 如果您可以添加一个如何在此用例中使用 benchmark.js 的示例,那就太好了。
        【解决方案10】:

        为此我设计了一个简单的方法,使用console.time() & console.timeEnd():

        测量函数定义
        function measureRunningTime(func,...args){
            const varToString = varObj => Object.keys(varObj)[0]
            const displayName = func.name || varToString({ func })
            console.time(displayName)
            func(...args)
            console.timeEnd(displayName)
        }
        
        

        要使用它,请传递一个不带参数、绑定参数或带参数作为以下参数的函数。

        示例:

        假设我想检查最简单的搜索算法的运行时间 - SimpleSearch:
        测量函数定义(你的代码在这里)
        const simpleSearch = (array = [1,2,3] ,item = 3) => {
            for(let i = 0; i< array.length; i++){
                if (array[i] === item) return i;
            }
            return -1
        }
        
        
        无参数实现
        measureRunningTime(simpleSearch) 
        //Prints something like that-> simpleSearch: 0.04ms
        
        使用 .bind() 实现参数
        const array = [1,2,3]
        const item = 3
        measureRunningTime(simpleSearch.bind(null, array, item))
        //Prints something like that-> bound simpleSearch: 0.04ms
        
        在不使用 .bind() 的情况下使用参数实现
        const array = [1,2,3]
        const item = 3
        measureRunningTime(simpleSearch, array, item)
        //Prints something like that-> simpleSearch: 0.04ms
        

        -> 注意!!这个实现远非完美——例如没有错误处理——但它可以用来检查简单算法的运行时间, 此外,我不是一个经验丰富的程序员,所以对一切都持保留态度??

        【讨论】:

          【解决方案11】:

          我从 AWS 迁移到 Azure 时遇到了同样的问题

          对于 express 和 aws,您已经可以使用现有的 time() 和 timeEnd()

          对于 Azure,请使用: https://github.com/manoharreddyporeddy/my-nodejs-notes/blob/master/performance_timers_helper_nodejs_azure_aws.js

          这些 time() 和 timeEnd() 使用现有的 hrtime() 函数,提供高分辨率的实时。

          希望这会有所帮助。

          【讨论】:

            【解决方案12】:

            您可以使用wrapper 函数轻松报告任何现有函数的执行时间。

            包装器用于扩展现有函数以在现有函数执行之前和之后执行某些操作 - 并且是组合逻辑的便捷方式。

            以下是使用withDurationReporting 包装器的示例:

            // without duration reporting
            const doSomethingThatMayTakeAWhile = async (someArg: string, anotherArg: number) => { 
              /** your logic goes here */
            }
            
            // with duration reporting
            const doSomethingThatMayTakeAWhileWithReporting = withDurationReporting(
              'doSomethingThatMayTakeAWhile', 
              doSomethingThatMayTakeAWhile
            );
            
            // note: you can define the function with duration reporting directly, too
            const doSomethingThatMayTakeAWhile = withDurationReporting(
              'doSomethingThatMayTakeAWhile', 
              async (someArg: string, anotherArg: number) => { 
                /** your logic goes here */
              }
            )
            

            这是包装器本身:

            import { hrtime } from 'process';
            
            const roundToHundredths = (num: number) => Math.round(num * 100) / 100; // https://stackoverflow.com/a/14968691/3068233
            
            /**
             * a wrapper which reports how long it took to execute a function, after the function completes
             */
            export const withDurationReporting = <R extends any, T extends (...args: any[]) => Promise<R>>(
              title: string,
              logic: T,
              options: {
                reportingThresholdSeconds: number;
                logMethod: (message: string, metadata?: Record<string, any>) => void;
              } = {
                reportingThresholdSeconds: 1, // report on anything that takes more than 1 second, by default
                logMethod: console.log, // log with `console.log` by default
              }, 
            ) => {
              return (async (...args: Parameters<T>): Promise<R> => {
                const startTimeInNanoseconds = hrtime.bigint();
                const result = await logic(...args);
                const endTimeInNanoseconds = hrtime.bigint();
                const durationInNanoseconds = endTimeInNanoseconds - startTimeInNanoseconds;
                const durationInSeconds = roundToHundredths(Number(durationInNanoseconds) / 1e9); // https://stackoverflow.com/a/53970656/3068233
                if (durationInSeconds >= options.reportingThresholdSeconds)
                  options.logMethod(`${title} took ${durationInSeconds} seconds to execute`, { title, durationInSeconds });
                return result;
              }) as T;
            };
            

            【讨论】:

              【解决方案13】:

              我需要它是累积的,并衡量不同的东西。
              构建了这些函数:

              function startMeasuring(key) {
                measureTimers[key] = process.hrtime();
              }
              
              function stopMeasuring(key) {
                if (!measures[key]) {
                  measures[key] = 0;
                }
              
                let hrtime = process.hrtime(measureTimers[key]);
                measures[key] += hrtime[0] + hrtime[1] / 1e9;
                measureTimers[key] = null;
              }
              

              用法:

              startMeasuring("first Promise");
              startMeasuring("first and second Promises");
              await new Promise((resolve) => {
                setTimeout(resolve, 1400);
              });
              stopMeasuring("first Promise");
              stopMeasuring("first and second Promises");
              
              startMeasuring("first and second Promises");
              await new Promise((resolve) => {
                setTimeout(resolve, 600);
              });
              stopMeasuring("first and second Promises");
              
              console.log("Measure Results", measures); 
              /*
              Measusre Results {
                setting: 0.00002375,
                'first Promise': 1.409392916,
                'first and second Promise': 2.015160376
              }
              */
              

              【讨论】:

                猜你喜欢
                • 2013-06-24
                • 2013-04-28
                • 1970-01-01
                • 1970-01-01
                • 2022-01-03
                • 1970-01-01
                • 2019-06-10
                • 1970-01-01
                相关资源
                最近更新 更多