Node.js の Async Hooks API の動作を検証しました

必要に迫られて、Node.js の Async Hooks API について調べたので、その仕組を実例を用いて説明します。

Async Hooks とは?

Node.js の Stability: 1 - Experimental (2019/12/30 現在) な機能です。
主に 非同期呼出を追跡する のに使われています。例えば以下の様な NPM Module が Async Hooks を使っています。

• trace → 非同期呼出で途切れる Stack trace を繋げて表示する
• express-http-context → リクエスト毎に異なるコンテキストに値を保存/取得する express middleware

対象読者

事前に Node.jsでのイベントループの仕組みとタイマーについて について知っておくことをオススメします。

動作環境

本記事は以下の環境で試しています。

• Mac OS 10.13.6
• Node.js v12.13.0

私は nodebrew を使っています。

nodebrew binary-install v12.13.0
nodebrew use v12.13.0

コード

記事で書くコードそのものが↓です。

• https://github.com/megmogmog1965/asynchooks-examples

Async Hooks の概要

公式の Node.js >> Async Hooks >> Overview の通りですが、実際に動かして見ないとドキュメントだけ読んでも分かりづらいです。まずはざっくり概要です。

Async Hooks 自体は、以下の様に async_hooks.createHook() するだけで使えます。

const async_hooks = require('async_hooks');

// 現在 (↓が実行されてる瞬間) の Async ID を取得できます。
const eid = async_hooks.executionAsyncId();

// Async Hook を生成します。
// ここで渡した４つの callback functions が、非同期呼び出しの際に呼ばれる様になります。
const asyncHook = async_hooks.createHook({
  init,
  before,
  after,
  destroy,
});

// 有効にしないと callback functions が呼ばれません。
asyncHook.enable();

前述の async_hooks.createHook() に渡した４つの callback functions は自由に実装できます。
今回は、確認の為に、呼出の際の引数値を Array に保存しておく様にしました。

// [init] setTimeout() 等の非同期処理 (callback function) の登録をした時に呼ばれます。
function init(asyncId, type, triggerAsyncId, resource) {
  // Promise による callback task 登録の場合、Promise オブジェクト自身が来るので、
  // ちゃんと GC されるように参照保持しないようにします。
  arguments[3] = resource.constructor.name === 'PromiseWrap' ? resource.toString() : resource;

  historyInit.push(arguments);
}

// [before] 登録した callback function が実行される「直前」に呼ばれます。
function before(asyncId) {
  historyBefore.push(asyncId);
}

// [after] 登録した callback function が実行された「後」に呼ばれます。
function after(asyncId) {
  historyAfter.push(asyncId);
}

// [destroy] 非同期リソースが破棄 (≒登録した非同期処理の完了) された時に呼ばれます。
function destroy(asyncId) {
  historyDestroy.push(asyncId);
}

// Async Hooks の動作確認の為に、init, before, after, destroy 呼出の際の引数値をここ↓に保存しておきます。
const historyInit = [];
const historyBefore = [];
const historyAfter = [];
const historyDestroy = [];

この状態で setTimeout() 等を実行すると、 init, before, after, destroy callback functions が順に呼ばれるようになります。

init, before, after, destroy の定義

時系列

API setInterval での例です。

init

非同期 API (setTimeout, Promise 等) を実行した瞬間に呼ばれます。

別の言い方をすると、非同期処理 (callback functions) が event queue に登録された時です。

• １度だけ 必ず 呼ばれます

引数名	型	説明
asyncId	Number	分岐元 (親) の Async ID
type	String	Timeout, PROMISE 等の識別子が来ます。resource の名称です。
triggerAsyncId	Number	分岐元 (親) の Async ID
resource	Object	実行した非同期処理の情報。Promise の場合、promise object 自身が来るので、参照保持で GC を阻害しないように注意。

before

登録した callback function が実行される 直前 に呼ばれます。

• 一度も呼ばれない事があります 例えば net.createServer で Socket listen していても、接続がなければ callback 実行されません
• setInterval 等、一度の callback 登録で before は 複数回 呼ばれる事があります

