Search code examples
node.jsasync-hooks

Node.js async_hooks loss tracing


I have read the doc of nodejs async_hooks module and want have a try, this is my demo.mjs:

import async_hooks, { executionAsyncId } from  'async_hooks';
import fs from 'fs';
import path from 'path';

// a async version of console.log
function println(...args) {
    fs.writeFileSync(1, args.join('') + '\n');
}

const globalEid = executionAsyncId();
println(`global execution id: ${ globalEid }`);

let indent = '';
async_hooks
    .createHook({
        init: (asyncId, type, triggerAsyncId, resource) => {
            const eid = executionAsyncId();
            println(`${ indent }init ${ type }(${ asyncId }), trigger by ${ triggerAsyncId }, execute by ${ eid }`);
        },
        before: (asyncId) => {
            println(`${ indent }before ${ asyncId }`);
            indent = ' '.repeat(indent.length + 2);
        },
        after: (asyncId) => {
            indent = ' '.repeat(indent.length - 2);
            println(`${ indent }after ${ asyncId }`);
        },
        destroy: (asyncId) => {
            println(`${ indent }destroy ${ asyncId }`);
        },
        promiseResolve: (asyncId) => {
            println(`${ indent }promise resolve ${ asyncId }`);
        }
    })
    .enable();

const filename = path.dirname(process.argv[1]);
fs.readFile(filename, () => {});

and there is what it print:

global execution id: 0
init FSREQCALLBACK(7), trigger by 0, execute by 0
promise resolve 8
init PROMISE(9), trigger by 8, execute by 0
before 9
  promise resolve 10
  promise resolve 9
after 9
promise resolve 11
promise resolve 12
before 13
  init PROMISE(14), trigger by 13, execute by 13
  promise resolve 14
  init PROMISE(15), trigger by 14, execute by 13
  promise resolve 13
after 13
before 15
  promise resolve 15
after 15
before 13
  init PROMISE(16), trigger by 15, execute by 13
after 13
before 16
  promise resolve 13
  promise resolve 16
after 16
destroy 6
before 7
  init FSREQCALLBACK(17), trigger by 7, execute by 7
after 7
destroy 7
before 17
  init FSREQCALLBACK(18), trigger by 17, execute by 17
after 17
destroy 17
before 18
  init FSREQCALLBACK(19), trigger by 18, execute by 18
after 18
destroy 18
before 19
after 19
destroy 19

you can see there is promise resolve 8 in line 3 but never INIT PROMISE(8) before, why?


Solution

  • well, it's seems like be ok if I switch to commonjs.

    global execution id: 1
    init FSREQCALLBACK(2), trigger by 1, execute by 1
    before 2
      init FSREQCALLBACK(3), trigger by 2, execute by 2
    after 2
    destroy 2
    before 3
      init FSREQCALLBACK(4), trigger by 3, execute by 3
    after 3
    destroy 3
    before 4
      init FSREQCALLBACK(5), trigger by 4, execute by 4
    after 4
    destroy 4
    before 5
    after 5
    destroy 5