tracking bug for agent performance impact on Kibana

[trentm]

This is a tracking bug for a timeboxed effort to look at improving the Node.js APM agent's perf impact in Kibana.
See elastic/kibana#78792 for most details. This ticket will help for tracking agent-side work.

[trentm]

Yesterday my thoughts on a plan for this issue were:

1. Investigate each of the top items over ~2% top-of-stack from flamegraphs
   of the loaded demo "pathosapp.js"
   (truncation/encoding, tracecontext, Transaction._captureBreakdown)
2. Implement the obvious "captureSpanStackTraces=false by default", and
   a new setting to only capture span stack traces for slow spans.
3. Profile and possibly improve stack trace capturing (used for
   captured errors and ^^^ slow spans).
4. Run Kibana DemoJourney with APM agent stripped to barebones core
   async-hook that is the foundation of tracing async context as a
   guide for "how low we can go" on overhead.
5. Learn (and possibly integrate) agent ability to get profiles of
   part of an app run using pprof-nodejs (building on Dario's PoC
   https://github.com/dgieselaar/apm-agent-nodejs/tree/pprof-poc/).
   This could be used for debugging customer perf issues (get a
   profile from prod to analyze offline) and is the likely basis
   for a profiling feature in the Node.js APM agent.
6. Add one or more benchmarks to the agent's current benchmark system
   that covers encoding of spans/transactions/errors for ongoing
   tracking.

Timebox to another 2 weeks max, then time to move on.

Future work:

• Investigate cachegrind technique for stable benchmarking
  (https://github.com/pythonspeed/cachegrind-benchmarking).
• WG Perf (https://github.com/elastic/observability-dev/issues/1248)

[trentm]

1. Investigate each of the top items over ~2% top-of-stack from flamegraphs
   of the loaded demo "pathosapp.js"
   (truncation/encoding, tracecontext, Transaction._captureBreakdown)

That flamegraph is here: https://gist.github.com/trentm/c70154cc6674a000f6b4c0827e3f0183
Screenshot:

Top "top-of-stack" items there are:

• breadthFilter (top of stack: 4.8% of samples in this profile) and Client._encode (top of stack: 3%) in apm-nodejs-http-client. This is the so-called "truncation" work. My thoughts/comments on this are in this comment below.
• "lib/tracecontext/..." (top of stack: 2.7%) spread over a number of stacks. Alan looks at this in Perf Work: Investigate TraceContext/TraceState #2056
• Transaction._captureBreakdown (top of stack: 2.5%)
• ... next is 1.3% top-of-stack or lower.

[trentm]

a look at Client._encode et al perf

Here I show data from a number of DemoJourney kibana-load-testing runs against a dev mode Kibana v7.12.0 on my laptop (2019 MBP, 2.4GHz Core i9, 64G RAM) with tweaks to the APM agent.

Base APM config is:

{
  active: true,
  serverUrl: 'http://127.0.0.1:8200',
  centralConfig: false,
  breakdownMetrics: false,
  transactionSampleRate: 0.1,
  metricsInterval: '120s',
  captureHeaders: false,
  captureBody: 'off',
  logUncaughtExceptions: true,
  captureSpanStackTraces: false
}

The data is the "Global Information" from the DemoJourney report for each run. The values are in milliseconds.
Here is the data in a spreadsheet.

                                min     p50     p75     p95     p99       max    mean   stddev
baseline (no APM)
  demojourney-20210422210946639  11      82     195     578      877     1720     152     188
  demojourney-20210422211752793  11      84     213     602      924     1624     159     195
  demojourney-20210422212632139  11      85     248     609      970     1453     168     209
  demojourney-20210422214929820  11      89     216     593      967     1423     163     202

with APM (yarn add link:../apm-agent-nodejs; i.e. v3.14.0 of the agent)
  demojourney-20210422191919074  12      90     214     696     1231     2072     176     241
  demojourney-20210422192943594  12     104     244     666      975     1705     179     221
  demojourney-20210422194110834  12      96     230     618      955     1536     168     206

with APM (back to agent v7.10.0, as a sanity check)
  demojourney-20210422220144348  12      84     208     592      911     1497     158     196
  demojourney-20210422221044599  12      83     200     586      961     1466     157     198

with APM (yarn add elastic-apm-node@3.14.0)
  demojourney-20210422222345996  12      91     216     551     1003     1559     161     198
  demojourney-20210422223249288  12      87     219     612      962     1575     163     205
  demojourney-20210422225030336  12      82     203     590      980     1693     158     208
  demojourney-20210422225827807  12      86     197     685      960     1292     165     211
  demojourney-20210422230632355  12      85     222     616      991     1455     163     208

baseline (no APM, *again* as sanity check)
  demojourney-20210422232018753  11      74     182     522      871     1237     142     177
  demojourney-20210422232815319  11      85     211     602      908     1308     160     195
  demojourney-20210422233613017  11      71     187     543     1000     1337     144     196

with APM (noop redact, noop Client._encode)
  demojourney-20210422202202398  12      97     238     655      969     1579     176     213
  demojourney-20210422203146572  12      96     230     594      933     1400     166     199
  demojourney-20210422210103812  12     112     262     673     1012     2019     193     239
... same again later in the day (me trying harder not to make computer busy):
  demojourney-20210422235152556  12      83     191     535      933     1444     150     190
  demojourney-20210422235950181  12      96     235     597      928     1189     166     196
  demojourney-20210423000747805  12      84     198     562      940     1297     150     186

The "noop redact" and "noop Client._encode" are patches against the Node.js APM agent to mostly eliminate that processing.

Earlier runs (e.g. those with "demojourney-2021042220" and "demojourney-2021042221" prefix) were a bit noisier as I wasn't completely hands-off my laptop during those runs -- or at least that's the hypothesis for why those showed slightly higher p50 values.

Conclusions

Looking (mostly) at the p50, my conclusion here is that there is too much noise in the results here to clearly separate out impact of Client._encode and redacting APM agent code.

• The range of p50 values (the spreadsheet shows the calculated stddev) "with APM" overlaps with the range with "no APM".
• The percentage increase in p50 "with APM" (over the baseline) is less than with APM with the Client._encode work noop'd out, which obviously doesn't make sense.

With many runs of the DemoJourney we can eek out a general trend of "yes there is some APM agent impact", but not precise enough to measure small (single-digit percentage points) improvements in agent perf.

I think we should move on to steps 2 and later in the "plan" from the earlier comment. Small perf improvements in the agent should still be looked at, but not in this block of work for Kibana+APM. Subsequent DemoJourney comparisons should be done against cloud deployments (as described at https://github.com/elastic/kibana-load-testing#readme) to be somewhat closer to the real thing.

[trentm]

Some updates on my perf look at async_hooks usage in the agent:

• If an app is very async-op heavy -- the number of promises, nextTicks, setImmediates, setTimeouts are large per transaction -- then the impact of node's async_hooks can be significant. (Using node pathosapp.js deep_callstack can simulate an extreme version of this: with a 1000-deep nextTick stack per request and no other processing, loading to 1000 req/s, without the agent CPU<40%, with the agent CPU is pinned and can only sustain ~600 req/s.)
• Our agent's async-hook.js does more bookkeeping than it should, but I doubt this will be a significant impact on Kibana. Profiling actual Kibana is the best next way to prove that. I've looked into Investigation about async-hooks #1697 some, but wasn't able to produce the extreme perf issue hinted at by the two user examples given there.
• Using asyncHooks=false does significantly reduce overhead for the extreme simulated cases. However, I'm not clear if we want to recommend using that config for Kibana -- mainly because I'm not sure one what we are trading off using the "patch-async.js" context manager.
  TODO: some more DemoJourney runs (I've started some) should be able to
  show if the p50 can be improved with asyncHooks=false

[trentm]

This issue was intended to track a timeboxed perf effort on the Node.js APM agent -- mainly motivated by usage of the Node.js agent by the Kibana team. I'm closing this issue with a summary of what improvements we've made lately and some thoughts for future perf work.

Improvements:

• Communication between agent and APM server was improved to gracefully cope with a down or overloaded APM server. Before this an APM agent running in a busy service could overly consume CPU and introduce large latency bubbles with long synchronous hogging of the event loop. The addition of backoff and queueing also helps ensure agents don't overload a taxed APM server. fix: blocking behaviour under load apm-nodejs-http-client#144
• ELASTIC_APM_SPAN_FRAMES_MIN_DURATION was implemented so that the relatively expensive stacktrace collection is skipped by default for short spans. This is a large improvement in default agent behaviour -- important for fleet deployments. perf: don't collect stack traces on short spans  #2081
• fix: remove .entries and Object.entries in for loops to improve flamegraph perf #2066 improved perf of a top agent stack frame from performance testing.
• perf: refactor error capture and stacktrace collection #2094 significantly improved the performance of error capture and stacktrace collection (important for non-error span stacktrace collection).

A before vs. after run of a simulated workload (80% transaction, 17% transaction + some spans, 3% errors) of an Express.js app loaded to 500 req/s show a significant reduction in CPU usage:

and latency percentiles:

Percentile	Before	After
10%	0.0064s	0.0053s
25%	0.0124s	0.0103s
50%	0.0217s	0.0201s
75%	0.0305s	0.0287s
90%	0.0363s	0.0341s
95%	0.0405s	0.0373s
99%	0.0846s	0.0479s

Future work

• We'll be adding some scripts/tooling to the repo to help with subsequent performance analysis.
• Flame graphs for simulated load runs (provided by this tooling) show more top stacks that should be consider, in particular breakdown calculation.
• The performance label marks a number of issues for future work.
• Work on continuous profiling as an APM feature and for use in one-off in-production performance analysis should continue.
• The Node.js APM agent should grow Async Local Storage-based context tracking.
• Investigate cachegrind technique for stable benchmarking (https://github.com/pythonspeed/cachegrind-benchmarking).