引数名	型	説明
asyncId	Number	分岐元 (親) の Async ID

after

登録した callback function が実行された 後 に呼ばれます。

• before と同様に、 一度も呼ばれない もしくは 複数回 呼ばれる事があります
• callback で例外が発生し catch されなかった場合、 uncaughtException event もしくは handler 実行の後に、after が呼ばれます

引数名	型	説明
asyncId	Number	分岐元 (親) の Async ID

destroy

非同期リソース resource　が 破棄 (≒登録した非同期処理の完了) された時に 一度だけ 呼ばれます。

具体的にいつ呼ばれるかはまちまちで、例えば Promise の場合は promise object が GC により破棄された際に呼ばれます

引数名	型	説明
asyncId	Number	分岐元 (親) の Async ID

Examples

ドキュメントを読んだだけでは、init, before, after, destroy callback functions がそれぞれ、どのタイミングで、何回呼ばれるのか、よく分かりません。

実際に実行して試してみます。

下準備

前述のコードをファイル名 register-hook.js とし、以下の Debug Print 関数を module.exports します。

わざと setTimeout で表示処理を非同期実行してます。

register-hook.js

const async_hooks = require('async_hooks');

const asyncHook = async_hooks.createHook({ init, before, after, destroy });
asyncHook.enable();

// ...
// 省略...
// ...

/**
 * async_hooks で取得した非同期呼び出しの履歴を表示します.
 */
module.exports = function () {
  // 表示処理が呼出元とは異なる event task として実行される様、setTimeout する. (event queue に入れておく)
  setTimeout(function printHistory() {
    const [init, before, after, destroy]
      = [[...historyInit], [...historyBefore], [...historyAfter], [...historyDestroy]];

    console.log('FirstExecutionAsyncId: ', eid, '\n');
    console.log('async_hook calls: init: ', init, '\n');
    console.log('async_hook calls: before: ', before, '\n');
    console.log('async_hook calls: after: ', after, '\n');
    console.log('async_hook calls: destroy: ', destroy, '\n');
  }, 10);
}

(1) setTimeout で Async Hooks

まずは Async Hooks を有効にした状態で setTimeout を呼ぶとどうなるか見てみます。

index_setTimeout.js

const printHistory = require('./register-hook');

function _01_SetTimeoutCallbackFunction() {
  printHistory(); // ← setTimeout 経由で console.log する.
}

setTimeout(_01_SetTimeoutCallbackFunction);

以下の様に printHistory() で出力されます。

FirstExecutionAsyncId:  1 

async_hook calls: init:  [
  [Arguments] {
    '0': 2,
    '1': 'Timeout',
    '2': 1,
    '3': Timeout {
      _idleTimeout: 1,
      _idlePrev: null,
      _idleNext: null,
      _idleStart: 44,
      _onTimeout: [Function: _01_SetTimeoutCallbackFunction],
      _timerArgs: undefined,
      _repeat: null,
      _destroyed: true,
      [Symbol(refed)]: null,
      [Symbol(asyncId)]: 2,
      [Symbol(triggerId)]: 1
    }
  },
  [Arguments] {
    '0': 3,
    '1': 'Timeout',
    '2': 2,
    '3': Timeout {
      _idleTimeout: 10,
      _idlePrev: null,
      _idleNext: null,
      _idleStart: 46,
      _onTimeout: [Function: printHistory],
      _timerArgs: undefined,
      _repeat: null,
      _destroyed: false,
      [Symbol(refed)]: true,
      [Symbol(asyncId)]: 3,
      [Symbol(triggerId)]: 2
    }
  }
] 

async_hook calls: before:  [ 2, 3 ] 

async_hook calls: after:  [ 2 ] 

async_hook calls: destroy:  [ 2 ] 

エントリファイルの index_setTimeout.js が実行された直後の Async ID は 1 です

init は２回呼ばれています。

