Node process performance degradation

[toniov]

Hi there,

I think the tracer is having a considerable effect in my node processes performance. When there is a low or moderate load it's not appreciable, but during peak time period the CPU usage grows more than double than before (server load average that used to be 0.5 going to around 2, for example).

Didn't have the chance to profile the app, but the behavior I explained above happened only in the two servers I installed the tracer.

My configuration and other details:

const tracer = require('dd-trace').init({ plugins: false });
tracer.use('express');
tracer.use('http');
tracer.use('elasticsearch');
tracer.use('mysql');

Node version: 8.11.3
Express version: 4.16.3
dd-trace version: 0.5.6
elasticsearch version: 15.1.1
mysql version: 2.11.1

[rochdev]

How many spans are generated on average for each request, and how many req/sec are you getting?

If you could provide any output from profiling it would definitely be helpful as well.

Also, just to confirm, are these server load average numbers CPU percentage?

[toniov]

I'm getting around 200 req/sec per instance, spanning 3 Node processes, so around 66 req/sec per process. Also I think around 3 spans are generated on average each request.

By load average I meant the same that top or uptime show: average of the number of processes which are being executed by the CPU or in waiting state. I just mentioned it to give an idea about how it's affecting the system, globally speaking.
Said as CPU percentage, Node processes went from like 30% of CPU utilization to around 70% during peak time period after installing the tracer.

[rochdev]

In my own testing, I am unable to reproduce such a big impact for just a couple hundred requests. If you could provide profiling data it would be very helpful.

If the profiling data is sensitive, please PM me in our public Slack or contact support (you can mention me to them so they can forward it to me).

[ibolmo]

I've ran into this as well. Doing some flamegraphs I discovered that the require-in-the-middle causes most functions imported to no longer be optimized by V8:

Here's the flamegraph with dd-agent:

Here's the flamegraph without dd-trace:

[rochdev]

Since require-in-the-middle is only executed when require is called (which in most cases only happens when the app starts) I doubt it would make an impact at runtime.

@ibolmo Can you try with dd-trace, but with plugins disabled? I wonder if maybe the graphql plugin is at fault in your case.

[ibolmo]

@rochdev I agree with the assumption but here's another look with empirical data:

with tracer on:

without tracer on:

It's the same uncached request and payload. Same amount of work the graphql js has to process, but my theory is that the require-in-the-middle doesn't permit v8 to properly optimize the call. Thus every cal is dramatically slower.

[rochdev]

One way to test this theory would be to completely exclude dd-trace from the equation and try using only require-in-the-middle.

You could do that with the following snippet:

const Hook = require('require-in-the-middle')
const modules = [
  'graphql/execution/execute.js',
  'graphql/language/parser.js',
  'graphql/validation/validate.js'
]

Hook(modules, (exports, name, basedir) => exports)

If you still get the same behavior, then we'll know for sure it's related to require-in-the-middle. Otherwise it means it's most probably something else.

[bengl]

There hasn't been any activity on this thread in a few years, so I'm closing it. If the exact same issue is coming up for anyone, please still feel free to comment or reopen.

[rochdev]

It's also very likely related to #1095