►
Description
Instrumentation and Node.js Diagnostics - Thomas Watson, Opbeat
This talk is a head first dive into the next-gen core tracing API’s being developed under the Node.js Diagnostics Working Group. We’ll learn about the upcoming AsyncHooks API and how this can be used to build your own high level instrumentation logic in production.
About Thomas Watson
Thomas Watson is an open source Node.js hacker out of Copenhagen, Denmark. He is a member of the Node.js Diagnostics Working Group and is the Node.js Lead at Opbeat - a JavaScript performance analysis and monitoring startup. He maintains over a 100 open source projects, enjoys working with mad science and implementing network protocols in JavaScript.
A
I,
my
name
is
thomas
watson,
and
why
am
I
talking
to
you
today,
basically
I'm
an
open-source
developer
and
you
can
find
all
my
stuff
at
github
under
/
Watson,
but
also
I'm,
the
nerdiest
lead
at
upbeat
where
we
do
a
lot
of
performance.
Monitoring
of
note,
GS
front,
end
stuff,
react,
ankle,
etc
and
then
I'm,
a
member
of
the
nokias
diagnostics
working
group
under
the
node
foundation,
where
we
are
researching
and
developing
the
new
Diagnostics
tools
that
are
coming
into
future
versions
of
node
and
by
the
way
I
am
on
Twitter
as
well.
A
You
can
follow
me.
There
I'll
tweet
out
some
some
links
to
my
slides
after
the
after
the
talk.
So
if
there's
anything
in
the
slide,
you
you
you
want
to
want
to
read
again,
then
you
can.
You
can
check
that
link
and
and
of
course,
if
you
have
any
questions
that
I
don't
answer
during
the
talk
or
afterwards
feel
free
to
give
me
a
shout
on
Twitter
at
any
time,
I'll
respond
to
everybody
so
yeah.
So
my
talk
is
Scott.
It's
called
instrument,
instrumentation
and
tracing
a
note.
A
Yes-
and
this
is
something
that
you
do
in
a
lot
of
programming
languages,
but
why
is
this
hard
to
do
a
node?
The
problem
with
node
is
also
one
of
its
strengths,
no
DSS
single
threaded
and
that
by
itself
is
not
really
a
problem,
because
node
is
really
good
at
handling
multiple
requests
at
the
same
time.
A
So
normally,
when
a
request
comes
in
to
a
node
HTTP
server,
which
is
what
we
typically
use
note
for,
we
we
can
start
to
look
at
what
goes
on
during
a
trace.
Let's
say:
oh
doing
this
doing
the
request.
So
let's
say
that,
oh
you
check
something
in
the
in
the
reddish
cash,
for
example,
to
check.
If
you
have
whatever
the
user
is
requesting
and
then
afterwards
you,
you
may
be
checking
something
a
database
and
your
mighty
store.
Some
stayed
in
the
database,
so
you
get
like
this
nice.
A
If
you
want
to
graph
it,
you
guys
get
this
nice
waterfall
model
of
what
goes
on
during
a
request
and-
and
we
call
these
things
normally-
we
call
them
traces.
So
we
would
take
a
measure,
the
start
time
and
end
time,
and
we
use
that
to
determine
what
goes
on
and
and
what
is
slowing
down
our
app
and
and
then
we
call
like
the
whole
thing.
A
We
call
normally
that
a
transaction,
but,
of
course
what
can
happen
is
that
an
error
happens
during
one
of
these
asynchronous
events
and
you
get
a
stack
trace
and
it
says.
Oh,
the
error
is
right
here
in
your
code:
get
line
number
everything,
but
what
you
don't
get
is
you
know
you
have
no
clue
what
request
actually
found
that
waterfall
course
that
arrow
to
happen
and
no
and
a
lot
of
times
errors
are
related
to
data
that
you
expect
to
be
something,
but
it's
something
different
and
it
was
really
nice.
A
A
So
if
we,
if
we
graph
the
what
goes
on
in
the
node
process,
we
have
an
incoming
HTTP
request
and
it
does
something,
and
then
it
sends
a
request
off
to
the
database
and
then
wait
for
the
database
return
and
then
it
returns.
There's
another
yellow
blob
there
when
it
returns,
and
it
does
something
else
and
it
waits
and
in
the
meantime
this
is
dead.
Space
note
process
is
not
doing
anything.
A
This
is
all
synchronous
code
and
then
you
get
another
HTTP
request
that
comes
in
and
it
it
also
uses
pieces
of
this.
This
space
that
is
available
to
run
the
synchronous
code
and
let's
say
we
want
to
figure
out
what
is
what
is
the
current
requests
are
like
all
the
time
at
any
time
you
want
to
figure
out
what
is
the
current
request
that
goes
on
every
time.
A
Some
synchronous
code
is
running,
so
what
we
could
do
is
we
could
every
time
I
request
comes
in,
we
could
have
a
global
and
we
could
set
it
to.
We
call
it
current
request
time
we
could
set
it
to
to
whatever
the
current
request
is.
The
problem,
of
course,
is
that,
if
we,
if
we
fast
forward
in
time
here
and
and
see
now
that
the
second
request
comes
in,
we
set
the
the
current
request
to
request
number
two
and
that's
fine
when
the
second
piece
of
synchronous
code
runs.
A
But
then,
when
we
get
back
to
the
to
the
second
piece
of
the
first
request,
it
actually
point
to
the
second
request,
because
that's
the
last
thing
we
ever
we
ever
set
the
current
request
to
so,
of
course,
that's
a
problem
and
what
we
want
to
do
is
you
want
to
figure
out
a
magic
way
to
make
sure
that
current
request
also
always
points
to
the
right
current
request
and
that's
just
the
latest
one
to
come
into
our
server.
So
the
solution
to
this-
and
you
know
anybody
see
what
this
is-
it's
a
monkey
patch.
A
In
strips
out
there,
okay,
so
what
you
could
do
is
you
can
you
can
override
all
asing
stuff
in
node?
So
let's
say
this
is
a
timer
and
we
just
want
to
make
sure
that
every
time
the
the
callback
for
the
timer
runs
we
want
to
reset
whatever
the
current
request
was
to
whatever
current
request
was
when
the
timer
was
queued
on
the
event
loop.
So
so
we
will
just
make
a
reference
to
the
original
timer
settimeout
function.
A
We
just
reset
the
state
of
the
current
request
to
whatever
it
was
when
the
callback
was
cute,
and
that
is
like
an
all
simple
this.
Actually,
that's
actually
what
happens
and
it's
it's
kind
of
like
magic.
So,
basically,
what
we
have
to
do
is
we
have
to
basically
patch
everything
we
have
to
patch
the
world
we
have
to
patch
timers.
We
have
to
patch
promises.
Are
then
the
new
native
promises
that
we
have
a
note?
A
We
also
have
to
Japan
patcher
process
next
tick
and
we
have
to
patch
everything
that
goes
on
inside
the
UV,
because
Libby
UV
is
actually
the
part
of
node
where
all
I
owe
is
happening.
So
every
time
you
talk
to
the
file
system,
every
time
you
talk
to
a
TCP
socket,
we
it
goes
through
a
lip
UV
and
just
one
bullet
here,
but
Libby
is
huge.
A
So
so
that's
where
most
of
the
stuff
we
need
to
patch
is,
and
then
we
also
need
to
patch
certain
third-party
modules,
because
certain
third-party
modules
might
have
their
do
their
own
I.
Oh,
that
is
not
directly
controlled
by
note,
have
their
own
callback,
you
and
stuff
like
that.
So
so
there
are
some
gotchas
that
we
have
to
take
care
of.
So
this
is
basically
how
all
performance
monitoring
tools
you
use
today
work.
This
is
how
upbeat
work.
A
The
company
that
I
work
for
this
is
how
Annie
Willock
New
Relic
works,
seems
kind
of
messy
right.
It
would
be
nice
if
node
provided
a
way
for
us
to
do
this
without
having
to
patch
everything
so
enter.
Asian
cooks,
Asian
cooks
is
a
new
API
that
the
note
foundation
or
the
diagnostic
striking
trace
the
Diagnostics
working
group
is
working
on
and
a
cig
hooks
have
been
around
for
a
long
time.
At
least
in
theory.
A
It
hasn't
been
in
your
node
application,
but
it's
been
worked
on
for
long
Simon's
used
to
be
called
a
sink
wrap.
It
was
actually
introduced
by
another
name
called
a
single
listener.
I
think
it
was
called
originally
back
in
zero
point
11
and
which
was
there
for
two
versions,
and
it
was
removed
again.
So
at
Trevor
Norris
is
the
guy
who,
who
is
doing
all
the
hard
work
is
who
was
working
on
it,
and
he
just
SAT
here
in
when
is
that
September?
Oh
we're
ason
grab
is
dead,
we're
now
calling
the
gates
and
cooks.
A
So,
oh,
it's
now
called
Asian
cooks
are,
but
it
actually
is
already
shipping
with
no
tits
been
shipping
with
notes
and
version
4.
But
you
just
didn't
know
this
and
the
reason
why
you
didn't
know
this:
it's
because
it's
nowhere
in
the
documentation,
because
this
is
still
a
very
experimental
thing,
but
you
can
actually
still
access
it.
If
you
want
to
play
around
with
it,
I
probably
what
wouldn't
use
it
in
production,
if
I
with
you,
but
you
could
play
around
with
it
and
it's
still
behind
the
scenes
they
still
called
async
wrap.
A
This
is
something
that
we
are
changing
as
time
moves
on,
but
it
still
called
Aten
grab.
So
the
way
that
you
you
access
it
is
you
use.
This
function
called
process
that
binding,
which
is
a
way
for
you
to
access
stuff
in
in
deep
you
be
in
in
the
sea
layer
of
node,
and
you
can
actually
access
the
async
wrap
directly
using
processor
binding.
A
You
get
a
JavaScript
object
back
normal
JavaScript
object,
you
can
use
and
then
you
just
set
up
some
hooks
and
Asian
cooks
needs
a
init
hook,
a
pre
hook
a
post
hook
and
it's
right
hook.
All
of
them
are
optional,
and
then
you
just
enable
it,
and
what
does
these
hook
look
like?
It's
basically
just
functions
that
you
give
it,
and
these
functions
are
hooks
that
will
be
kind
of
like
a
venda
minutes.
They
will
be
called
whenever
something
happens,
that
it
has
something
to
do
with
with
asynchronous
stuff.
A
You
will,
you
will
see
a
call
to
the
destroy
book.
Let's
test
this,
let's
try
to
get
a
file
descriptor
from
the
file
system
of
the
current
file,
so
we
require
FS.
We
ufs
open
and
just
before
we
lock
Wheelock
some
some
some
data,
as
we
can
see
what
it
looks
like.
So
this
is
the
entire
program
and
we
get
it
says
Oh
user
before,
because
it's
not
calling
in
any
of
the
hooks.
Yet
so
we
get
the
user
before
them
again.
A
Acing
crap
in
it
because
we're
now
cueing
the
callback
by
calling
FS
open,
then
at
some
point
after
when
it
actually
has
got
the
the
father
scripture
as
I
sorry
to
right
after
that
it
call
it
prints
out
user
after
but
then
at
some
point
we
get
the
pre
hook.
That's
when
the
when
this
ready
to
call
the
callback-
and
so
this
all
runs
synchronously
you
get
the
pre
hook,
then
the
callback
is
actually
called.
A
Should
we
get
user
colon
done
it's
printed
out,
then
we
get
the
post
hook
and
then
at
some
point
later,
we'll
get
to
destroy
hook
not
directly
later,
but
at
some
point
later
when,
when
the
the
objects
garbage
collected.
So
why
am
I
using
lock
and
not
just
console
log?
The
reason
is
not
many
people
know
this,
but
console.log
is
actually
a
synchronous.
There's
a
lot
of
magic
going
on
under
the
hood
to
make
it
appear
synchronous,
but
in
reality
console.log
is
asynchronous.
So
what
happens?
A
If
you
do
something
asynchronous
inside
of
the
init
function,
you'll
get
an
infinite
loop
because
it
will
keep
calling
the
init
function
all
the
time.
So
you'll
get
an
error
in
this
case,
we'll
just
say:
console.log:
it's
not
it's
not
a
function
because
it
doesn't
make
sense
to
call
console.log
in
that
and
there.
So
what
we
can
do
if
you
want
to
debug
this
normally,
you
won't
use
console
log
in
a
in
here,
but
it's
really
nice
for
debugging
purposes.
A
So
you
could
either
ufs
right
sync
to
to
the
to
stand
it
out
and
if
you
want
to
have
nice
formatting,
you
can
use
util
that
format
it's
kind
of
quirky.
So
there
is
this
secret
function
that
actually
ships
with
no.
That
is
called
process
that
underscore
rocky
back.
That
is
basically
behaving
like
console.log,
but
its
geosynchronous
so
we'll
use
that
instead
and
really
get
the
functionality
that
we
expect.
A
There's
a
lot
of
stuff
about
what
is
actually
given
to
you
in
the
init
in
the
init
function:
I'm
not
going
too
much
into
this,
also,
mainly
because
this
have
changed,
or
this
is
changing.
So
this
is
actually,
if
you
use
process
that
binding
right
now.
This
is
what
you
this
is
the
four
arguments
you'll
get,
but
in
a
very
near
future,
we'll
actually
going
to
change
this.
A
You'll
get
a
provider
which
is
basically
just
a
an
ID
referring
to
who
is
actually
making
this
queuing.
This
callback,
you
actually
figure
out
what
all
these
provider
IDs
mean
by
by
accessing
the
dot
providers
constant
on
a
pacing
rap
right
now
these
are
still
in
this
slide.
It's
ids
is
also,
if
you
want
to
play
with
this
now,
it's
going
to
be
it's
going
to
be
IDs,
but
in
the
future,
let's
get
going
to
be
a
string,
but
then
you
can
see
like
its
is.
A
A
And
then
you
have
handle
up,
Y
X
and
handle
objects
is
actually
a
reference
to
the
messaging
protocol
that
happens
between
the
JavaScript
code
and
the
C
code
of
nodes.
A
node
is
actually
pad
JavaScript
paw
pad
C++
and
when
node
talks
to
to
the
booby
it
uses,
these
handle
objects
to
pass
data
back
and
forth.
A
So
this
is
an
example
from
netconnect
where
we
actually
create
a
to
handle
objects.
These
two
here,
a
TCP,
connect,
wrap
and
a
TCP
socket,
and
you
can
see
we
said
like
we
set
the
address
and
the
port
on
the
on
the
request,
and
we
have
some
callbacks
on
the
circuit
and
you
can
actually
access
these
by
the
handle
object.
So
you
can
figure
out
what
is
the
port
and
the
IP
that
we're
trying
to
connect
to,
for
example,.
A
So
a
little
got
you
about.
Timers
timers
are
really
really
optimized
in
nodejs,
so
they
will
actually
share
the
same.
Handle
object
so
the
init
function,
the
handle
object,
will
only
be
neutralized
once
and
it
will
only
be
cold.
So
the
unit
call
back
below
and
you'd
be
called
once
so.
If
you
have
two
timers
that
are
sep
22
to
be
executed,
their
callback
is
set
to
be
executed.
A
At
the
same
time,
you
will
actually
see
that
their
hooks
will
only
fire
once
even
your
immune,
though
you
have
two
timers,
and
this
is
purely
an
optimization
strategy
employed
by
note.
So
it's
just
a
thing
to
know.
So
if
you
want
to
do
something
with
timers,
you
need
to
probably
make
your
own
logic
to
handle
the
that
educates
so
just
very
quickly.
It
will
World
example
and
again
I'm
going
to
try
out
a
link
to
this
later.
A
So
you
can
you
can
you
can
see
this
in
more
details,
but
let's
try
to
keep
this
current
request
property
in
sync
all
the
time,
so
we
just
make
a
reference
of
what?
What
is
the
idea
of
timers,
because
you
want
to
handle
that
separately
and
do
our.
We
still
basically
want
to
do
a
monkey
patching
in
this
case,
so
we
set
up
the
the
async
wrap
callbacks
enable
them
we
have
to
state
maps,
they
be
used
to
keep
state
of
of
what
was
the
original
with
the
current
requests.
A
Before
and
after
we
queue
a
callback
and
in
the
inner
function,
we
basically
just
set
this
in
its
state
to
whatever
the
current
request
is
and
in
the
before
state.
We
just
restore
it
to
it
was
when,
when
in
this
state,
when
the,
when
interstate
was
set
and
in
the
after
state,
we
just
take
it
back
to
what
it
was
just
before
the
before
state,
and
then
we
just
clean
up
after
ourselves
in
the
destroyed.
A
Finally,
a
sinker
crutches
the
handle
creation
time
is
not
always
obvious.
For
example,
if
you
make
a
HTTP
server,
the
init
function
will
not
be
called
until
you
actually
bind
to
a
port.
So
that's
not
until
you
actually
call
listen.
So
sometime
not
really
obvious,
when
the
init
unit
called
back
is
going
to
be
called
console
lock,
you
can't
do
that.
You
have
to
use
raw
underscore
underscore
o
debug
process.
Next
tick
is
is
currently
not
covered
by.
A
This
will
be
in
the
future
very
soon
timers,
as
I
said,
you
need
to
take
care
of
that.
If
you
want
to
have
the
unique
callback
being
called
for
every
every
call
back
that
is
queued,
promises
is
still
not
covered,
because
v8
doesn't
actually
give
us
access
to
promise
it
yet,
but
it's
something
we
are
working
with
Google
to
to
fix
so,
hopefully
very
soon
we
will
have
these
hooks
being
called
for
promises
as
well,
and
it's
still
not
possible
to
have
multiple
hooks
so
set
up
multiple
Asian
cooks.
A
At
the
same
time,
you
can
read
all
about
the
new
API
here
on
this.
This
pull
request.
So
there's
a
few
differences
with
what
I
showed
here.
What
you
can
use
now
to
as
opposed
to
what
was
actually
shipping,
there's
going
to
be
a
solution
to
the
I/o
and
user
land,
so
there's
going
to
be
a
new
and
better
API
is
not
shipped
yet,
but
it's
coming
that
allows
shoot.
If
you
doing
your
own
I
you,
oh
if
you're
using
Nate,
if
you're
doing
native
modules,
you
can,
you
can
actually
fire
these
events
yourself.
A
So
in
JavaScript
will
look
like
this.
You
can
emit
an
init
call.
You
can
omit
the
before,
and
so
you
can.
You
can
actually
make
no
damn
it.
These
events,
if
you're
doing
you're
your
own
low
level
stuff
es
modules,
is
still
up
in
the
air.
How
that
that
work,
but
we're
working
with
t239
to
to
make
that
to
solve
that
problem
as
well,
is
it's
it's
it's,
hopefully,
beings
being
resolved
and
yeah?
This
is
a
p.I
proposed
letter
was
talking
about
with
the
new
API.