１回目は setTimeout(_01_SetTimeoutCallbackFunction) (id=2) で、 index_setTimeout.js ファイル自身 (id=1) からトリガーされた非同期タスクである事が分かります。

２回目は setTimeout(printHistory) (id=3) で、先程の setTimeout(_01_SetTimeoutCallbackFunction) (id=2) からトリガーされた非同期タスクである事が分かります。

before は２回呼ばれています。

function _01_SetTimeoutCallbackFunction (id=2) と printHistory (id=3) が呼出されたからです

after は１回呼ばれています。

function _01_SetTimeoutCallbackFunction (id=2) の実行は完了したが、 printHistory (id=3) はまだ途中だからです

destroy は１回呼ばれています。

function _01_SetTimeoutCallbackFunction (id=2) の破棄は完了したが、 printHistory (id=3) はまだ実行途中で破棄されてないからです

(2) setInterval で Async Hooks

次に Async Hooks を有効にした状態で setInterval を呼ぶとどうなるか見てみます。

index_setInterval.js

const printHistory = require('./register-hook');

let count = 0;

function _01_SetIntervalCallbackFunction() {
  if (++count > 10) {
    clearInterval(intervalID);
    printHistory(); // ← setTimeout 経由で console.log する.
  }
}

const intervalID = setInterval(_01_SetIntervalCallbackFunction, 10);

以下の様に printHistory() で出力されます。

FirstExecutionAsyncId:  1 

async_hook calls: init:  [
  [Arguments] {
    '0': 2,
    '1': 'Timeout',
    '2': 1,
    '3': Timeout {
      _idleTimeout: -1,
      _idlePrev: null,
      _idleNext: null,
      _idleStart: 157,
      _onTimeout: null,
      _timerArgs: undefined,
      _repeat: 10,
      _destroyed: true,
      [Symbol(refed)]: null,
      [Symbol(asyncId)]: 2,
      [Symbol(triggerId)]: 1
    }
  },
  [Arguments] {
    '0': 3,
    '1': 'Timeout',
    '2': 2,
    '3': Timeout {
      _idleTimeout: 10,
      _idlePrev: null,
      _idleNext: null,
      _idleStart: 171,
      _onTimeout: [Function: printHistory],
      _timerArgs: undefined,
      _repeat: null,
      _destroyed: false,
      [Symbol(refed)]: true,
      [Symbol(asyncId)]: 3,
      [Symbol(triggerId)]: 2
    }
  }
] 

async_hook calls: before:  [
  2, 2, 2, 2, 2,
  2, 2, 2, 2, 2,
  2, 3
] 

async_hook calls: after:  [
  2, 2, 2, 2, 2,
  2, 2, 2, 2, 2,
  2
] 

async_hook calls: destroy:  [ 2 ]

init は２回呼ばれています。

１回目は setInterval(_01_SetIntervalCallbackFunction, 10) (id=2) で、 index_setInterval.js ファイル自身 (id=1) からトリガーされた非同期タスクである事が分かります。

２回目は setTimeout(printHistory) (id=3) で、先程の setTimeout(_01_SetIntervalCallbackFunction) (id=2) からトリガーされた非同期タスクである事が分かります。

before は１１回呼ばれています。

このコードでは、１度の setInterval(_01_SetIntervalCallbackFunction, 10) で callback function _01_SetIntervalCallbackFunction (id=2) は 10 ms おきに実行され、clearInterval() されるまで 計１０回 呼ばれています。

また、 printHistory (id=3) も１度呼出され、カウントされます。

after は１０回呼ばれています。

before で述べた通り、_01_SetIntervalCallbackFunction (id=2) は 計１０回 実行されました。

printHistory (id=3) の処理はまだ途中の為、カウントされません。

destroy は１回呼ばれています。

clearInterval の実行により callback function _01_SetTimeoutCallbackFunction (id=2) は破棄されます。

printHistory (id=3) はまだ実行途中で破棄されてないので、カウントされません。

(3) Promise で Async Hooks

