Async hooks based context tracking #538

matthewloring · 2017-08-10T22:56:19Z

Introduces a lower overhead, more correct context tracking
mechanism based on async hooks that is available when using the
trace agent on newer versions of node (>=8). To enable async
hooks based context, set the GCLOUD_TRACE_NEW_CONTEXT environment
variable. This change is not expected to have observable behavior
difference but due to the nature of context propagation it is
difficult to say for sure without real world testing.

matthewloring · 2017-08-14T04:25:30Z

I'm still working through the right test plan for this and I'm not sold on the way namespaces are represented in the async hook based implementation but all the high level structure is there and the tests are passing. I would be interested to get some early feedback on this, especially on the required changes to the tests (grpc required the most invasive changes).

src/trace-api.js

@@ -165,11 +166,17 @@ TraceAgent.prototype.runInRootSpan = function(options, fn) {
    // Create a new root span, and invoke fn with it.
    var traceId = incomingTraceContext.traceId || (uuid.v4().split('-').join(''));
    var parentId = incomingTraceContext.spanId || '0';
+    var frameOffset;
+    if (semver.satisfies(process.version, '>=8')) {


ofrobots

Still looking.. some initial comments.

index.js

@@ -20,7 +20,9 @@ var filesLoadedBeforeTrace = Object.keys(require.cache);

 // Load continuation-local-storage first to ensure the core async APIs get
 // patched before any user-land modules get loaded.
-require('continuation-local-storage');
+if (require('semver').satisfies(process.version, '<8')) {


src/cls-ah.js

@@ -0,0 +1,146 @@
+/**
+ * Copyright 2015 Google Inc. All Rights Reserved.


src/trace-api.js

@@ -169,7 +172,8 @@ TraceAgent.prototype.runInRootSpan = function(options, fn) {
      options.name, /* Span name */
      parentId, /* Parent's span ID */
      true, /* Is root span */
-      options.skipFrames ? options.skipFrames + 2 : 2);
+      options.skipFrames ?
+        options.skipFrames + ROOT_SPAN_STACK_OFFSET : ROOT_SPAN_STACK_OFFSET);


test/plugins/common.js

+  // Monkeypatch the monkeypatcher
+  var oldIt = global.it;
+  global.it = function it(title, fn) {
+    return oldIt.call(this, title, cls.createNamespace().bind(fn));


src/cls-ah.js

+// Core Zone Api
+
+function Context() {
+  this.properties = {};


src/cls-ah.js

+
+Context.prototype.run = function(cb, applyThis, applyArgs) {
+  const oldContext = current;
+  current = new Context();


src/cls-ah.js

+  }
+};
+
+Namespace.prototype.run = function(cb) {


src/cls-ah.js

+  }
+};
+
+Namespace.prototype.runAndReturn = function(cb) {


src/cls-ah.js

+  }
+};
+
+Namespace.prototype.bind = function(cb) {


src/cls-ah.js

+  }
+};
+
+Namespace.prototype.runAndReturn = function(cb) {


src/cls-ah.js

+  }
+};
+
+Namespace.prototype.bindEmitter = function(ee) {


test/plugins/common.js

 var logger = require('@google-cloud/common').logger;
 var trace = require('../..');
 var cls = require('../../src/cls.js');
+if (semver.satisfies(process.version, '>=8')) {
+  // Monkeypatch the monkeypatcher


matthewloring · 2017-08-18T02:29:06Z

It looks like appveyor is hanging on hiredis compilation but everything else looks clean. Comments should be addressed. I think this is ready for another look. @kjin @ofrobots

.travis.yml

@@ -19,7 +19,7 @@ before_install:
  - psql -c "alter user postgres with password 'Password12!';" -U postgres

 env:
-  - CXX=g++-4.8
+  - CXX=g++-4.8 GCLOUD_TRACE_NEW_CONTEXT=1


appveyor.yml

@@ -25,6 +25,7 @@ install:
  - ps: cd ..\..\..\..
  # set GCLOUD_PROJECT


index.js

@@ -20,7 +20,10 @@ var filesLoadedBeforeTrace = Object.keys(require.cache);

 // Load continuation-local-storage first to ensure the core async APIs get
 // patched before any user-land modules get loaded.
-require('continuation-local-storage');
+if (require('semver').satisfies(process.version, '<8') &&


src/cls-ah.js

+  return res;
+};
+
+Namespace.prototype.runAndReturn = function(fn) {


src/cls-ah.js

+  }
+};
+
+var n = null;


src/cls-ah.js

+const contexts = {};
+var current = {};
+
+const hook = asyncHook.createHook({init, before, after, destroy});


src/cls-ah.js

+const asyncHook = require('async_hooks');
+
+const wrappedSymbol = Symbol('context_wrapped');
+const contexts = {};


src/cls-ah.js

+
+function Namespace() {}
+
+Namespace.prototype.get = function(k) {


src/cls-ah.js

+    return cb;
+  }
+  const boundContext = current;
+  const wrapped = cb.length === 0 ? function() {


src/cls-ah.js

+
+Namespace.prototype.bindEmitter = function(ee) {
+  for (var method of eventEmitterMethods) {
+    patchEventEmitterMethod(ee, method, this);


ofrobots

sorry.. butter fingers

matthewloring · 2017-08-21T23:10:34Z

@ofrobots All comments should be addressed. PTAL.

src/cls-ah.js

+let contexts = {};
+let current = {};
+
+const hook = asyncHook.createHook({init, before, destroy});


src/cls-ah.js

+function Namespace() {}
+
+Namespace.prototype.get = function(k) {
+  return current ? current[k] : undefined;


ofrobots

LGTM w/ nits.

src/cls-ah.js

+    return cb;
+  }
+  const boundContext = current;
+  const wrapped = function contextWrapper() {


src/cls-ah.js

+const eventEmitterMethods =
+  [ 'addListener', 'on', 'once', 'prependListener', 'prependOncelistener' ];
+
+Namespace.prototype.bindEmitter = function(ee) {


Introduces a lower overhead, more correct context tracking mechanism based on async hooks that is available when using the trace agent on newer versions of node (>=8). To enable async hooks based context, set the GCLOUD_TRACE_NEW_CONTEXT environment variable. This change is not expected to have observable behavior difference but due to the nature of context propagation it is difficult to say for sure without real world testing.

Introduces a lower overhead, more correct context tracking mechanism based on async hooks that is available when using the trace agent on newer versions of node (>=8). To enable async hooks based context, set the GCLOUD_TRACE_NEW_CONTEXT environment variable. This change is not expected to have observable behavior difference but due to the nature of context propagation it is difficult to say for sure without real world testing. PR-URL: #538

googlebot added the cla: yes This human has signed the Contributor License Agreement. label Aug 10, 2017

jmdobry added the in progress label Aug 10, 2017

kjin self-requested a review August 11, 2017 17:14

matthewloring requested a review from ofrobots August 12, 2017 04:35

evanlucas reviewed Aug 14, 2017

View reviewed changes

ofrobots reviewed Aug 14, 2017

View reviewed changes

kjin reviewed Aug 15, 2017

View reviewed changes

ofrobots approved these changes Aug 18, 2017

View reviewed changes

ofrobots suggested changes Aug 18, 2017

View reviewed changes

ofrobots reviewed Aug 24, 2017

View reviewed changes

ofrobots approved these changes Aug 29, 2017

View reviewed changes

matthewloring changed the title ~~[WIP]: Experiment with async hooks based context tracking~~ Async hooks based context tracking Aug 29, 2017

matthewloring merged commit 87e4254 into googleapis:master Aug 30, 2017

matthewloring deleted the cls branch August 30, 2017 02:10

jmdobry removed the in progress label Aug 30, 2017

kjin mentioned this pull request Nov 29, 2017

[async_hooks] stable API - tracking issue nodejs/diagnostics#124

Closed

20 tasks

AndreasMadsen mentioned this pull request Dec 18, 2017

Performance impact of async_hooks nodejs/benchmarking#181

Open

		@@ -0,0 +1,146 @@
		/**
		* Copyright 2015 Google Inc. All Rights Reserved.

		@@ -25,6 +25,7 @@ install:
		- ps: cd ..\..\..\..
		# set GCLOUD_PROJECT


		function Namespace() {}

		Namespace.prototype.get = function(k) {

Async hooks based context tracking #538

Async hooks based context tracking #538

Conversation

matthewloring commented Aug 10, 2017 • edited Loading

matthewloring commented Aug 14, 2017

This comment was marked as spam.

This comment was marked as spam.

ofrobots left a comment

Choose a reason for hiding this comment

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

matthewloring commented Aug 18, 2017

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

ofrobots left a comment

Choose a reason for hiding this comment

matthewloring commented Aug 21, 2017

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

ofrobots left a comment

Choose a reason for hiding this comment

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

This comment was marked as spam.

matthewloring commented Aug 10, 2017 •

edited

Loading