search

eclipse-mat / mat

The Eclipse Memory Analyzer is a fast and feature-rich Java heap dump analyzer that helps you find memory leaks and reduce memory consumption.
https://eclipse.dev/mat/
Eclipse Public License 2.0
78 stars 13 forks source link

17X dump parsing performance regression since commit 35b3ff7 #57

Open kgibm opened 4 months ago

kgibm commented 4 months ago

@jasonk000,

Last week, we rolled out a new build of MAT from the latest commit to IBM support servers and we're getting reports of very slow parses up to 9 hours. The issue is reproducible and the majority of time is spent in:

Subtask: Removing unreachable objects
Marking reachable objects

Doing some basic profiling with thread dumps every 30 seconds during this step shows a flame graph with most samples in ObjectMarker.countMarked (the percentage on each frame is of all threads in each thread dump though only the Worker-X threads are relevant; the key point is that across 30 thread dumps, almost all Worker threads were in ObjectMarker.countMarked):

org/eclipse/mat/parser/internal/snapshot/ObjectMarker.countMarked (29 samples, 1.83%)
org/eclipse/mat/parser/internal/snapshot/ObjectMarker.markSingleThreaded (30 samples, 1.89%)
org/eclipse/mat/parser/internal/GarbageCleaner.markUnreachableAsGCRoots (30 samples, 1.89%)
org/eclipse/mat/parser/internal/GarbageCleaner.clean (30 samples, 1.89%)
org/eclipse/mat/parser/internal/SnapshotFactoryImpl.parse (30 samples, 1.89%)
org/eclipse/mat/parser/internal/SnapshotFactoryImpl.openSnapshot (30 samples, 1.89%)
org/eclipse/mat/snapshot/SnapshotFactory.openSnapshot (30 samples, 1.89%)
org/eclipse/mat/ui/snapshot/ParseHeapDumpJob.run (30 samples, 1.89%)
org/eclipse/core/internal/jobs/Worker.run (30 samples, 1.89%)
Worker-X (30 samples, 1.89%)

Taking a dump of MAT itself during this step shows that the boolean[] bits array has about 77 million entries. I guess it's just incredibly slow to iterate over so many elements in our support server environment. The support servers are virtualized Windows servers. The boxes don't appear to be particularly loaded. 2 CPU sockets and 8 virtual processors, about 25% utilized. 256GB RAM.

I then uploaded a test build of MAT from commit 35b3ff7 and re-parsed from scratch, and the parse completed in about 30 minutes.

I'll be reverting our MAT builds to that commit but let me know if you want me to run any debug builds as I can upload custom builds and I can re-try on this dump.

jasonk000 commented 4 months ago

(1) I'd be interested to see if you can run a build with just this reverted?

https://github.com/eclipse-mat/mat/commit/7c2cb094fc6119999e14e1d8a04fe15c37c31f34

(2) I wonder if you can run a job with async-profiler and capture a full wall-time and CPU flamegraph of the run? 9 hours is an extraordinarily long time. 77 million boolean[] is 77MB, scanning 77MB to count 1 vs 0 should not be a 9 hour job! A flamegraph and/or output with line numbers would be perfect.

I can see this loop, maybe we're seeing some particular behavior triggered here. https://github.com/eclipse-mat/mat/blob/master/plugins/org.eclipse.mat.parser/src/org/eclipse/mat/parser/internal/GarbageCleaner.java#L917-L938

(3) Is there any chance you can share a sample hprof?

kgibm commented 4 months ago

Thanks. Sure, I'll get as much of that for you as I can, probably tomorrow. I only took thread dumps for a subset of the whole parse, so maybe ObjectMarker.countMarked is only part of the regression. Unfortunately, I can't download anything from these systems, so I can't share any dumps from it, but I can run debug logging and extract out snippets if we need to go down that path. I'll look into async-profiler...

jasonk000 commented 4 months ago

Also, timestamps of the log parser log would be good, if you can capture them

kgibm commented 4 months ago

Just a note that this might take me some time because currently our internal build of MAT has some patches which requires running with IBM Semeru Runtimes and async-profiler doesn't support the OpenJ9 JVM. For some time, I've wanted to make our internal build not require OpenJ9 but that will take a bit of work...

However, I will also try running without commit 7c2cb09 and get back to you on that...

kgibm commented 4 months ago

I checked out e06518880d7b3d192bd3d6c1d53fb4734d80bed2 and then applied 6d27b35d936a62c546a96ea465e61930f8fcaf36 and 4842f05f2afe384905d289cf1d724d2ed773c655 and re-parsed the dump from scratch and it completed quickly, so it does seem that 7c2cb094fc6119999e14e1d8a04fe15c37c31f34 is the proximate cause of the slowdown.

jasonk000 commented 4 months ago

Got it. I think a profile would help. I think a profile would be very helpful. Sending across a hprof (redacted) might be helpful too, MAT has the export redacted=FULL option which might be a viable reproduction?

kgibm commented 4 months ago

I've been very busy with other work but finally getting back around to this. It turns out IBM Semeru Runtimes does work with async-profiler (despite what it says in the README); however, async-profiler is not available on Windows which is where this issue is occurring. I've added in the IBM Health Center sampling profiler (similar to JFR) and I'm parsing the dump now.

Sending across a hprof (redacted) might be helpful too, MAT has the export redacted=FULL option which might be a viable reproduction?

Unfortunately all downloading is disabled in these environments. We can only copy/paste small text output or images. I should be able to get a flamegraph from the HealthCenter data. By default, it takes thread dumps every 30 seconds.

kgibm commented 4 months ago

I reproduced the 15 hour parse with the profiler. For the CPU samples, ~93% are in ObjectMarker.countMarked:

Samples Self (%)    Method
2087851 93.26       org.eclipse.mat.parser.internal.snapshot.ObjectMarker.countMarked()

Invocation paths:

org.eclipse.mat.parser.internal.snapshot.ObjectMarker.countMarked
  |-org.eclipse.mat.parser.internal.snapshot.ObjectMarker.markSingleThreaded (100%)
  |  |-org.eclipse.mat.parser.internal.GarbageCleaner.markUnreachableAsGCRoots (100%)
  |  |  |-org.eclipse.mat.parser.internal.GarbageCleaner.clean (100%)
  |  |  |  |-org.eclipse.mat.parser.internal.SnapshotFactoryImpl.parse (100%)
  |  |  |  |  |-org.eclipse.mat.parser.internal.SnapshotFactoryImpl.openSnapshot (100%)
  |  |  |  |  |  |-org.eclipse.mat.snapshot.SnapshotFactory.openSnapshot (100%)
  |  |  |  |  |  |  |-org.eclipse.mat.ui.snapshot.ParseHeapDumpJob.run (100%)
  |  |  |  |  |  |  |  |-org.eclipse.core.internal.jobs.Worker.run (100%)

For the 30 second thread dumps, here's the flame graph which shows a similar thing:

flamegraph

kgibm commented 4 months ago

Attaching an interactive SVG to the GitHub issue seems to strip/restrict the SVG capabilities somehow, but it looks to work when uploaded to a repository: https://raw.githubusercontent.com/kgibm/ExampleFlameGraphs/main/flamegraph.svg

kgibm commented 4 months ago

Hmm, no, the raw.githubusercontent.com is more interactive but not fully interactive. You must download the file locally and then open it in your browser.

jasonk000 commented 2 months ago

I'm interested to know if this is resolved in #63, though I suspect not.

kgibm commented 1 month ago

@jasonk000 Thanks. I've been busy and I'm also in the process of some required upgrades to our internal tooling, but I hope to test out #63 soon.