Use high-resolution host language timer (#641)

* Add hrTime function In order to set times from the host language, instead of relying on the agent's internal timing, this patch adds a hrTime (high-resolution time) function based on the one shipped by OpenTelemetry, and functioning through Node's built-in perf_hooks module. * Set times from span creation functions Use the newly added hrTime function to set the time when starting and completing spans, if no custom time has been passed. * Add changeset to explain timer change Adding the new timer is marked as a patch release. * Update packages/nodejs/.changesets/use-high-resolution-host-language-timer.md Co-authored-by: Tom de Bruijn <[email protected]> * Update packages/nodejs/src/__tests__/span.test.ts Co-authored-by: Tom de Bruijn <[email protected]> * Update packages/nodejs/src/utils.ts Co-authored-by: Tom de Bruijn <[email protected]> * Update packages/nodejs/src/__tests__/utils.test.ts Co-authored-by: Tom de Bruijn <[email protected]> * Remove span.closeSpan from the extension Since all spans are closed with explicit timestamps (using span.closeSpanWithTimestamp), span.closeSpan is no longer used, and can be removed from the extension. Co-authored-by: Tom de Bruijn <[email protected]>
appsignal · Apr 25, 2022 · fc9f2fd · fc9f2fd
1 parent e7ca9d1
commit fc9f2fd
Show file tree

Hide file tree

Showing 6 changed files with 67 additions and 18 deletions.
diff --git a/packages/nodejs/.changesets/use-high-resolution-host-language-timer.md b/packages/nodejs/.changesets/use-high-resolution-host-language-timer.md
@@ -0,0 +1,6 @@
+---
+bump: "patch"
+type: "change"
+---
+
+Use the Node.js performance module as high-resolution timer for span creation and close times. This provides more accurate times and improves compatibility with other systems in the future.
diff --git a/packages/nodejs/ext/appsignal_extension.cpp b/packages/nodejs/ext/appsignal_extension.cpp
@@ -334,17 +334,6 @@ Napi::Value CreateSpanFromTraceparent(const Napi::CallbackInfo &info) {
       [](Napi::Env env, appsignal_span_t *ptr) { appsignal_free_span(ptr); });
 }
 
