Extremely slow startup around aws-sdk on javascript

[jreichhold]

Added basic node opentelemetry and after noticing extremely slow startup added some Diag debug logs and noticed an extreme slowness related to aws-sdk instrumentation: applying patch to aws-sdk v3 client send. In the log below over 6 min between log lines. It is interesting to note the CPU is 100% pegged during this.

version in package.json are

   "@aws-sdk/client-dynamodb": "^3.163.0",
    "@aws-sdk/client-s3": "^3.163.0",
    "@aws-sdk/client-sqs": "^3.163.0",
    "@aws-sdk/credential-provider-node": "^3.163.0",
    "@aws-sdk/lib-dynamodb": "^3.163.0",
    "@aws-sdk/node-http-handler": "^3.162.0",
    "@aws-sdk/s3-request-presigner": "^3.163.0",
    "@aws-sdk/util-dynamodb": "^3.163.0",
    "@onesignal/node-onesignal": "^1.0.0-beta4",
    "@opensearch-project/opensearch": "^2.0.0",
    "@opentelemetry/api": "^1.1.0",
    "@opentelemetry/api-metrics": "^0.31.0",
    "@opentelemetry/auto-instrumentations-node": "^0.32.0",
    "@opentelemetry/core": "^1.6.0",
    "@opentelemetry/exporter-metrics-otlp-proto": "^0.32.0",
    "@opentelemetry/exporter-trace-otlp-proto": "^0.32.0",
    "@opentelemetry/instrumentation": "^0.32.0",
    "@opentelemetry/resources": "^1.6.0",
    "@opentelemetry/sdk-metrics-base": "^0.31.0",
    "@opentelemetry/sdk-node": "^0.32.0",
    "@opentelemetry/sdk-trace-base": "^1.6.0",
    "@opentelemetry/sdk-trace-node": "^1.6.0",
    "@opentelemetry/sdk-trace-web": "^1.6.0",
    "@opentelemetry/semantic-conventions": "^1.6.0",

Full log is below with timestamps. This was via ts-node startup but similar on straight node startup.

  | 2022-08-31T20:26:16.445-07:00 | @opentelemetry/api: Registered a global for diag v1.1.0.
  | 2022-08-31T20:26:16.446-07:00 | Loading instrumentation for @opentelemetry/instrumentation-amqplib
  | 2022-08-31T20:26:16.447-07:00 | Loading instrumentation for @opentelemetry/instrumentation-aws-lambda
  | 2022-08-31T20:26:16.448-07:00 | No modules instrumentation has been defined, nothing will be patched
  | 2022-08-31T20:26:16.449-07:00 | Loading instrumentation for @opentelemetry/instrumentation-aws-sdk
  | 2022-08-31T20:26:16.451-07:00 | Loading instrumentation for @opentelemetry/instrumentation-bunyan
  | 2022-08-31T20:26:16.452-07:00 | Loading instrumentation for @opentelemetry/instrumentation-cassandra-driver
  | 2022-08-31T20:26:16.453-07:00 | Loading instrumentation for @opentelemetry/instrumentation-connect
  | 2022-08-31T20:26:16.455-07:00 | Loading instrumentation for @opentelemetry/instrumentation-dns
  | 2022-08-31T20:26:16.456-07:00 | Loading instrumentation for @opentelemetry/instrumentation-express
  | 2022-08-31T20:26:16.457-07:00 | Loading instrumentation for @opentelemetry/instrumentation-fastify
  | 2022-08-31T20:26:16.459-07:00 | Loading instrumentation for @opentelemetry/instrumentation-generic-pool
  | 2022-08-31T20:26:16.460-07:00 | Loading instrumentation for @opentelemetry/instrumentation-graphql
  | 2022-08-31T20:26:16.461-07:00 | Loading instrumentation for @opentelemetry/instrumentation-grpc
  | 2022-08-31T20:26:16.464-07:00 | Loading instrumentation for @opentelemetry/instrumentation-hapi
  | 2022-08-31T20:26:16.465-07:00 | Loading instrumentation for @opentelemetry/instrumentation-http
  | 2022-08-31T20:26:16.466-07:00 | Loading instrumentation for @opentelemetry/instrumentation-ioredis
  | 2022-08-31T20:26:16.467-07:00 | Loading instrumentation for @opentelemetry/instrumentation-knex
  | 2022-08-31T20:26:16.468-07:00 | Loading instrumentation for @opentelemetry/instrumentation-koa
  | 2022-08-31T20:26:16.470-07:00 | Loading instrumentation for @opentelemetry/instrumentation-lru-memoizer
  | 2022-08-31T20:26:16.471-07:00 | Loading instrumentation for @opentelemetry/instrumentation-memcached
  | 2022-08-31T20:26:16.472-07:00 | Loading instrumentation for @opentelemetry/instrumentation-mongodb
  | 2022-08-31T20:26:16.473-07:00 | Loading instrumentation for @opentelemetry/instrumentation-mysql2
  | 2022-08-31T20:26:16.474-07:00 | Loading instrumentation for @opentelemetry/instrumentation-mysql
  | 2022-08-31T20:26:16.476-07:00 | Loading instrumentation for @opentelemetry/instrumentation-nestjs-core
  | 2022-08-31T20:26:16.477-07:00 | Loading instrumentation for @opentelemetry/instrumentation-net
  | 2022-08-31T20:26:16.478-07:00 | Loading instrumentation for @opentelemetry/instrumentation-pg
  | 2022-08-31T20:26:16.479-07:00 | Loading instrumentation for @opentelemetry/instrumentation-pino
  | 2022-08-31T20:26:16.480-07:00 | Loading instrumentation for @opentelemetry/instrumentation-redis
  | 2022-08-31T20:26:16.482-07:00 | Loading instrumentation for @opentelemetry/instrumentation-redis-4
  | 2022-08-31T20:26:16.483-07:00 | Loading instrumentation for @opentelemetry/instrumentation-restify
  | 2022-08-31T20:26:16.484-07:00 | Loading instrumentation for @opentelemetry/instrumentation-winston
  | 2022-08-31T20:26:25.683-07:00 | @opentelemetry/instrumentation-http Applying patch for http@18.7.0
  | 2022-08-31T20:26:35.776-07:00 | Applying patch for net module
  | 2022-08-31T20:26:42.234-07:00 | Applying patch for express@4.18.1
  | 2022-08-31T20:26:43.248-07:00 | @opentelemetry/instrumentation-http Applying patch for https@18.7.0
  | 2022-08-31T20:27:53.558-07:00 | aws-sdk instrumentation: applying patch to aws-sdk v3 constructStack
  | 2022-08-31T20:27:58.260-07:00 | aws-sdk instrumentation: applying patch to aws-sdk v3 client send
  | 2022-08-31T20:34:25.158-07:00 | EnvDetector found resource. Resource { attributes: { 'service.name': 'xxx-jonathan' } }

