[7.16.0 BC2] Potential memory leak observed - possibly caused by perf_hooks usage

[pmuellr]

I built a 7.16.0 BC1 deployment in our cloud staging env the other day, and loaded it up with my usual alerting load test - 100 index threshold rules running with a 1s interval - the rule is doing very little i/o itself, this is a "framework" test to make sure the framework is holding up. Deployment name is pmuellr 7.16.0 BC1

I noticed some memory growth over time:

I've restarted Kibana twice, to tweak the task manager config to get it to run rules more frequently, in hopes of accelerating the memory growth - expecting an OOM this weekend.

To check to see if this was alerting, or maybe a general Kibana issue, I built another deployment named pmuellr 7.16.0 BC1 do nothing. It is literally doing nothing :-) It looks like it is also slowly leaking, but maybe too soon to tell:

For reference, here is the same setup, but for 7.15.1, which I've been doing other testing with, so has a little more variablity the last few days, but obviously does not look like the memory metrics are increasing like the other two:

So my current guess is that this may be a leak in some core Kibana service, and with alerting driving more service calls, it's aggravating the memory leak. For example, in play here with alerting are Saved Objects, es client library, the new execution context (async hook) stuff, etc. Also Task Manager.

[elasticmachine]

Pinging @elastic/kibana-core (Team:Core)

[elasticmachine]

Pinging @elastic/kibana-alerting-services (Team:Alerting Services)

[pmuellr]

an update on the first graph at the top:

The curve is starting to trend down!

So maybe this isn't a leak - maybe node v16 used in 7.16 (v14 in 7.15) is "smarter" about using memory - basically using as much as it possibly can, instead of trying to GC stuff so often. I was thinking that curve would go up and it would eventually OOM.

I tried running 7.16 locally, in dev mode (quickest way for me to get started), same rule load test, let it run overnight. Took a heap snapshot once the rules started running, and then again this morning. Nothing substantial in the comparison view! Which I first thought was maybe because dev mode was doing something different, or maybe the graphs we're seeing aren't what I'm used to seeing (for instance, these aren't RSS or heap sizes, some container based measurement of the memory used).

So ...perhaps nothing to see here. I'll poke around the node / v8 docs to see if there was a change to the memory management in v16

[rudolf]

Once we've enabled monitoring we'll be better able to tell how much is heap vs RSS memory.

[ymao1]

For an apples to apples comparison, I created 4 clusters on GCP in the same region with the same configuration

xpack.task_manager.max_workers: 50
xpack.task_manager.poll_interval: 1000

I'm also using es-apm-sys-sim to generate sample data for the clusters with rules every 2 seconds, 25 hosts.

2 of them are on 7.15.1 and 2 are on 7.16.0 BC2. I loaded 150 rules running at 1s interval on a 7.15.1 deployment and a 7.16.0-BC2 deployment and let them run overnight. Here are the memory charts after 16 hours:

7.15.1 empty

7.15.1 with rules

7.16.0 empty

7.16.0 with rules

To summarize what I'm seeing:
On 7.15.1, memory stays steady around 37% utilization for an empty Kibana. With 150 rules running at a high interval, memory increases to around 52% utilization but holds steady around there, so an increase of 15%.

On 7.16.0-BC2, memory starts at 45% and has increased to 49% on an empty Kibana after 16 hours. With 150 rules running at a high interval, memory increases to around 60% utilization (a 15% increase) and steadily increases until ~83% utilization where it looks like some sort of garbage collection kicks in and drops it back down to 60% again. This took around 13 hours

[ymao1]

I've enabled monitoring on the 2 7.16.0 deployments. Monitoring cluster here: https://ymao-monitoring.kb.europe-west1.gcp.cloud.es.io:9243/

[rudolf]

I've created the following visualization to show heap used vs RSS https://ymao-monitoring.kb.europe-west1.gcp.cloud.es.io:9243/app/lens#/edit/c69320d0-38c0-11ec-ad24-a7cfc3f6acda?_g=(filters:!(),refreshInterval:(pause:!f,value:10000),time:(from:now-1d,to:now))

[ymao1]

Latest memory charts for 7.16. BC2 deployments (over the last 80 hours)

7.16.0 empty

7.16.0 with rules

[pmuellr]

I'm seeing similar graphs. None of the deployments I created last week to test this have OOM'd (BC1 and BC2, w/rules and w/o). The ones with rules have the sawtooth pattern, never hitting 100%. I suspect the ones without rules will have a sawtooth pattern looking over much longer ranges of time.

So ... not looking like a leak to me at this point - a change in GC behavior in v8/node? Delaying big GCs for longer?

[ymao1]

I agree that it is likely a change in behavior with Node16/v8

I ran some local deployments using I used Node's --expose-gc option to force garbage collection and then print out memory usage at the end of each alerting task runner run. Then I ran 50 rules at 3s intervals for 2 hours and compared the memory usage snapshot from the beginning to the end of the 2 hour run:

For 7.15.1:

rss -16.76MB
heapTotal -33MB
heapUsed -0.25MB

For 7.16.0 commit f96311fd9e23f56630a5cf16024c87b63f2efb8f right before NodeJS upgrade:

rss -13.91MB
heapTotal -34MB
heapUsed -1.43MB

For 7.16.0 commit e1503d4658ed02081faecbc794e3f00e461df38a - NodeJS upgrade:

rss +34.83MB
heapTotal +16.25MB
heapUsed +12.37MB

For 7.16.0 BC2

rss +39.96MB
heapTotal +15MB
heapUsed +13.21MB

Not the most scientific of tests but definitely shows to me the difference in how memory is used pre Node 16 vs post Node 16 upgrade.

[ymao1]

@rudolf @elastic/kibana-core Would you agree that this doesn't seem to be a memory leak, rather a change in how memory is handled by Node after the v16 upgrade? Is there anything further that alerting can do wrt to this investigation?