Clinic HeapProfiler reports drastically different heap usage than Clinic Doctor

[robross0606]

Expected Behavior

I would expect clinic heapprofiler to show resulting memory usage similar to that of clinic doctor since one recommends you use the other as a "next step".

Current Behavior

When I repeat the same test with the two options, doctor shows heap usage in line with other tools and OS reporting in terms of overall memory usage.

However, heapprofiler shows drastically different memory reporting which leads to confusion.

Perhaps I am just misinterpreting heapprofile output, but the results are confusing when you go from one tool to the other. One says total heap reached over 6GB (which is accurate). The other says 40.31% of overall heap allocation is 1.049MB. The results don't make much sense to me.

Environment

• Clinic.js: v13.0.0
• Clinic.js doctor: v11.0.0
• Clinic.js heapprofiler: v5.0.0
• Node.js version: 18.18.0
• Browser name and version: Chrome 121.0.6167.86
• Operating system and version: Windows 10 22H2

[robross0606]

It also appears that the "Dependencies" section is broken. All the node_modules calls are showing up under "Application" while there is nothing at all on "Dependencies" and nothing in the dropdown:

[RafaelGSS]

Self allocated memory is different of memory usage. It counts how much memory allocation happened by the application during the profiling. Clinic doctor counts all the process resident set size.

It also appears that the "Dependencies" section is broken. All the node_modules calls are showing up under "Application" while there is nothing at all on "Dependencies" and nothing in the dropdown

This is a bug, possibly related to how we match files inside node_modules/. PR is welcome.

[robross0606]

Sorry, I'm still confused. Doctor shows allocation occurring within the running application, directly caused by an incoming query. I can trigger it and twist behavior on demand. Doctor tells me memory usage is high -- which it definitely is -- and then tells me to run heapprofiler. But heapprofiler shows an entirely different statistic? The nodejs app only has a single process according to debuggers. Your saying 4+ GB of memory is being allocated in some sort of hidden process? I don't understand.

I guess I'm unclear how heapprofiler can be used to help once doctor shows the problem. Is the self allocated static a total? An average for the function? If it is a total, the numbers don't seem to make sense.

[RafaelGSS]

It would help if you did not consider the self-allocated memory from heap-profiler as base of memory usage of your process. That number only tells you the amount of memory allocated by your application during the profiling. If you use a doctor with a different timeframe, the numbers won't match.

[robross0606]

If you use a doctor with a different timeframe, the numbers won't match.

It isn't a different timeframe. I'm running the same exact test over and over. I run the application, make the query, see the same results in doctor. Restart the application, run the query, see the results in heapprofiler. This is not a dynamic application right now with multiple users. This is being run isolated in a controlled debug environment. I can reproduce the same curves and information in both clinic and heapprofiler. The problem is just that I don't understand how to use heapprofileronce clinic tells me there is a problem. The stats produced by heapprofilerseem of little use and don't jive in any way with what is produced by clinic, using the same exact data and query with a reasonably similar test timeframe (~3.5 minutes).

It would help if you did not consider the self-allocated memory from heap-profiler as base of memory usage of your process.

Then why does doctor tell me the next step should be to use heapprofilerto find memory allocations? In short, the memory allocation data in heapprofilerin no way aligns with the data being captured by clinic. One shows a build-up of over 5GB of RAM used by the application over the time it takes to generate the query response. This is 100% "caused" by the query and reproducible. I just don't know what allocations are causing it. That's where I would think heapprofilerwould come into play, but it doesn't show anything like that amount of RAM being allocated so it doesn't help pinpoint the cause. All the allocations shown in heapprofiler look minor.

Maybe I'm misunderstanding the difference between a "hot" function (color) and a "wide" function (width in flame graph)?

[robross0606]

This is a bug, possibly related to how we match files inside node_modules/. PR is welcome.

I'll definitely look into this if I have time.

[RafaelGSS]

the 1GB represents 40% of your allocations as shown in the image. The goal of heapprofiler is to tell which functions are allocating more memory during the timeframe - that's why we use flamegraphs for that.

One shows a build-up of over 5GB of RAM used by the application over the time it takes to generate the query response.

It can be two things:

1. The memory allocations are somehow not being captured by clinic heapprofiler -- which I doubt since you are using Node.js 18.
2. The memory allocation of your process is happening on the native side, for instance, if you are using a database driver in C++. IIRC we aren't tracking memory allocations in the native scope.

[robross0606]

the 1GB represents 40% of your allocations as shown in the image.

I apologize for my obvious ignorance here. How can you tell 40% is 1GB in heapprofiler? I don't see anything in that tool which references "GB" at all. If you're referring to the 40% used by "V8 runtime" it says "self-allocation" is 1.049MB. Megabytes, not Gigabytes. If that were actually "1.049GB" I probably wouldn't have opened this ticket. All the numbers would make a lot more sense to me if they were "GB" which would align more closely with other observations (including clinic).

Am I just looking right past something in the UI?

The memory allocation of your process is happening on the native side, for instance, if you are using a database driver in C++. IIRC we aren't tracking memory allocations in the native scope.

Ahh... now that is interesting. This application is using Apollo (GraphQL) server with Koa, and ArangoDB for graph database (arangojs driver) back end. The database driver is just a wrapper on ArangoDB's REST API, so I don't think it uses any custom C/C++ drivers. Not sure about Apollo. I suppose it could be possible a lot of the memory is being somehow allocated on the Node.js network stack, but I thought that would appear under either "Node JS" or "V8" categories.

[robross0606]

One other thing I forgot to mention is this application is actually running out of heap and crashing when I run this query if we don't set a custom --max_old_space_size. Without forcing it, heap_size_limit defaults 4345298944 in this environment. So there is clearly something GC is unable to address during the life of this query.

[RafaelGSS]

I apologize for my obvious ignorance here. How can you tell 40% is 1GB in heapprofiler? I don't see anything in that tool which references "GB" at all. If you're referring to the 40% used by "V8 runtime" it says "self-allocation" is 1.049MB. Megabytes, not Gigabytes. If that were actually "1.049GB" I probably wouldn't have opened this ticket. All the numbers would make a lot more sense to me if they were "GB" which would align more closely with other observations (including clinic).

Right, maybe the . shouldn't be shown in the UI. The correct way to interpret it is 1.000MB = 1000MB = 1GB. In your case 1.049GB. There's no way a Node.js app can allocate only 1MB.

but I thought that would appear under either "Node JS" or "V8" categories.

If a object is created in the V8 heap, It might be allocated in those categories yes, but sometimes drivers use pure C for that.

[robross0606]

Right, maybe the . shouldn't be shown in the UI.

If that's the case, then the output would make far more sense. And that is surely a bug.

[mcollina]

This is a bug. Decimal point vs Decimal comma unfortunately exists in this world.

[robross0606]

Understood. Locale will never not be annoying. 😄