feat: dropped span stats (#2707)

* feat: track span statistics

#2302

CHANGELOG.asciidoc

@@ -101,6 +101,8 @@ specifying links during span creation (with the limitation that span link
   Lambda layers now that
   https://aws.amazon.com/blogs/compute/node-js-16-x-runtime-now-available-in-aws-lambda/[this runtime is available on AWS].
 
+- Adds [dropped span statistics](https://github.com/elastic/apm/blob/main/specs/agents/handling-huge-traces/tracing-spans-dropped-stats.md) to transaction payloads allowing APM Server to calculate more accurate throughput metrics.
+
 [float]
 ===== Bug fixes
 

lib/instrumentation/dropped-span-stats.js

@@ -0,0 +1,58 @@
+'use strict'
+const LIMIT_STATS = 128
+class DroppedSpanStats {
+  constructor () {
+    this.statsMap = new Map()
+  }
+
+  captureDroppedSpan (span) {
+    const resource = span && span._destination && span._destination.service && span._destination.service.resource
+    if (!resource || !span._exitSpan) {
+      return
+    }
+
+    const stats = this.getOrCreateStats(resource, span.outcome)
+    if (!stats) {
+      return
+    }
+    stats.duration.count++
+    stats.duration.sum.us += (span._duration * 1000)
+    return true
+  }
+
+  getOrCreateStats (resource, outcome) {
+    const key = [resource, outcome].join('')
+    let stats = this.statsMap.get(key)
+    if (stats) {
+      return stats
+    }
+
+    if (this.statsMap.size >= LIMIT_STATS) {
+      return
+    }
+    stats = {
+      duration: {
+        count: 0,
+        sum: {
+          us: 0
+        }
+      },
+      destination_service_resource: resource,
+      outcome: outcome
+    }
+    this.statsMap.set(key, stats)
+    return stats
+  }
+
+  encode () {
+    return Array.from(this.statsMap.values())
+  }
+
+  size () {
+    return this.statsMap.size
+  }
+}
+
+module.exports = {
+  DroppedSpanStats
+}

lib/instrumentation/index.js

@@ -357,6 +357,7 @@ Instrumentation.prototype.addEndedSpan = function (span) {
   }
 
   if (!span.isRecorded()) {
+    span.transaction.captureDroppedSpan(span)
     return
   }
 

lib/instrumentation/transaction.js

@@ -5,6 +5,7 @@ var util = require('util')
 var ObjectIdentityMap = require('object-identity-map')
 
 const constants = require('../constants')
+const { DroppedSpanStats } = require('./dropped-span-stats')
 var getPathFromRequest = require('./express-utils').getPathFromRequest
 var GenericSpan = require('./generic-span')
 var parsers = require('../parsers')
@@ -87,6 +88,7 @@ function Transaction (agent, name, ...args) {
   this._service = undefined
   this._message = undefined
   this._cloud = undefined
+  this._droppedSpanStats = new DroppedSpanStats()
   this.outcome = constants.OUTCOME_UNKNOWN
 }
 
@@ -280,6 +282,9 @@ Transaction.prototype.toJSON = function () {
     payload.links = this._links
   }
 
+  if (this._droppedSpanStats.size() > 0) {
+    payload.dropped_spans_stats = this._droppedSpanStats.encode()
+  }
   return payload
 }
 
@@ -433,6 +438,10 @@ Transaction.prototype._captureBreakdown = function (span) {
   }
 }
 
+Transaction.prototype.captureDroppedSpan = function (span) {
+  return this._droppedSpanStats.captureDroppedSpan(span)
+}
+
 function transactionBreakdownDetails ({ name, type } = {}) {
   return {
     name,

test/instrumentation/dropped-span-stats.test.js

@@ -0,0 +1,141 @@
+'use strict'
+const agent = require('../..').start({
+  serviceName: 'test-span-stats',
+  captureExceptions: false,
+  metricsInterval: 0,
+  centralConfig: false,
+  cloudProvider: 'none',
+  spanCompressionEnabled: true,
+  spanCompressionExactMatchMaxDuration: '60ms',
+  spanCompressionSameKindMaxDuration: '50ms'
+})
+
+const tape = require('tape')
+const { OUTCOME_FAILURE, OUTCOME_SUCCESS } = require('../../lib/constants')
+
+const destinationContext = {
+  service: {
+    resource: 'foo'
+  }
+}
+tape.test(function (suite) {
+  suite.test('test DroppedSpanStats invalid cases', function (test) {
+    const transaction = agent.startTransaction('trans')
+    const span = agent.startSpan('foo', 'baz', 'bar', { exitSpan: true })
+    span.setDestinationContext(destinationContext)
+    span.setOutcome(OUTCOME_SUCCESS)
+    span.end()
+
+    test.ok(transaction.captureDroppedSpan(span))
+
+    test.ok(!transaction.captureDroppedSpan(null))
+
+    span.setOutcome(OUTCOME_SUCCESS)
+    span.setDestinationContext({
+      service: {}
+    })
+    test.ok(!transaction.captureDroppedSpan(span))
+
+    transaction.end()
+    test.end()
+  })
+
+  suite.test('test DroppedSpanStats objects', function (test) {
+    const transaction = agent.startTransaction('trans')
+    for (let i = 0; i < 2; i++) {
+      const span = agent.startSpan('foo', 'baz', 'bar', { exitSpan: true })
+      span.setDestinationContext(destinationContext)
+      span.setOutcome(OUTCOME_SUCCESS)
+      span.end()
+      test.ok(
+        transaction.captureDroppedSpan(span)
+      )
+    }
+
+    for (let i = 0; i < 3; i++) {
+      const span = agent.startSpan('foo', 'baz', 'bar', { exitSpan: true })
+      span.setDestinationContext(destinationContext)
+      span.setOutcome(OUTCOME_FAILURE)
+      span.end()
+      test.ok(
+        transaction.captureDroppedSpan(span)
+      )
+    }
+
+    for (let i = 0; i < 4; i++) {
+      const span = agent.startSpan('foo', 'baz', 'bar', { exitSpan: true })
+      span.setDestinationContext({
+        service: {
+          resource: 'bar'
+        }
+      })
+      span.setOutcome(OUTCOME_SUCCESS)
+      span.end()
+      span._duration = 1000 // override duration so we can test the sum
+      test.ok(
+        transaction.captureDroppedSpan(span)
+      )
+    }
+    transaction.end()
+
+    // three distinct resource/outcome pairs captured
+    test.equals(transaction._droppedSpanStats.statsMap.size, 3)
+
+    const payload = transaction._encode()
+    const stats = payload.dropped_spans_stats
+    test.equals(stats[0].duration.count, 2)
+    test.equals(stats[0].destination_service_resource, 'foo')
+    test.equals(stats[0].outcome, OUTCOME_SUCCESS)
+
+    test.equals(stats[1].duration.count, 3)
+    test.equals(stats[1].destination_service_resource, 'foo')
+    test.equals(stats[1].outcome, OUTCOME_FAILURE)
+
+    test.equals(stats[2].duration.count, 4)
+    test.equals(stats[2].destination_service_resource, 'bar')
+    test.equals(stats[2].duration.sum.us, 4000000)
+    test.equals(stats[2].outcome, OUTCOME_SUCCESS)
+
+    test.end()
+  })
+
+  suite.test('test DroppedSpanStats max items', function (test) {
+    const transaction = agent.startTransaction('trans')
+    for (let i = 0; i < 128; i++) {
+      const destinationContext = {
+        service: {
+          resource: 'foo' + i
+        }
+      }
+      const span = agent.startSpan('foo', 'baz', 'bar', { exitSpan: true })
+      span.setDestinationContext(destinationContext)
+      span.setOutcome(OUTCOME_FAILURE)
+      span.end()
+      test.ok(transaction.captureDroppedSpan(span))
+    }
+
+    // one too many
+    const span = agent.startSpan('foo', 'baz', 'bar', { exitSpan: true })
+    span.setDestinationContext(destinationContext)
+    span.setOutcome(OUTCOME_FAILURE)
+    span.end()
+    test.ok(!transaction.captureDroppedSpan(span))
+
+    // and we're still able to increment spans that fit the previous profile
+    const span2 = agent.startSpan('foo', 'baz', 'bar', { exitSpan: true })
+    span2.setDestinationContext({
+      service: {
+        resource: 'foo0'
+      }
+    })
+    span2.setOutcome(OUTCOME_FAILURE)
+    span2.end()
+    test.ok(transaction.captureDroppedSpan(span2))
+
+    transaction.end()
+    test.equals(transaction._droppedSpanStats.statsMap.size, 128)
+    test.end()
+  })
+
+  suite.end()
+})

test/instrumentation/transaction.test.js

@@ -499,11 +499,17 @@ test('#_encode() - dropped spans', function (t) {
   trans.result = 'result'
   var span0 = trans.startSpan('s0', 'type0')
   trans.startSpan('s1', 'type1')
-  var span2 = trans.startSpan()
+  var span2 = trans.startSpan('s2', { exitSpan: true })
+  span2.setDestinationContext({
+    service: {
+      resource: 'foo'
+    }
+  })
   if (span2.isRecorded()) {
     t.fail('should have dropped the span')
   }
   span0.end()
+  span2.end()
   trans.end()
 
   agent.flush(function () {
@@ -527,7 +533,7 @@ test('#_encode() - dropped spans', function (t) {
       started: 2,
       dropped: 1
     })
-
+    t.equals(payload.dropped_spans_stats.length, 1)
     agent._conf.transactionMaxSpans = oldTransactionMaxSpans
     t.end()
   })