feat: support for own, high resolution timestamps (#125)

- [x] add handling for val `'false'` to make it adjustable via cloud
cockpit
- [x] add `_hrtime` to readme

CHANGELOG.md

@@ -4,6 +4,14 @@ All notable changes to this project will be documented in this file.
 This project adheres to [Semantic Versioning](http://semver.org/).
 The format is based on [Keep a Changelog](http://keepachangelog.com/).
 
+## Version 0.1.0 - tbd
+
+### Added
+
+- Support for own, high resolution timestamps
+  + Enable via `cds.env.requires.telemetry.tracing.hrtime = true`
+  + Enabled by default in development profile
+
 ## Version 0.0.5 - 2024-03-11
 
 ### Added

README.md

@@ -362,6 +362,21 @@ Default:
       }
     }
   },
+  {
+    "kind": "telemetry-to-cloud-logging",
+    "tracing": {
+      "exporter": {
+        "module": "@opentelemetry/exporter-trace-otlp-grpc",
+        "class": "OTLPTraceExporter"
+      }
+    },
+    "metrics": {
+      "exporter": {
+        "module": "@opentelemetry/exporter-metrics-otlp-grpc",
+        "class": "OTLPMetricExporter"
+      }
+    }
+  },
   {
     "kind": "telemetry-to-jaeger",
     "tracing": {
@@ -380,43 +395,44 @@ Default:
     ```json
     {
       "tracing": {
-        "module": "@opentelemetry/sdk-trace-base",
-        "class": "ConsoleSpanExporter"
-      },
-      "metrics": {
-        "module": "@opentelemetry/sdk-metrics",
-        "class": "ConsoleMetricExporter"
-      }
-    }
-    ```
-1. For gRPC, use:
-    ```json
-    {
-      "tracing": {
-        "module": "@opentelemetry/exporter-trace-otlp-grpc",
-        "class": "OTLPTraceExporter"
+        "exporter": {
+          "module": "@opentelemetry/sdk-trace-base",
+          "class": "ConsoleSpanExporter"
+        }
       },
-      
       "metrics": {
-        "module": "@opentelemetry/exporter-metrics-otlp-grpc",
-        "class": "OTLPMetricExporter"
+        "exporter": {
+          "module": "@opentelemetry/sdk-metrics",
+          "class": "ConsoleMetricExporter"
+        }
       }
     }
     ```
 1. For HTTP, use:
     ```json
     {
       "tracing": {
-        "module": "@opentelemetry/exporter-trace-otlp-http",
-        "class": "OTLPTraceExporter"
+        "exporter": {
+          "module": "@opentelemetry/exporter-trace-otlp-http",
+          "class": "OTLPTraceExporter"
+        }
       },
       "metrics": {
-        "module": "@opentelemetry/exporter-metrics-otlp-http",
-        "class": "OTLPMetricExporter"
+        "exporter": {
+          "module": "@opentelemetry/exporter-metrics-otlp-http",
+          "class": "OTLPMetricExporter"
+        }
       }
     }
     ```
 
+### High resolution timestamps (beta)
+
+By default, the start time of a span is taken from `Date.now()` and, hence, has only millisecond resolution.
+Via `cds.requires.telemetry.tracing.hrtime = true`, you can instruct the plugin to specify the start and end times of spans, which it does with nanosecond resolution.
+This may result in minor drifts, especially for spans created by other instrumentations such as `@opentelemetry/instrumentation-http`.
+Hence, the `hrtime` mode is on by default in development but not in production.
+
 ### Environment variables
 
 - `NO_TELEMETRY`: Disables the plugin

lib/exporter/ConsoleSpanExporter.js

@@ -60,8 +60,8 @@ const _span_sorter = (a, b) => {
 }
 
 const _list2tree = (span, spans, flat) => {
-  const id = span.attributes.___id
-  const children = spans.filter(s => s.attributes.___parentId === id)
+  const id = span.attributes.__id
+  const children = spans.filter(s => s.attributes.__parentId === id)
   if (children.length === 0) return
   children.sort(_span_sorter)
   for (const each of children) {
@@ -109,8 +109,8 @@ class ConsoleSpanExporter /* implements SpanExporter */ {
           const children = this._temporaryStorage.get(span.spanContext().traceId)
           if (children) {
             const batch = !!span.attributes['http.url']?.match(/\/\$batch/)
-            const ids = new Set(children.map(s => s.attributes.___id).filter(s => !!s))
-            const reqs = children.filter(s => s.attributes.___id && !ids.has(s.attributes.___parentId))
+            const ids = new Set(children.map(s => s.attributes.__id).filter(s => !!s))
+            const reqs = children.filter(s => s.attributes.__id && !ids.has(s.attributes.__parentId))
             const flat = []
             reqs.sort(_span_sorter)
             for (const each of reqs) {

lib/tracing/index.js

@@ -16,7 +16,7 @@ function _getSampler() {
   if (!Array.isArray(ignoreIncomingPaths) || !ignoreIncomingPaths.length) _shouldSample = () => true
   else {
     // eslint-disable-next-line no-unused-vars
-    _shouldSample = (context, traceId, name, spanKind, attributes, links) => {
+    _shouldSample = (_context, _traceId, _name, _spanKind, attributes, _links) => {
       const originalUrl = attributes?.['http.originalUrl']
       if (!originalUrl) return true
       return !ignoreIncomingPaths.some(p => originalUrl.startsWith(p))

lib/tracing/trace.js

@@ -4,20 +4,18 @@ const otel = require('@opentelemetry/api')
 const { SpanKind, SpanStatusCode, ROOT_CONTEXT } = otel
 const { SemanticAttributes } = require('@opentelemetry/semantic-conventions')
 
+const { _hrnow } = require('../utils')
+
 const MASK_HEADERS = (cds.env.log.mask_headers || ['/authorization/i', '/cookie/i']).map(s => {
   const parts = s.match(/\/(.+)\/(\w*)/)
   if (parts) return new RegExp(parts[1], parts[2])
   return new RegExp(s)
 })
 
-const HRTIME = cds.env.requires.telemetry.tracing._hrtime
-const EPOCH_OFFSET = Math.floor(Date.now() / 1000) - process.hrtime()[0]
+const HRTIME = cds.env.requires.telemetry.tracing.hrtime && cds.env.requires.telemetry.tracing.hrtime !== 'false'
 
-// returns [seconds, nanoseconds] since unix epoch
-function _hrtime() {
-  const hrtime = process.hrtime()
-  return [hrtime[0] + EPOCH_OFFSET, hrtime[1]]
-}
+// attach a hr time to incoming requests for later adjustment of span start time in _getParentSpan()
+if (HRTIME) cds.on('listening', ({ server }) => server.on('request', req => (req.__hrnow = _hrnow())))
 
 function _getParentSpan() {
   if (!cds.context) return
@@ -26,7 +24,7 @@ function _getParentSpan() {
     cds.context._otelctx = otel.context.active()
     const parent = otel.trace.getSpan(cds.context._otelctx)
     if (HRTIME && parent && !parent.__adjusted) {
-      parent.startTime = _hrtime()
+      parent.startTime = cds.context.http?.req?.__hrnow || _hrnow()
       parent.__adjusted = true
     }
     if (!parent?._is_async) cds.context._otelctx.setValue(cds.context._otelKey, parent)
@@ -174,7 +172,7 @@ function trace(name, fn, targetObj, args, options = {}) {
   }
   // needed for sampling decision (cf. shouldSample)
   if (cds.context.http?.req) spanOptions.attributes = { 'http.originalUrl': cds.context.http?.req.originalUrl }
-  if (HRTIME) spanOptions.startTime = _hrtime()
+  if (HRTIME) spanOptions.startTime = _hrnow()
   if (isAsync) {
     spanOptions.links = [{ context: parentSpan.spanContext() }]
     spanOptions.parent = undefined
@@ -189,8 +187,8 @@ function trace(name, fn, targetObj, args, options = {}) {
   if (span.constructor.name === 'NonRecordingSpan') return fn.apply(targetObj, args)
 
   // in order to create hierarchy in console exporter
-  span.setAttribute('___id', cds.utils.uuid())
-  if (parentSpan) span.setAttribute('___parentId', parentSpan.attributes.___id)
+  span.setAttribute('__id', cds.utils.uuid())
+  if (parentSpan) span.setAttribute('__parentId', parentSpan.attributes.__id)
 
   /*
    * set attributes on span
@@ -238,7 +236,7 @@ function trace(name, fn, targetObj, args, options = {}) {
       throw e
     }
     const onDone = () => {
-      if (span.status.code !== SpanStatusCode.UNSET && !span.ended) span.end(HRTIME ? _hrtime() : undefined)
+      if (span.status.code !== SpanStatusCode.UNSET && !span.ended) span.end(HRTIME ? _hrnow() : undefined)
     }
 
     try {

lib/utils.js

@@ -4,6 +4,7 @@ const LOG = cds.log('telemetry')
 const fs = require('fs')
 
 const { DiagLogLevel } = require('@opentelemetry/api')
+const { hrTimeToMilliseconds } = require('@opentelemetry/core')
 const { Resource } = require('@opentelemetry/resources')
 const { SemanticResourceAttributes } = require('@opentelemetry/semantic-conventions')
 
@@ -129,6 +130,24 @@ function hasDependency(name) {
   return !!PKG.dependencies[name]
 }
 
+const now = Date.now()
+const hrTimeInMS = Number(`${hrTimeToMilliseconds(process.hrtime())}`.split('.')[0])
+const diff = now - hrTimeInMS
+const EPOCH_OFFSET_S = Number(`${diff}`.slice(0, -3))
+const EPOCH_OFFSET_MS = Number(`${diff}`.slice(-3) + '000000')
+
+// returns [seconds, nanoseconds] since unix epoch
+function _hrnow() {
+  const hrtime = process.hrtime()
+  let s = hrtime[0] + EPOCH_OFFSET_S
+  let ns = hrtime[1] + EPOCH_OFFSET_MS
+  if (ns >= 1000000000) {
+    s++
+    ns -= 1000000000
+  }
+  return [s, ns]
+}
+
 function _require(name) {
   name = Array.isArray(name) ? name[0] : name
   try {
@@ -146,5 +165,6 @@ module.exports = {
   getDynatraceCredentials,
   getCloudLoggingCredentials,
   hasDependency,
+  _hrnow,
   _require
 }

package.json

@@ -70,7 +70,9 @@
           "propagators": [
             "W3CTraceContextPropagator"
           ],
-          "_hrtime": true,
+          "[development]": {
+            "hrtime": true
+          },
           "_tx": false
         },
         "metrics": {