我想计算异步函数 (
async
/await
) 在 JavaScript 中花费了多长时间。
一个人可以做:
const asyncFunc = async function () {};
const before = Date.now();
asyncFunc().then(() => {
const after = Date.now();
console.log(after - before);
});
但是,这不起作用,因为 Promise 回调是在新的微任务中运行的。 IE。在
asyncFunc()
结束到 then(() => {})
开始之间,任何已经排队的微任务将首先被触发,并且它们的执行时间将被考虑在内。
例如:
const asyncFunc = async function () {};
const slowSyncFunc = function () {
for (let i = 1; i < 10 ** 9; i++) {}
};
process.nextTick(slowSyncFunc);
const before = Date.now();
asyncFunc().then(() => {
const after = Date.now();
console.log(after - before);
});
这在我的机器上打印
1739
,即几乎 2 秒,因为它等待 slowSyncFunc()
完成,这是错误的。
请注意,我不想修改
asyncFunc
的主体,因为我需要检测许多异步函数,而无需承担修改每个函数的负担。否则我可以在 Date.now()
的开头和结尾添加一个 asyncFunc
语句。
另请注意,问题不在于如何检索性能计数器。使用
Date.now()
、console.time()
、process.hrtime()
(仅限 Node.js)或 performance
(仅限浏览器)不会改变此问题的根源。问题在于 Promise 回调是在新的微任务中运行的。如果您在原始示例中添加诸如 setTimeout
或 process.nextTick
之类的语句,则您正在修改问题。
任何已经排队的微任务将首先被触发,并且它们的执行时间将被考虑在内。
是的,而且没有办法解决这个问题。如果您不想让其他任务对您的测量做出贡献,请不要对任何任务进行排队。这是唯一的解决办法。
这不是 Promise(或
async function
s)或微任务队列的问题,这是在任务队列上运行回调的 all 异步事物所共有的问题。
我们遇到的问题
process.nextTick(() => {/* hang 100ms */})
const asyncFunc = async () => {/* hang 10ms */}
const t0 = /* timestamp */
asyncFunc().then(() => {
const t1 = /* timestamp */
const timeUsed = t1 - t0 /* 110ms because of nextTick */
/* WANTED: timeUsed = 10ms */
})
解决方案(想法)
const AH = require('async_hooks')
const hook = /* AH.createHook for
1. Find async scopes that asycnFunc involves ... SCOPES
(by handling 'init' hook)
2. Record time spending on these SCOPES ... RECORDS
(by handling 'before' & 'after' hook) */
hook.enable()
asyncFunc().then(() => {
hook.disable()
const timeUsed = /* process RECORDS */
})
但这不会捕获第一个同步操作;即假设
asyncFunc
如下,$1$
不会添加到 SCOPES(因为它是同步操作,async_hooks 不会初始化新的异步范围),然后永远不会将时间记录添加到 RECORDS
hook.enable()
/* A */
(async function asyncFunc () { /* B */
/* hang 10ms; usually for init contants etc ... $1$ */
/* from async_hooks POV, scope A === scope B) */
await /* async scope */
}).then(..)
要记录这些同步操作,一个简单的解决方案是通过包装到
setTimeout
中强制它们在新的 ascyn 范围中运行。这个额外的东西确实需要时间来运行,忽略它,因为值很小
hook.enable()
/* force async_hook to 'init' new async scope */
setTimeout(() => {
const t0 = /* timestamp */
asyncFunc()
.then(()=>{hook.disable()})
.then(()=>{
const timeUsed = /* process RECORDS */
})
const t1 = /* timestamp */
t1 - t0 /* ~0; note that 2 `then` callbacks will not run for now */
}, 1)
请注意,解决方案是“测量异步函数涉及的同步操作所花费的时间”,异步操作例如超时空闲不计算在内,例如
async () => {
/* hang 10ms; count*/
await new Promise(resolve => {
setTimeout(() => {
/* hang 10ms; count */
resolve()
}, 800/* NOT count*/)
}
/* hang 10ms; count*/
}
// measurement takes 800ms to run
// timeUsed for asynFunc is 30ms
最后,我认为也许可以以包含同步和异步操作的方式来测量异步函数(例如可以确定 800ms),因为 async_hooks 确实提供了调度的详细信息,例如
setTimeout(f, ms)
,async_hooks 将初始化一个“Timeout”类型的异步作用域,调度细节ms
,可以在 resource._idleTimeout
的 init(,,,resource)
hook 中找到
演示(在nodejs v8.4.0上测试)
// measure.js
const { writeSync } = require('fs')
const { createHook } = require('async_hooks')
class Stack {
constructor() {
this._array = []
}
push(x) { return this._array.push(x) }
peek() { return this._array[this._array.length - 1] }
pop() { return this._array.pop() }
get is_not_empty() { return this._array.length > 0 }
}
class Timer {
constructor() {
this._records = new Map/* of {start:number, end:number} */
}
starts(scope) {
const detail =
this._records.set(scope, {
start: this.timestamp(),
end: -1,
})
}
ends(scope) {
this._records.get(scope).end = this.timestamp()
}
timestamp() {
return Date.now()
}
timediff(t0, t1) {
return Math.abs(t0 - t1)
}
report(scopes, detail) {
let tSyncOnly = 0
let tSyncAsync = 0
for (const [scope, { start, end }] of this._records)
if (scopes.has(scope))
if (~end) {
tSyncOnly += end - start
tSyncAsync += end - start
const { type, offset } = detail.get(scope)
if (type === "Timeout")
tSyncAsync += offset
writeSync(1, `async scope ${scope} \t... ${end - start}ms \n`)
}
return { tSyncOnly, tSyncAsync }
}
}
async function measure(asyncFn) {
const stack = new Stack
const scopes = new Set
const timer = new Timer
const detail = new Map
const hook = createHook({
init(scope, type, parent, resource) {
if (type === 'TIMERWRAP') return
scopes.add(scope)
detail.set(scope, {
type: type,
offset: type === 'Timeout' ? resource._idleTimeout : 0
})
},
before(scope) {
if (stack.is_not_empty) timer.ends(stack.peek())
stack.push(scope)
timer.starts(scope)
},
after() {
timer.ends(stack.pop())
}
})
// Force to create a new async scope by wrapping asyncFn in setTimeout,
// st sync part of asyncFn() is a async op from async_hooks POV.
// The extra async scope also take time to run which should not be count
return await new Promise(r => {
hook.enable()
setTimeout(() => {
asyncFn()
.then(() => hook.disable())
.then(() => r(timer.report(scopes, detail)))
.catch(console.error)
}, 1)
})
}
测试
// arrange
const hang = (ms) => {
const t0 = Date.now()
while (Date.now() - t0 < ms) { }
}
const asyncFunc = async () => {
hang(16) // 16
try {
await new Promise(r => {
hang(16) // 16
setTimeout(() => {
hang(16) // 16
r()
}, 100) // 100
})
hang(16) // 16
} catch (e) { }
hang(16) // 16
}
// act
process.nextTick(() => hang(100)) // 100
measure(asyncFunc).then(report => {
// inspect
const { tSyncOnly, tSyncAsync } = report
console.log(`
∑ Sync Ops = ${tSyncOnly}ms \t (expected=${16 * 5})
∑ Sync&Async Ops = ${tSyncAsync}ms \t (expected=${16 * 5 + 100})
`)
}).catch(e => {
console.error(e)
})
结果
async scope 3 ... 38ms
async scope 14 ... 16ms
async scope 24 ... 0ms
async scope 17 ... 32ms
∑ Sync Ops = 86ms (expected=80)
∑ Sync&Async Ops = 187ms (expected=180)
考虑使用 perfrmance.now() API
var time_0 = performance.now();
function();
var time_1 = performance.now();
console.log("Call to function took " + (time_1 - time_0) + " milliseconds.")
由于
performance.now()
是 console.time
的基本版本,因此它提供更准确的计时。
这个问题解决了吗?我一直在关注这个问题。
您可以使用
console.time('nameit')
和 console.timeEnd('nameit')
检查下面的示例。
console.time('init')
const asyncFunc = async function () {
};
const slowSyncFunc = function () {
for (let i = 1; i < 10 ** 9; i++) {}
};
// let's slow down a bit.
slowSyncFunc()
console.time('async')
asyncFunc().then((data) => {
console.timeEnd('async')
});
console.timeEnd('init')