manual logging and garbage collection of old spans (#3849)

LICENSE-3rdparty.csv

@@ -30,6 +30,7 @@ require,opentracing,MIT,Copyright 2016 Resonance Labs Inc
 require,path-to-regexp,MIT,Copyright 2014 Blake Embrey
 require,pprof-format,MIT,Copyright 2022 Stephen Belanger
 require,protobufjs,BSD-3-Clause,Copyright 2016 Daniel Wirtz
+require,tlhunter-sorted-set,MIT,Copyright (c) 2023 Datadog Inc.
 require,retry,MIT,Copyright 2011 Tim Koschützki Felix Geisendörfer
 require,semver,ISC,Copyright Isaac Z. Schlueter and Contributors
 dev,@types/node,MIT,Copyright Authors

integration-tests/memory-leak/index.js

@@ -0,0 +1,15 @@
+const tracer = require('../../')
+tracer.init()
+
+const http = require('http')
+
+http.createServer((req, res) => {
+  const delay = Math.random() < 0.01 // 1%
+    ? 61 * 1000 // over 1 minute
+    : Math.random() * 1000 // random 0 - 1s
+
+  setTimeout(() => {
+    res.write('Hello World!')
+    res.end()
+  }, delay)
+}).listen(8080)

package.json

@@ -97,8 +97,9 @@
     "node-abort-controller": "^3.1.1",
     "opentracing": ">=0.12.1",
     "path-to-regexp": "^0.1.2",
-    "pprof-format": "^2.0.7", 
+    "pprof-format": "^2.0.7",
     "protobufjs": "^7.2.5",
+    "tlhunter-sorted-set": "^0.1.0",
     "retry": "^0.13.1",
     "semver": "^7.5.4"
   },

packages/dd-trace/src/config.js

@@ -540,6 +540,12 @@ ken|consumer_?(?:id|key|secret)|sign(?:ed|ature)?|auth(?:entication|orization)?)
       true
     )
 
+    // 0: disabled, 1: logging, 2: garbage collection + logging
+    const DD_TRACE_SPAN_LEAK_DEBUG = coalesce(
+      process.env.DD_TRACE_SPAN_LEAK_DEBUG,
+      0
+    )
+
     const ingestion = options.ingestion || {}
     const dogstatsd = coalesce(options.dogstatsd, {})
     const sampler = {
@@ -722,6 +728,8 @@ ken|consumer_?(?:id|key|secret)|sign(?:ed|ature)?|auth(?:entication|orization)?)
     this.isGCPFunction = isGCPFunction
     this.isAzureFunctionConsumptionPlan = isAzureFunctionConsumptionPlan
 
