Leakcanary: Leak analysis failed: OOM

[nowele-rechka-entercom]

Description

Leak analysis failed - error suggested I report this failure to LeakCanary. Including a link to .hprof and the logcat below.

Steps to Reproduce

https://drive.google.com/open?id=1Eez5QchPJ9zjQqK-noO-qzh95tplHz82

```2019-08-12 14:53:02.159 16258-16289/com.radiocom.staging D/LeakCanary: Found 2 retained references, dumping the heap
2019-08-12 14:53:02.176 16258-16289/com.radiocom.staging I/adiocom.stagin: hprof: heap dump "/storage/emulated/0/Download/leakcanary-com.radiocom.staging/2019-08-12_14-53-02_168.hprof" starting...
2019-08-12 14:53:08.147 16258-16289/com.radiocom.staging D/LeakCanary: Checking retained object because found new object retained
2019-08-12 14:53:08.147 16258-16289/com.radiocom.staging D/LeakCanary: No retained objects
2019-08-12 14:53:08.253 16258-23141/com.radiocom.staging D/LeakCanary: Analysis in progress, working on: PARSING_HEAP_DUMP
2019-08-12 14:53:21.928 16258-23141/com.radiocom.staging D/LeakCanary: Analysis in progress, working on: REPORTING_HEAP_ANALYSIS
2019-08-12 14:53:21.931 16258-23141/com.radiocom.staging D/LeakCanary: HeapAnalysisFailure(heapDumpFile=/storage/emulated/0/Download/leakcanary-com.radiocom.staging/2019-08-12_14-53-02_168.hprof, createdAtTimeMillis=1565643201930, analysisDurationMillis=13678, exception=
java.lang.RuntimeException: Not enough memory to allocate buffers for rehashing: 2097152 -> 4194304
at shark.internal.hppc.LongObjectScatterMap.allocateBuffers(LongObjectScatterMap.kt:275)
at shark.internal.hppc.LongObjectScatterMap.allocateThenInsertThenRehash(LongObjectScatterMap.kt:307)
at shark.internal.hppc.LongObjectScatterMap.set(LongObjectScatterMap.kt:99)
at shark.internal.HprofInMemoryIndex$Builder.onHprofRecord(HprofInMemoryIndex.kt:170)
at shark.HprofReader.readHprofRecords(HprofReader.kt:424)
at shark.internal.HprofInMemoryIndex$Companion.createReadingHprof(HprofInMemoryIndex.kt:249)
at shark.internal.HprofInMemoryIndex$Companion.createReadingHprof$default(HprofInMemoryIndex.kt:211)
at shark.HprofHeapGraph$Companion.indexHprof(HprofHeapGraph.kt:187)
at shark.HeapAnalyzer.analyze(HeapAnalyzer.kt:100)
at leakcanary.internal.HeapAnalyzerService.onHandleIntentInForeground(HeapAnalyzerService.kt:61)
at leakcanary.internal.ForegroundService.onHandleIntent(ForegroundService.kt:55)
at android.app.IntentService$ServiceHandler.handleMessage(IntentService.java:76)
at android.os.Handler.dispatchMessage(Handler.java:106)
at android.os.Looper.loop(Looper.java:193)
at android.os.HandlerThread.run(HandlerThread.java:65)
Caused by: java.lang.OutOfMemoryError: Failed to allocate a 33554456 byte allocation with 10849984 free bytes and 10MB until OOM, max allowed footprint 201326592, growth limit 201326592
at shark.internal.hppc.LongObjectScatterMap.allocateBuffers(LongObjectScatterMap.kt:269)
at shark.internal.hppc.LongObjectScatterMap.allocateThenInsertThenRehash(LongObjectScatterMap.kt:307)
at shark.internal.hppc.LongObjectScatterMap.set(LongObjectScatterMap.kt:99)
at shark.internal.HprofInMemoryIndex$Builder.onHprofRecord(HprofInMemoryIndex.kt:170)
at shark.HprofReader.readHprofRecords(HprofReader.kt:424)
at shark.internal.HprofInMemoryIndex$Companion.createReadingHprof(HprofInMemoryIndex.kt:249)
at shark.internal.HprofInMemoryIndex$Companion.createReadingHprof$default(HprofInMemoryIndex.kt:211)
at shark.HprofHeapGraph$Companion.indexHprof(HprofHeapGraph.kt:187)
at shark.HeapAnalyzer.analyze(HeapAnalyzer.kt:100)
at leakcanary.internal.HeapAnalyzerService.onHandleIntentInForeground(HeapAnalyzerService.kt:61)
at leakcanary.internal.ForegroundService.onHandleIntent(ForegroundService.kt:55)
at android.app.IntentService$ServiceHandler.handleMessage(IntentService.java:76)
at android.os.Handler.dispatchMessage(Handler.java:106)
at android.os.Looper.loop(Looper.java:193)
at android.os.HandlerThread.run(HandlerThread.java:65)

)

```

Trying to trigger memory leaks within app with LeakCanary monitoring, LeakCanary had a HeapAnalysisFailure

Version Information

• LeakCanary version: LeakCanary 2.0-beta-2 cc5b133
• Phone: Pixel 2 XL
• Android OS version: 9
• Gradle version: gradle-4.10.1

[pyricau]

Thanks!

[pyricau]

Running the analysis with the profiler:

