diff --git a/CHANGELOG.md b/CHANGELOG.md index 751d67f..ae77ce9 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/README.md b/README.md index d997ea1..56bbab7 100644 --- a/README.md +++ b/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,26 +395,16 @@ 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" + } } } ``` @@ -407,16 +412,27 @@ Default: ```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 diff --git a/lib/exporter/ConsoleSpanExporter.js b/lib/exporter/ConsoleSpanExporter.js index 9ef9efc..594e9dc 100644 --- a/lib/exporter/ConsoleSpanExporter.js +++ b/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) { diff --git a/lib/tracing/index.js b/lib/tracing/index.js index 3bc6ab6..6cd1472 100644 --- a/lib/tracing/index.js +++ b/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)) diff --git a/lib/tracing/trace.js b/lib/tracing/trace.js index e2913de..3b14071 100644 --- a/lib/tracing/trace.js +++ b/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 { diff --git a/lib/utils.js b/lib/utils.js index 3708e22..c2d0486 100644 --- a/lib/utils.js +++ b/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 } diff --git a/package.json b/package.json index f8d14c1..af56cfb 100644 --- a/package.json +++ b/package.json @@ -70,7 +70,9 @@ "propagators": [ "W3CTraceContextPropagator" ], - "_hrtime": true, + "[development]": { + "hrtime": true + }, "_tx": false }, "metrics": {