-Napi::Value CloseSpan(const Napi::CallbackInfo &info) {
-  Napi::Env env = info.Env();
-
-  Napi::External<appsignal_span_t> span =
-      info[0].As<Napi::External<appsignal_span_t>>();
-
-  appsignal_close_span(span.Data());
-
-  return env.Null();
-}
-
 Napi::Value CloseSpanWithTimestamp(const Napi::CallbackInfo &info) {
   Napi::Env env = info.Env();
 
@@ -674,8 +663,6 @@ Napi::Object CreateSpanObject(Napi::Env env, Napi::Object exports) {
            Napi::Function::New(env, GetTraceId));
   span.Set(Napi::String::New(env, "getSpanId"),
            Napi::Function::New(env, GetSpanId));
-  span.Set(Napi::String::New(env, "closeSpan"),
-           Napi::Function::New(env, CloseSpan));
   span.Set(Napi::String::New(env, "closeSpanWithTimestamp"),
            Napi::Function::New(env, CloseSpanWithTimestamp));
   span.Set(Napi::String::New(env, "addSpanError"),

diff --git a/packages/nodejs/src/__tests__/span.test.ts b/packages/nodejs/src/__tests__/span.test.ts
@@ -11,6 +11,7 @@ describe("RootSpan", () => {
 
     expect(span).toBeInstanceOf(RootSpan)
     expect(internal.closed).toBeFalsy()
+    expect(typeof internal.start_time).toBe("number")
   })
 
   it("creates a RootSpan with a timestamp", () => {
@@ -45,9 +46,11 @@ describe("RootSpan", () => {
   it("creates a new ChildSpan", () => {
     const span = new RootSpan()
     const child = span.child()
+    const internal = child.toObject()
 
     expect(child).toBeDefined()
     expect(child).toBeInstanceOf(ChildSpan)
+    expect(typeof internal.start_time).toBe("number")
   })
 
   it("belongs to a given namespace", () => {

diff --git a/packages/nodejs/src/__tests__/utils.test.ts b/packages/nodejs/src/__tests__/utils.test.ts
@@ -1,4 +1,5 @@
-import { getAgentTimestamps } from "../utils"
+import { getAgentTimestamps, hrTime } from "../utils"
+import perf_hooks from "perf_hooks"
 
 describe("Utils", () => {
   describe("getAgentTimestamps", () => {
@@ -9,4 +10,21 @@ describe("Utils", () => {
       expect(timestamp.nsec).toEqual(108000000)
     })
   })
+
+  describe("hrTime", () => {
+    it("returns a second/nanosecond tuple", () => {
+      const performance = {
+        ...perf_hooks.performance,
+        timeOrigin: 1648719688126.149,
+        now: function () {
+          return 116931.83823999763
+        }
+      }
+
+      expect(hrTime(performance)).toEqual({
+        sec: 1648719688 + 116,
+        nsec: 126148939 + 931838240
+      })
+    })
+  })
 })
diff --git a/packages/nodejs/src/span.ts b/packages/nodejs/src/span.ts
@@ -3,7 +3,7 @@ import { Span, SpanOptions, SpanContext, SpanData } from "./interfaces"
 
 import { span } from "./extension_wrapper"
 import { Data } from "./internal/data"
-import { getAgentTimestamps } from "./utils"
+import { getAgentTimestamps, hrTime } from "./utils"
 import { BaseClient } from "./client"
 
 /**
@@ -174,7 +174,8 @@ export class BaseSpan implements Span {
       span.closeSpanWithTimestamp(this._ref, sec, nsec)
       return this
     } else {
-      span.closeSpan(this._ref)
+      const { sec, nsec } = hrTime()
+      span.closeSpanWithTimestamp(this._ref, sec, nsec)
       return this
     }
   }
@@ -222,7 +223,12 @@ export class ChildSpan extends BaseSpan {
           nsec
         )
       } else {
-        this._ref = span.createChildSpan(spanOrContext.ref())
+        const { sec, nsec } = hrTime()
+        this._ref = span.createChildSpanWithTimestamp(
+          spanOrContext.ref(),
+          sec,
+          nsec
+        )
       }
     } else {
       const { traceId, spanId } = spanOrContext
@@ -243,7 +249,8 @@ export class RootSpan extends BaseSpan {
       const { sec, nsec } = getAgentTimestamps(startTime)
       this._ref = span.createRootSpanWithTimestamp(namespace, sec, nsec)
     } else {
-      this._ref = span.createRootSpan(namespace)
+      const { sec, nsec } = hrTime()
+      this._ref = span.createRootSpanWithTimestamp(namespace, sec, nsec)
     }
   }
 

diff --git a/packages/nodejs/src/utils.ts b/packages/nodejs/src/utils.ts
@@ -1,5 +1,9 @@
 import fs from "fs"
 import path from "path"
+import perf_hooks from "perf_hooks"
+
+const NANOSECOND_DIGITS = 9
+const SECOND_TO_NANOSECONDS = Math.pow(10, NANOSECOND_DIGITS)
 
 /**
  * Retrieve a valid version number from a `package.json` in a given
@@ -42,3 +46,27 @@ export function isWritable(path: string) {
     return false
   }
 }
+
+/**
+ * Returns a high-resolution time tuple containing the current time in seconds and nanoseconds.
+ *
+ * @function
+ */
+export function hrTime(
+  performance = perf_hooks.performance
+): { sec: number; nsec: number } {
+  const origin = numberToHrtime(performance.timeOrigin)
+  const now = numberToHrtime(performance.now())
+
+  return { sec: origin[0] + now[0], nsec: origin[1] + now[1] }
+}
+
+function numberToHrtime(epochMillis: number) {
+  const epochSeconds = epochMillis / 1000
+  const seconds = Math.trunc(epochSeconds)
+  const nanoseconds =
+    Number((epochSeconds - seconds).toFixed(NANOSECOND_DIGITS)) *
+    SECOND_TO_NANOSECONDS
+
+  return [seconds, nanoseconds]
+}