+    this.spanLeakDebug = Number(DD_TRACE_SPAN_LEAK_DEBUG)
+
     tagger.add(this.tags, {
       service: this.service,
       env: this.env,

packages/dd-trace/src/opentracing/span.js

@@ -13,6 +13,7 @@ const log = require('../log')
 const { storage } = require('../../../datadog-core')
 const telemetryMetrics = require('../telemetry/metrics')
 const { channel } = require('dc-polyfill')
+const spanleak = require('../spanleak')
 
 const tracerMetrics = telemetryMetrics.manager.namespace('tracers')
 
@@ -90,6 +91,7 @@ class DatadogSpan {
 
       unfinishedRegistry.register(this, operationName, this)
     }
+    spanleak.addSpan(this, operationName)
   }
 
   toString () {

packages/dd-trace/src/proxy.js

@@ -10,6 +10,7 @@ const PluginManager = require('./plugin_manager')
 const remoteConfig = require('./appsec/remote_config')
 const AppsecSdk = require('./appsec/sdk')
 const dogstatsd = require('./dogstatsd')
+const spanleak = require('./spanleak')
 
 class Tracer extends NoopProxy {
   constructor () {
@@ -37,6 +38,15 @@ class Tracer extends NoopProxy {
         }, 10 * 1000).unref()
       }
 
+      if (config.spanLeakDebug > 0) {
+        if (config.spanLeakDebug === spanleak.MODES.LOG) {
+          spanleak.enableLogging()
+        } else if (config.spanLeakDebug === spanleak.MODES.GC_AND_LOG) {
+          spanleak.enableGarbageCollection()
+        }
+        spanleak.startScrubber()
+      }
+
       if (config.remoteConfig.enabled && !config.isCiVisibility) {
         const rc = remoteConfig.enable(config)
 

packages/dd-trace/src/spanleak.js

@@ -0,0 +1,98 @@
+'use strict'
+
+/* eslint-disable no-console */
+
+const SortedSet = require('tlhunter-sorted-set')
+
+const INTERVAL = 1000 // look for expired spans every 1s
+const LIFETIME = 60 * 1000 // all spans have a max lifetime of 1m
+
+const MODES = {
+  DISABLED: 0,
+  // METRICS_ONLY
+  LOG: 1,
+  GC_AND_LOG: 2
+  // GC
+}
+
+module.exports.MODES = MODES
+
+const spans = new SortedSet()
+
+// TODO: should these also be delivered as runtime metrics?
+
+// const registry = new FinalizationRegistry(name => {
+//   spans.del(span) // there is no span
+// })
+
+let interval
+let mode = MODES.DISABLED
+
+module.exports.disable = function () {
+  mode = MODES.DISABLED
+}
+
+module.exports.enableLogging = function () {
+  mode = MODES.LOG
+}
+
+module.exports.enableGarbageCollection = function () {
+  mode = MODES.GC_AND_LOG
+}
+
+module.exports.startScrubber = function () {
+  if (!isEnabled()) return
+
+  interval = setInterval(() => {
+    const now = Date.now()
+    const expired = spans.rangeByScore(0, now)
+
+    if (!expired.length) return
+
+    const gc = isGarbageCollecting()
+
+    const expirationsByType = Object.create(null) // { [spanType]: count }
+
+    for (const wrapped of expired) {
+      spans.del(wrapped)
+      const span = wrapped.deref()
+
+      if (!span) continue // span has already been garbage collected
+
+      // TODO: Should we also do things like record the route to help users debug leaks?
+      if (!expirationsByType[span._name]) expirationsByType[span._name] = 0
+      expirationsByType[span._name]++
+
+      if (!gc) continue // everything after this point is related to manual GC
+
+      // TODO: what else can we do to alleviate memory usage
+      span.context()._tags = Object.create(null)
+    }
+
+    console.log('expired spans:' +
+      Object.keys(expirationsByType).reduce((a, c) => `${a} ${c}: ${expirationsByType[c]}`, ''))
+  }, INTERVAL)
+}
+
+module.exports.stopScrubber = function () {
+  clearInterval(interval)
+}
+
+module.exports.addSpan = function (span) {
+  if (!isEnabled()) return
+
+  const now = Date.now()
+  const expiration = now + LIFETIME
+  // eslint-disable-next-line no-undef
+  const wrapped = new WeakRef(span)
+  spans.add(wrapped, expiration)
+  // registry.register(span, span._name)
+}
+
+function isEnabled () {
+  return mode > MODES.DISABLED
+}
+
+function isGarbageCollecting () {
+  return mode >= MODES.GC_AND_LOG
+}

yarn.lock

@@ -4943,6 +4943,11 @@ timestring@^6.0.0:
   resolved "https://registry.npmjs.org/timestring/-/timestring-6.0.0.tgz"
   integrity sha512-wMctrWD2HZZLuIlchlkE2dfXJh7J2KDI9Dwl+2abPYg0mswQHfOAyQW3jJg1pY5VfttSINZuKcXoB3FGypVklA==
 
+tlhunter-sorted-set@^0.1.0:
+  version "0.1.0"
+  resolved "https://registry.yarnpkg.com/tlhunter-sorted-set/-/tlhunter-sorted-set-0.1.0.tgz#1c3eae28c0fa4dff97e9501d2e3c204b86406f4b"
+  integrity sha512-eGYW4bjf1DtrHzUYxYfAcSytpOkA44zsr7G2n3PV7yOUR23vmkGe3LL4R+1jL9OsXtbsFOwe8XtbCrabeaEFnw==
+
 to-fast-properties@^2.0.0:
   version "2.0.0"
   resolved "https://registry.npmjs.org/to-fast-properties/-/to-fast-properties-2.0.0.tgz"