apm-agent-nodejs icon indicating copy to clipboard operation
apm-agent-nodejs copied to clipboard

`transactionMaxSpans` will drop spans that could have been compressed

Open trentm opened this issue 3 years ago • 0 comments

There is a bug in interaction between span compression (after https://github.com/elastic/apm-agent-nodejs/pull/2656 goes in) and transactionMaxSpans.

In the following example we make 600 mysql spans which, I believe, we'd expect to all be compressed and reported as a single composite span.

var apm = require('./').start({
  metricsInterval: '0s',
  centralConfig: false,
  cloudProvider: 'none',
  captureExceptions: false,
  spanCompressionEnabled: true
})

// Simulate a ~1ms call to MySQL (with a span).
async function callDb (sql) {
  // Hack for https://github.com/elastic/apm-agent-nodejs/issues/2611
  await Promise.resolve()

  const s = apm.startSpan(sql, 'db', 'mysql', { exitSpan: true })
  if (s) s.setDestinationContext({ service: { name: 'mysql', resource: 'mysql', type: 'db' } })
  return new Promise((resolve, reject) => {
    setTimeout(() => {
      if (s) s.end()
      resolve()
    }, 1)
  })
}

async function main () {
  var t0 = apm.startTransaction('t0')
  for (let i = 0; i < 600; i++) {
    await callDb('SELECT FROM myTable')
  }
  t0.end()
}

main()

However, instead we get a composite span of 500 mysql spans, and 100 dropped spans because of transactionMaxSpans=500:

    {
        "transaction": {
            "name": "t0",
            "type": "custom",
            "result": "success",
            "id": "98d84e8ac1e22619",
            "trace_id": "5aab922fb9d15f9cf810999aa0a438c0",
            "duration": 876.822,
            "timestamp": 1650923053195033,
            "sampled": true,
            "context": {
                "user": {},
                "tags": {},
                "custom": {},
                "service": {},
                "cloud": {},
                "message": {}
            },
            "span_count": {
                "started": 500,
                "dropped": 100
            },
            "outcome": "unknown",
            "sample_rate": 1
        }
    }
    {
        "span": {
            "name": "SELECT FROM myTable",
            "type": "db",
            "id": "f7ea06a7b2e259d1",
            "transaction_id": "98d84e8ac1e22619",
            "parent_id": "98d84e8ac1e22619",
            "trace_id": "5aab922fb9d15f9cf810999aa0a438c0",
            "subtype": "mysql",
            "action": null,
            "timestamp": 1650923053197859,
            "duration": 748.777,
            "context": {
                "destination": {
                    "service": {
                        "name": "mysql",
                        "resource": "mysql",
                        "type": "db"
                    }
                }
            },
            "sync": false,
            "outcome": "success",
            "sample_rate": 1,
            "composite": {
                "compression_strategy": "exact_match",
                "count": 500,
                "sum": 671.669
            }
        }
    }

My understanding from the spec (https://github.com/elastic/apm/blob/main/specs/agents/handling-huge-traces/tracing-spans-limit.md#implementation) is that this is a bug. We will need to adjust our transactionMaxSpans handling currently in Transaction.prototype.createSpan to follow the spec'd implementation notes (i.e. do dropping on span end).

trentm avatar Apr 25 '22 21:04 trentm