tracing.ts is

/* eslint-disable no-console */
import { NodeSDK } from '@opentelemetry/sdk-node';
import { getNodeAutoInstrumentations } from '@opentelemetry/auto-instrumentations-node';
import { diag, DiagConsoleLogger, DiagLogLevel } from '@opentelemetry/api';
import { Resource } from '@opentelemetry/resources';
import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-proto';
import { SemanticResourceAttributes } from '@opentelemetry/semantic-conventions';

const startTime = new Date();
console.log(`Starting tracing ${startTime.toISOString()}`);
// The Trace Exporter exports the data to Honeycomb and uses
// the environment variables for endpoint, service name, and API Key.
const traceExporter = new OTLPTraceExporter();

// For troubleshooting, set the log level to DiagLogLevel.DEBUG
diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.INFO);

const resource = new Resource({
  [SemanticResourceAttributes.SERVICE_NAME]: 'api-service',
});

const anotherResource = new Resource({
  'service.version': '0.1.0',
  'service.group': 'instrumentation-group',
});

const mergedResource = resource.merge(anotherResource);

const sdk = new NodeSDK({
  resource: mergedResource,
  traceExporter,
  instrumentations: [getNodeAutoInstrumentations()],
});

sdk.start()
  .then(() => {
    const initTime = new Date();
    console.log(`${initTime.toISOString()} Tracing initialized in ${(initTime.getTime() - startTime.getTime()) / 1000} seconds`);
  })
  .catch((error) => console.log('Error initializing tracing', error));

// gracefully shut down the SDK on process exit
process.on('SIGTERM', () => {
  sdk.shutdown()
    .then(() => console.log('Tracing terminated'))
    .catch((error) => console.log('Error terminating tracing', error))
    .finally(() => process.exit(0));
});

[legendecas]

This might be related to #3029.

[jreichhold]

Oddly adding more direct instruments doesn't slow down startup. Have 8 now and startup is basically the same as one.

[jreichhold]

no, that was incorrect. With 8 the startup is now about 30 seconds.

[dyladan]

the code on auto-instrumentation-node is not code at all. it is just a metapackage that installs a bunch of other packages including instrumentations you likely aren't using. The problem is that each registered instrumentation replaces require with a wrapped version of require which intercepts the argument and sees if the return value needs to be replaced. If you have many instrumentations you end up in a situation where require has been wrapped many times. The more files are in your project, the larger performance impact this has.

[dyladan]

Here is a PR which attempts to solve this but it has been left in draft state #3161

[jreichhold]

This has nothing to do with the size of my project and think the performance impact on startup alone is enough that this needs a deeper look. The fact that just use the meta package makes startup 3-5 minutes before any of my normal code is even loaded is a bit messy for every project out there. Just adding tracer.js as a require would hit this startup issue on an empty project. If this isn't fixed I would be stripping things from the auto instrumentation or at least warning users on the impact. I'm used to runtime issues with having too much instrumented but never really had startup be minutes from adding observability. Just adding tracer.js as a require would hit this startup issue on an empty project. I've never dug deep into the require in the middle side but really wonder if usage on the core instrumentation should be rethought.