• Memory starts at 2Mb
• Goes up to 176Mb when building the index
• After building the index it drops back to 140Mb. => 1) what are the extra 36Mb for?
• Then it goes up to 181Mb => 2) Is this for finding leaking instances?
• Then down to 140Mb (so those were temporary 40Mb)
• Then up to 214Mb => 3) Is this for the shortest path? Maybe initial list of GC roots?
• Then down to 153Mb and slowing building back up to 190Mb => 4) What's that about?

Generally, we have two directions to investigate: a) the baseline memory required post hprof indexing, and how to lower that and b) the spikes while analyzing. The baseline is the most impactful right now.

I dumped the heap post indexing:

• The object cache uses 120Mb, the hprof string cache 13Mb
• Object cache (LongObjectScatterMap):
  
  
  
  • => Keys: 33Mb for the array
  
  
  • => values: 87Mb including 16Mb for the array => 71Mb for the rest => matches the remaining.
  
  
  • IndexedInstance (1.4M): 45Mb
  
  
  • PrimitiveArray (514K): 16Mb
  
  
  • ObjectArray (213K): 7Mb
  
  
  • Class (27K classes): 1Mb
  
  

[pyricau]

So our baseline is 133Mb (makes sense that memory goes down to 140Mb, 7Mb of baseline java memory for instrumentation tests is reasonable) and the big question is: how can we reduce that, and what do we have to sacrifice for it?

[pyricau]

There's ~2M instances and 8 bytes per ref so we should use 16Mb per array. Not sure why keys is double the size of values, long et object ref are the same size.

Edit: it's a 32 bit emulator so references use only 4 bits.

Which makes me think, might be worth storing those ids as ints when parsing a heap dump from a 32bit platform. That'd require maintaining parallel data structures (for the maps but also the sealed class that are values in the map), so not great.

[pyricau]

A few more observations:

• we use position to figure out where to read in the heap dump. So position is only useful when performing IO, as opposed to the rest of the index which is useful to skip reads. So we could store the "id=>position" map on disk. Would need to be efficient for the initial write phase and subsequence reads.
• IndexedClass uses 40bits, the other ones use 32bits. That's most likely due to 12bit header + content + 4bit shadow$_monitor + alignment.

The total cost of IndexedInstance (which we have 1.4M instances here) is 8 bit key + 4bit value ref + 32bit = 44bits per instance.

We could inline the index sealed classes and split our object index maps into one map per type of thing to store.

IndexedClass: long => (position, superclassId, instanceSize) => 32 bits per instance instead of 56
IndexedInstance: long => (position, classId) => 24 bits per instance instead of 44bits
Same for IndexedObjectArray
IndexedPrimitiveArray: long => (position, type) => 5 bits per instance instead of 44 bits

This would approximately divide by two the total memory used by the index in this case. The perf hit is that it's slower to find an object by id, but that should still be pretty good. Probably less than 4x (we'll always look up the bigger map first)

If we dump the position to a file index we can reduce this further by another 30%.

[pyricau]

The hprof string cache can be reduced by storing a reversed trie as value instead of strings directly. Class names have a lot of repetitive prefix so this should compress well.

[pyricau]

Thinking about this some more: we probably just need one new map type, long to n-bytes, where n is provided when building the map and each entry has n bytes allocated. The tricky part is writing and reading with minimal allocations, which probably requires exposing access to the underlying array.

[pyricau]

Also, the size of position can be dynamic, based on the size of the hprof. In this example we'd need 4 bytes. We can store it as unsigned.

[pyricau]

Answering some of my prior questions:

• The hprof is a 32bit hprof
• Opening it in Android Studio bumps the memory by 2Gb, so we're still doing 10x better (side note: that memory in AS never gets reclaimed on closing the heap dump...)
• The first spike and drop happens as we're parsing the heap dump and getting to the end of parsing. Looks like these spikes are due to reading large arrays. We don't use the content of these arrays so that's definitely an optimization target.
• We go from 140 pre enqueing of GC roots to 160Mb~190Mb post enqueuing GC roots and then drops down to 130Mb. Sorting GC roots has no impact, so it looks like it's the enqueuing of 12K GC roots that's using all that memory. Which is weird because when we start polling we immediately reclaim that memory. There are a ton of Java frames and for each java frame we read the thread name. I wonder if we might be constantly reading up thread names (no caching for those currently), when maybe the number of threads is actually small. Worth trying to add a temporary cache there.

[pyricau]

Confirmed that adding a map of thread names removes the spike and memory stays flat when enqueuing GC roots. Nice!

[pyricau]

Skipping reading the dynamic content of arrays and classes and instance saves significant allocations and memory while reading (no impact on the baseline though)

Splitting the index in 4 (one per object type) and replacing the 3 largest indexes with nbyte maps goes from 120,816,776 to 82,604,520, a 32% reduction.

Another idea: the load factor is 0.75% which makes sense as the array is growing. However, once done, we might want to rehash to 100% and save the unused space.

[pyricau]

@nowele-rechka-entercom btw, it looks like there are 161 leaks in this heap dump..

[nowele-rechka-entercom]

@nowele-rechka-entercom btw, it looks like there are 161 leaks in this heap dump..

Will we be able to get access to that report or should we wait to rerun with the LeakCanary update?

[pyricau]

You can use Shark CLI directly against the hprof file: https://square.github.io/leakcanary/shark/#shark-cli