High startup memory when using @opentelemetry/instrumentation-fs

[adam-kiss-sg]

What version of OpenTelemetry are you using?

    "@opentelemetry/api": "^1.3.0",
    "@opentelemetry/auto-instrumentations-node": "^0.36.0",
    "@opentelemetry/instrumentation": "^0.34.0",
    "@opentelemetry/resources": "^1.8.0",
    "@opentelemetry/sdk-trace-base": "^1.8.0",
    "@opentelemetry/sdk-trace-node": "^1.8.0",
    "@opentelemetry/semantic-conventions": "^1.8.0",

What version of Node are you using?

18

What did you do?

I'm using opentelemetry with the auto instrumentation package. After updating opentelemetry packages to latest version, i realized that the memory usage of my container during application startup went from ~200MiB to ~600MiB. After disabling @opentelemetry/instrumentation-fs, the memory usage went back to normal.

What did you expect to see?

No change in memory usage.

What did you see instead?

Memory usage went up by ~400MiB during starup.

Additional context

After realizing the problem, I traced it back to the version update of @opentelemetry/auto-instrumentations-node from 0.33.x to 0.34.x, to this commit: https://github.com/open-telemetry/opentelemetry-js-contrib/pull/981/files . From there i realized the @opentelemetry/instrumentation-fs instrumentation that was added is causing the high memory usage. I tried disabling it with:

registerInstrumentations({
  instrumentations: [
    getNodeAutoInstrumentations({
      '@opentelemetry/instrumentation-fs': {
        enabled: false,
      },
    }),
  ],
})

This solved the memory issue.

The high memory usage appeared both when running the container in wsl, and on AWS ECS (fargate).

[dyladan]

Can we have a little more info here? How many fs spans are being created and do you have an estimate of how many files are read at startup of your application? Does the memory use drop to normal after the startup or does it stay high? The FS instrumentation may be able to be optimized a bit more to reduce memory use.

[adam-kiss-sg]

How many fs spans are being created?

There are not many fs spans:

• 4 statSync
• 3 readFileSync
  all less than 30μs

Do you have an estimate of how many files are read at startup?

If you don't count require, i don't think there is many file reads (nestjs might be reading some files). If you do count require, then the number of files in "dist" and "node_modules" are:

$ find dist | wc -l
98
$ find node_modules | wc -l
19814

Does the memory use drop to normal after the startup or does it stay high?
It drops back to normal

Here is a graph, with two containers running on aws ecs, the only difference is whether i enable fs-instrumentation or not:

After the startup the memory is the same, but there is a huge spike during startup when fs-instrumentation is enabled.

Some more info about the project:
It's a minimal project (really, just the skeleton of a new application), using:

• aws sdk (^3.110.0)
• nestjs (^9.2.1)
• opentelemetry (everything latest)
• mongodb (^4.13.0)

[Flarna]

I assume that require calls will also result in spans because fs is used internally and there is no parent span required (Refs: #1335 which adds this).

I guess you could use the createHook of fs instrumentation to avoid that fs instrumentation creates spans in cases you don't need them (e.g. app startup, no parent span active, within node_modules folder,...).

[kirrg001]

Experiencing the same. Over 1000 spans are created when the application is bootstrapped caused by fs-instrumentation. The memory usage is over 100% for ~11 seconds.

If I set requireParentSpan: true and the problem is resolved. But that is not a real solution, because any fs call which have no parent are not traced.

[github-actions]

This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 14 days.

[cartermp]

I think we should strongly consider disabling the fs instrumentation by default when using autoinstrumentations-node. It's fine to include it in the package graph, but off by default feels right to me.

Just had a customer run into a befuddling issue:

Dropped 486 spans because maxQueueSize reached

And the reason was because fs was creating a span for every file node was opening at startup. In Honeycomb's docs we have a line telling people to do this (and a code sample), but most people don't start by reading the docs. We could likely do this for the otel docs as well, but I still expect people will run into this.

The spans themselves are generally of low value -- it serves little purpose to know that node opened N files at startup.

I'm happy to contribute a PR if folks think this is a good idea.

[Flarna]

I fully agree. For traces more isn't better.

I assume it's useful at application runtime but not to trace the startup.
Main issue is likely that it must be registered at startup to ensure it instruments all fs API before the uninstrumented ones are cached at a lot places..

Some other options I have in mind:

• suppress node_modules folder on default
• add some API in the instrumentation to switch it to "active" mode once application has started (enable/disable wont work as it tries to unpatch/re-patch).

[github-actions]

This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 14 days.

[github-actions]

This issue was closed because it has been stale for 14 days with no activity.