Why the difference in the async_hooks output?

[deostroll]

Using node 9.1.0 on ubuntu 16.04

Cooked up a small example implementing async hooks api:

// Simple fs.writeFile example

const onAsyncHook = require('on-async-hook');
const fs = require('fs');

var stop = onAsyncHook(d => console.log(d));

fs.writeFile('foo.txt', 'bar', { encoding: 'utf8' }, err => {
        if(err) {
                console.log(err);
        }
        else {
                console.log('done');
        }
});

This gives output as follows:

{ startTime: 22588018265037,
  id: 5,
  spans: 
   [ { id: 5,
       type: 'FSREQWRAP',
       parent: 1,
       startTime: 22588018265037,
       endTime: 22588020547820,
       duration: 2282783 },
     { id: 6, type: 'FSREQWRAP', parent: 5, startTime: 22588020273762 } ],
  endTime: 22588020547820,
  duration: 2282783 }
done
{ startTime: 22588025987290,
  id: 8,
  spans: 
   [ { id: 8,
       type: 'FSREQWRAP',
       parent: 6,
       startTime: 22588025987290,
       endTime: 22588026935766,
       duration: 948476 },
     { id: 9,
       type: 'TickObject',
       parent: 8,
       startTime: 22588026830522,
       endTime: 22588026916204,
       duration: 85682 } ],
  endTime: 22588026935766,
  duration: 948476 }

Example 2:

// Simple promise implementation with a fs.writeFile inside a promise resolve

const onAsyncHook = require('on-async-hook');
const fs = require('fs');

var stop = onAsyncHook(d => console.log(d));

var makePromise = timeout => {
	return new Promise(done => {
		setTimeout(() => {
			console.log('done');
			done();
		}, timeout);
	});
};

makePromise(3000).then(() => {
	fs.writeFile('bar.txt', 'baz', { encoding: 'utf8' }, (e) => {
		if(e) {
			console.log(e);
		}
		else {
			console.log('finished');
		}
	});
});

output:

done
{ startTime: 22728240657407,
  id: 6,
  spans: 
   [ { id: 6,
       type: 'Timeout',
       parent: 1,
       startTime: 22728240657407,
       endTime: 22731256229556,
       duration: 3015572149 },
     { id: 9,
       type: 'TickObject',
       parent: 6,
       startTime: 22731252250446 } ],
  endTime: 22731256229556,
  duration: 3015572149 }
{ startTime: 22728241043413,
  id: 7,
  spans: 
   [ { id: 7,
       type: 'TIMERWRAP',
       parent: 1,
       startTime: 22728241043413,
       endTime: 22731264167684,
       duration: 3023124271 } ],
  endTime: 22731264167684,
  duration: 3023124271 }
finished

Why the the second example not invoke the hooks for the file system write?

the on-async-hook library simply registers to the init and destroy events of the async hooks lifecycle.

[devsnek]

i think this issue was meant for https://github.com/lrlna/on-async-hook

[deostroll]

I could simply use that code here and reproduce the issue. All that lib does is hook to the init and destroy events. Then there is some time computations from within them. Thats it.

…

On 15-Nov-2017 1:01 AM, "Gus Caplan" ***@***.***> wrote: i think this issue was meant for https://github.com/lrlna/on-async-hook — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#17027 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAZWaNLga5iRa4UsNZjV0Iz59tA05X23ks5s2eqhgaJpZM4Qd3ML> .

[devsnek]

my bad, i misread the issue

[refack]

@deostroll running this trace by using pure node core code https://gist.github.com/refack/e6d36a77cef460ca53b4e1ed58822434
I get:

PROMISE(6): trigger: 1 execution: 1
Timeout(7): trigger: 1 execution: 1
TIMERWRAP(8): trigger: 1 execution: 1
PROMISE(9): trigger: 6 execution: 1
before:  8
  before:  7
done
    TickObject(10): trigger: 7 execution: 7
    promiseResolve: 6
  after:   7
after:   8
before:  10
after:   10
before:  9
  FSREQWRAP(11): trigger: 9 execution: 9
  promiseResolve: 9
after:   9
destroy: 7
destroy: 10
destroy: 8
before:  11
  FSREQWRAP(12): trigger: 11 execution: 11
after:   11
destroy: 11
before:  12
  FSREQWRAP(13): trigger: 12 execution: 12
after:   12
destroy: 12
before:  13
finished
  TickObject(14): trigger: 13 execution: 13
after:   13
before:  14
after:   14
destroy: 14
destroy: 13

You will notice that the context with ID 9 doesn't get destroyed. It will only be destroyed on garbage collection. Just for testing, adding global.gc(); (and calling node with the --expose-gc cli arg) in the writeFile callback gives:

$ node --expose-gc ex2-17027.js
done
{ startTime: 696212318283343,
  id: 7,
  spans:
   [ { id: 7,
       type: 'Timeout',
       parent: 1,
       startTime: 696212318283343,
       endTime: 696215332686175,
       duration: 3014402832 },
     { id: 10,
       type: 'TickObject',
       parent: 7,
       startTime: 696215330089560 } ],
  endTime: 696215332686175,
  duration: 3014402832 }
{ startTime: 696212318612624,
  id: 8,
  spans:
   [ { id: 8,
       type: 'TIMERWRAP',
       parent: 1,
       startTime: 696212318612624,
       endTime: 696215340295557,
       duration: 3021682933 } ],
  endTime: 696215340295557,
  duration: 3021682933 }
finished
{ startTime: 696212317333560,
  id: 6,
  spans:
   [ { id: 6,
       type: 'PROMISE',
       parent: 1,
       startTime: 696212317333560,
       endTime: 696215354024005,
       duration: 3036690445 },
     { id: 9, type: 'PROMISE', parent: 6, startTime: 696212318772560 },
     { id: 11,
       type: 'FSREQWRAP',
       parent: 9,
       startTime: 696215331933105,
       endTime: 696215346637422,
       duration: 14704317 },
     { id: 14,
       type: 'FSREQWRAP',
       parent: 11,
       startTime: 696215346464228,
       endTime: 696215346882458,
       duration: 418230 },
     { id: 15,
       type: 'FSREQWRAP',
       parent: 14,
       startTime: 696215346856372 },
     { id: 16,
       type: 'TickObject',
       parent: 15,
       startTime: 696215348070007 } ],
  endTime: 696215354024005,
  duration: 3036690445 }

So AFAICT it is a bug in on-async-hook that it hooks init and destroy when it should hook before and after