我想获取浏览器(Chrome)环境下一整段 JavaScript 代码中每一小段代码精确的执行时间,使用了三种计算方式:
1.console.time、console.timeEnd 配合使用
2.console.log(new Date().getTime())
3.console.log(performance.now())
但是这两种方式计算出来的时间都和我“观察感觉到的时间”有所差异,实际使用断点进行 debug 时也有同样的感觉。
debug 时感觉每小段代码的耗时和感觉一致:代码循环和递归多的地方耗时长,一两行的地方耗时短,使用上述三种计算方式时会出现:本应该耗时长的代码段算出来的时间短、本应该耗时很短的地方显示的时间很长的情况,甚至出现了两个连在一起的 console 计算出来的时间差了 500ms,例如:
// 前面的代码,省略
......
// 中间某段代码
console.log("calcBefore", performance.now())
// 一个有很多循环和递归计算的代码
calculate()
console.log("calcAfter1", performance.now())
console.log("calcAfter2", performance.now())
console.log("calcAfter3", performance.now())
console.log("calcAfter4", performance.now())
// 后面的代码,省略
......
// 打印结果
calcBefore 573.499999998603
calcAfter1 633.2000000038533
calcAfter2 1221.1999999999534
calcAfter3 1222.6000000009662
calcAfter4 1223.5000000000582
搜了一下,没有发现很多相关资料,只有知乎的一篇文章:https://zhuanlan.zhihu.com/p/28978126 描述了类似的事情。
恳请前端大佬解惑!!!
更正:“这两种方式”应该为“这三种方式”,之前写的时候没有使用Performance API,但是结果是同样的不准确。
这个问题可以稳定复现,今天早上重启项目之后依然在这里有同样的时间消耗,如下图:
console.log("calcBefore", performance.now())
calculate()
console.log("calcAfter1", performance.now())
console.log("calcAfter2", performance.now())
// console
calcBefore 1134.9999999947613
calcAfter1 1214.80000000156
calcAfter2 1878.7000000011176
console.log("calcBefore", performance.now())
//calculate()
console.log("calcAfter1", performance.now())
console.log("calcAfter2", performance.now())
// console
calcBefore 669.3999999988591
calcAfter1 671.6000000014901
calcAfter2 672.5000000005821
1
noe132 2018-08-07 21:35:16 +08:00
有一种可能,v8 会对比较热门(popular)的代码做优化编译(Crankshaft),会将用的多的 JS 代码块进行优化,编译出效率更高的二进制代码执行。这是一个 runtime 执行的功能,有可能会影响接下来一部分代码的执行性能。
http://jayconrod.com/posts/54/a-tour-of-v8--crankshaft--the-optimizing-compiler 建议做性能基准测试时,先让代码多跑几个循环,让代码被优化后,再进行基准测试,以减小误差,jsPref 用的 benchmark.js 是这样做的。 https://stackoverflow.com/questions/4986245/how-does-jsperf-work |
2
noe132 2018-08-07 21:37:37 +08:00
gc 也有可能影响下一步操作的时间,因为 gc 也是需要暂停 js 的主线程的,尤其是在做全量 gc 的时候。能影响的因素还是比较多。
|
3
xiaody 2018-08-07 21:38:13 +08:00
能稳定复现吗?代码内存使用情况怎么样,会不会是遇到 GC 了?
|
4
tmxklzp OP @noe132 谢谢科普!对 v8 引擎和 GC 这方面的知识我了解得不够深入,后续会去深入研究。另外能否对上述这一个问题提出一下您的想法:两个连在一起的 console 即 calcAfter1 和 calcAfter2,为何稳定出现相差 500~600ms 的情况?如果是 GC 的话每次到这一步都会进行吗?
@xiaody 我对于何时会出现 GC 不太清楚,已知的就是 calculate() 这一行内部会有一个大循环和很多次递归,去掉这一行之后 console 时间正常,有可能会是因为在这里计算时占用了大量内存,然后在 calcAfter1 时显示正确的 calculate()调用时间,却在下一行 calcAfter2 时进行了 GC,导致了 600ms 左右的性能损耗吗? |
5
tmxklzp OP 另外就是 debug 的话,会明显感觉到这个 600ms 的时间消耗是在 calculate()这一行产生的,后面的 console 并不会有 debug 时的卡顿感。这也是我在问题描述里表达的“ console 计算出来的时间和我打断点&感觉出来的时间不一致”
|
6
tmxklzp OP 问 jjc 大佬得到的回复:“凡是带有 gc 和 jit 的 runtime,统计都会不准确”
|