Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Excessive GC pauses and ANR due to growing heap size when unread count gets >2600 #3869

Closed
eeeeeta opened this issue Aug 30, 2020 · 1 comment

Comments

@eeeeeta
Copy link

eeeeeta commented Aug 30, 2020

General information

  • Version: 2.8.10+pcr
  • Device: Motorola moto g(7) power
  • Android Version: Android 9 (stock)
  • Server name: theta.eu.org
  • Server software: prosody trunk
  • Installed server modules: CSI, MAM, others
  • Conversations source: PlayStore Beta Channel

Steps to reproduce

  1. Start Conversations fresh
  2. Do things to raise the unread count above ~2600 (receive lots of PMs, be in a lot of active MUCs, have unread history, ...)

Expected result

  • Conversations does not slow down or crash

Actual result

  • Conversations' UI gets slower and slower, until it eventually throws an App Not Responding / quits

From the logcat output, it seems like having a lot of unread messages causes Conversations to use a lot of heap space. Eventually, it hits the Android limit and the OS starts forcing GC pauses on it in order to try and reclaim space, which doesn't work; the app becomes unusable, and eventually dies due to App Not Responding.

After restarting, the app only loads ~50 or so messages for each MUC / conversation, so it doesn't run into the issue.

Suggested action: maybe Conversations should evict unread messages from memory when the OS signals heap space is low? It looks like each Conversation keeps around a list of message objects and only gets rid of them after you've read them; it shouldn't be too bad to just deallocate said message objects when memory pressure is encountered, possibly with some logic for not deallocating objects that have caused a push notification.

Relevant debug output

08-30 19:42:19.130 22008 22042 I s.conversation: Starting a blocking GC Alloc
08-30 19:42:19.130 22008 22008 I s.conversation: WaitForGcToComplete blocked Alloc on HeapTrim for 456.877ms
08-30 19:42:19.130 22008 22008 I s.conversation: Starting a blocking GC Alloc
08-30 19:42:19.137 22008 22042 D conversations: update unread count to 2651
08-30 19:42:19.139 22008 22042 D conversations: eta@theta.eu.org: suppressing notification because turned off
08-30 19:42:19.142 22008 22008 I s.conversation: Waiting for a blocking GC Alloc
08-30 19:42:19.142 22008 22042 I s.conversation: Waiting for a blocking GC Alloc
08-30 19:42:19.608 22008 22018 I s.conversation: Clamp target GC heap from 119MB to 96MB
08-30 19:42:19.608 22008 22018 I s.conversation: Background concurrent copying GC freed 3922(101KB) AllocSpace objects, 0(0B) LOS objects, 0% free, 95MB/96MB, paused 154us total 477.449ms
08-30 19:42:19.608 22008 22008 I s.conversation: WaitForGcToComplete blocked Alloc on HeapTrim for 466.686ms
08-30 19:42:19.608 22008 22008 I s.conversation: Starting a blocking GC Alloc
08-30 19:42:19.608 22008 22042 I s.conversation: WaitForGcToComplete blocked Alloc on HeapTrim for 466.510ms
08-30 19:42:19.608 22008 22042 I s.conversation: Starting a blocking GC Alloc
08-30 19:42:19.610 22008 22008 I s.conversation: Waiting for a blocking GC Alloc
08-30 19:42:19.610 22008 22123 I s.conversation: Waiting for a blocking GC Alloc
08-30 19:42:19.610 22008 22042 I s.conversation: Waiting for a blocking GC Alloc
08-30 19:42:20.067 22008 22018 I s.conversation: Clamp target GC heap from 119MB to 96MB
08-30 19:42:20.067 22008 22018 I s.conversation: Background concurrent copying GC freed 3886(155KB) AllocSpace objects, 0(0B) LOS objects, 0% free, 95MB/96MB, paused 115us total 458.027ms
08-30 19:42:20.067 22008 22008 I s.conversation: WaitForGcToComplete blocked Alloc on HeapTrim for 457.452ms
08-30 19:42:20.067 22008 22008 I s.conversation: Starting a blocking GC Alloc
08-30 19:42:20.067 22008 22123 I s.conversation: WaitForGcToComplete blocked Alloc on HeapTrim for 457.314ms
08-30 19:42:20.067 22008 22123 I s.conversation: Starting a blocking GC Alloc
08-30 19:42:20.067 22008 22042 I s.conversation: WaitForGcToComplete blocked Alloc on HeapTrim for 457.279ms
08-30 19:42:20.067 22008 22042 I s.conversation: Starting a blocking GC Alloc
08-30 19:42:20.071 22008 22008 I s.conversation: Waiting for a blocking GC Alloc
08-30 19:42:20.117 22008 22042 I s.conversation: Waiting for a blocking GC Alloc
08-30 19:42:20.250 22008 22019 I s.conversation: Waiting for a blocking GC Alloc
08-30 19:42:20.532 22008 22018 I s.conversation: Clamp target GC heap from 119MB to 96MB
@eeeeeta
Copy link
Author

eeeeeta commented Oct 4, 2020

Closing in favour of #3896 (large heap support), and the memory leak PRs #3898 & #3897 (which I suspect were the real causes)

@eeeeeta eeeeeta closed this as completed Oct 4, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

1 participant