Performance of instrumentations

[mattfysh]

Hi there,

I'm adding OpenTelemetry to my lambda function and noticed quite a slow down on cold boot times:

• The lambda layer (ADOT collector) adds about 300ms (outside the scope of this repo)
• The JS instrumentation / sdk.start() code is adding about 500-700ms

I should also mention I am using autoDetectResources: false to ensure sdk.start() is fast & synchronous

The time taken to setup the SDK in the node.js process seems quite high, even when including only one instrumentation (for dns.lookup)

I know that it's probably less important in long-running code environments (such as an Express server) but is fairly important for FaaS where the code to be traced begins to execute immediately, and the function needs to return promptly

I was wondering if the opentelemetry JS projects are aware of the performance implications, and if they are something that is understood?

Cheers! :)

[mattfysh]

I'd also be interested to hear if dd-trace has this same issue. @bengl - do you have any thoughts about this issue, and if I might see improved performance if I were to switch to the DataDog stack? Thanks!

[legendecas]

It will be helpful if you can provide a list of open telemetry packages and how you bootstrap with them.

[mattfysh]

Hi @legendecas - I created https://github.com/mattfysh/otel-js-perf

Let me know if you have any trouble running. Thanks for taking a look 👍

[legendecas]

I take a quick review and found that there are the following problems that cause significant slow down in the example:

1. OTel packages are not latest: should use @opentelemetry/exporter-trace-otlp-proto v0.27.0 instead of @opentelemetry/exporter-otlp-proto v0.26.0. This could make several OTel packages to be loaded with different versions (additional ~100ms to load them).
2. Not used packages were loaded:
   1. Even though autoDetectResources: false is set, @opentelemetry/resource-detector-gcp is still going to be loaded as it is one of the static dependencies (https://github.com/open-telemetry/opentelemetry-js/blob/main/experimental/packages/opentelemetry-sdk-node/src/sdk.ts#L27). GCP detector takes up ~20ms out of ~140ms sdk-node load time. The removal of gcp detector as a static dependency of sdk-node is tracked at resource-detector-aws, resource-detector-gcp #2583.
   2. @opentelemetry/auto-instrumentations-node would take up additional ~25ms load time for instrumentation packages not used: even though the instrumentation packages are quick to load, they still take time to load. In time-sensitive situations like lambda, you can choose to pick your own curated list of instrumentation instead of loading them all.

[legendecas]

For reference, I striped non-related entries and listed every @opentelemery packages load time as the following: (duplicated versions were fixed)

Click to expand!

Tested on my local machine, the time unit was measured as milliseconds.

• require('@opentelemetry/sdk-node') 136.548036
  • require('@opentelemetry/api') 19.862197
  • require('@opentelemetry/core') 16.86047
  • require('@opentelemetry/semantic-conventions') 2.494263
  • require('@opentelemetry/sdk-metrics-base') 19.747222
  • require('@opentelemetry/api-metrics') 4.117398
  • require('@opentelemetry/resources') 5.333716
  • require('@opentelemetry/sdk-trace-node') 28.342538
  • require('@opentelemetry/context-async-hooks') 1.50248
  • require('@opentelemetry/propagator-b3') 2.547406
  • require('@opentelemetry/sdk-trace-base') 6.964066
  • require('@opentelemetry/instrumentation') 20.244452
  • require('@opentelemetry/resource-detector-aws') 8.265106
  • require('@opentelemetry/resource-detector-gcp') 21.44988
• require('@opentelemetry/auto-instrumentations-node') 25.203033
  • require('@opentelemetry/instrumentation-dns') 1.890681
  • require('@opentelemetry/instrumentation-express') 2.319187
  • require('@opentelemetry/instrumentation-graphql') 2.652578
  • require('@opentelemetry/instrumentation-grpc') 5.256924
  • require('@opentelemetry/instrumentation-http') 2.865443
  • require('@opentelemetry/instrumentation-ioredis') 1.324165
  • require('@opentelemetry/instrumentation-koa') 2.088431
  • require('@opentelemetry/instrumentation-mongodb') 1.382517
  • require('@opentelemetry/instrumentation-pg') 1.747983
  • require('@opentelemetry/instrumentation-mysql') 1.35024
  • require('@opentelemetry/instrumentation-redis') 1.365149
• require('@opentelemetry/instrumentation-aws-lambda') 1.974279
• require('@opentelemetry/id-generator-aws-xray') 1.540811
• require('@opentelemetry/exporter-trace-otlp-proto') 24.477293
  • require('@opentelemetry/exporter-trace-otlp-http') 5.356276

[mattfysh]

HI @legendecas - I made these changes as suggested, but I'm not seeing much improvement. The commit can be found here:
mattfysh/otel-js-perf@1d4b0bf

Perhaps it is related to the specific version of node AWS Lambda is running, or the limited resources made available to the function runtime. Do you have an idea of where I can go next to keep digging into this issue?

[mattfysh]

It looks like this was a Lambda configuration issue. The default 128 MB of memory was causing the slowdown, and after playing with the settings it looks like 512-1024 MB is needed to get decent response times on cold boot