最後に Async Hooks を有効にした状態で new Promise(callback) を呼ぶとどうなるか見てみます。

index_promise.js

const printHistory = require('./register-hook');

function _01_PromiseCallbackFunction (resolve, _) {
  resolve();
}

function _02_PromiseThenCallbackFunction (_) {
  // GC で Promise オブジェクトを破棄しないと "async_hooks.destroy" callback は呼ばれない.
  setTimeout(global.gc);

  printHistory(); // ← setTimeout 経由で console.log する.
}

new Promise(_01_PromiseCallbackFunction)
  .then(_02_PromiseThenCallbackFunction);

以下の様に printHistory() で出力されます。

FirstExecutionAsyncId:  1 

async_hook calls: init:  [
  [Arguments] {
    '0': 2,
    '1': 'PROMISE',
    '2': 1,
    '3': '[object PromiseWrap]'
  },
  [Arguments] {
    '0': 3,
    '1': 'PROMISE',
    '2': 2,
    '3': '[object PromiseWrap]'
  },
  [Arguments] {
    '0': 4,
    '1': 'Timeout',
    '2': 3,
    '3': Timeout {
      _idleTimeout: 1,
      _idlePrev: null,
      _idleNext: null,
      _idleStart: 49,
      _onTimeout: [Function: gc],
      _timerArgs: undefined,
      _repeat: null,
      _destroyed: true,
      [Symbol(refed)]: null,
      [Symbol(asyncId)]: 4,
      [Symbol(triggerId)]: 3
    }
  },
  [Arguments] {
    '0': 5,
    '1': 'Timeout',
    '2': 3,
    '3': Timeout {
      _idleTimeout: 10,
      _idlePrev: null,
      _idleNext: null,
      _idleStart: 49,
      _onTimeout: [Function: printHistory],
      _timerArgs: undefined,
      _repeat: null,
      _destroyed: false,
      [Symbol(refed)]: true,
      [Symbol(asyncId)]: 5,
      [Symbol(triggerId)]: 3
    }
  }
] 

async_hook calls: before:  [ 3, 4, 5 ] 

async_hook calls: after:  [ 3, 4 ] 

async_hook calls: destroy:  [ 2, 3, 4 ]

ちょっとごちゃごちゃしているのは、new Promise(callback) に加え、
Promise.then() の呼出と、setTimeout(global.gc) の呼出があるからです。

init は４回呼ばれています。

１回目は new Promise(_01_PromiseCallbackFunction) (id=2) で、 index_promise.js ファイル自身 (id=1) からトリガーされた非同期タスクである事が分かります。

２回目は promise.then(_02_PromiseThenCallbackFunction) (id=3) で、 new Promise(_01_PromiseCallbackFunction) (id=2) からトリガーされた非同期タスクである事が分かります。

３回目は意図的にコード setTimeout(global.gc) を記述した為に、記録されています。

destroy で後述しますが、 Promise の場合は GC で promise object 破棄されるまで destroy が呼出されません

４回目は setTimeout(printHistory) (id=5) で、先程の promise.then(_02_PromiseThenCallbackFunction) (id=3) からトリガーされた非同期タスクである事が分かります。

before は３回呼ばれています。

正直意図しない動きをしています。

• new Promise(_01_PromiseCallbackFunction) (id=2) では before は 呼出されない
• promise.then(_02_PromiseThenCallbackFunction) (id=3) では before は 呼出される

以下の通り、公式のドキュメントにもそれとなく書いてありますが、どうしてこういう動作になるのか理解できていません。

• promiseResolve(asyncId)
• async hooks promise not destroyed

after は２回呼ばれています。

before と同様です。

printHistory (id=5) の処理はまだ途中の為、カウントされません。

destroy は３回呼ばれています。

Promise の場合、promise object が 破棄 (=GC) されるまで destroy は呼出されません。

本コードでは、意図的に global.gc() を実行しました。

printHistory (id=5) はまだ実行途中で破棄されてないので、カウントされません。