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

Instability and OOMs with large playback queues #957

Open
4 tasks done
foss- opened this issue Jan 11, 2025 · 60 comments
Open
4 tasks done

Instability and OOMs with large playback queues #957

foss- opened this issue Jan 11, 2025 · 60 comments
Assignees
Labels
bug Something isn't working playback Related to music playback

Comments

@foss-
Copy link

foss- commented Jan 11, 2025

Describe the Bug/Crash

Auxio 4.0.0-dev3
Is this #825 all over?

Reproducible by tapping shuffle button on large library.

Describe the intended behavior

Should not crash.

What android version do you use?

Android 13

What device model do you use?

Xiaomi lisa
ArrowOS 13.1

Provide a sample file

N/A

Bug report

android.app.ForegroundServiceStartNotAllowedException: Service.startForeground() not allowed due to mAllowStartForeground false: service org.oxycblt.auxio/.AuxioService
	at android.app.ForegroundServiceStartNotAllowedException$1.createFromParcel(ForegroundServiceStartNotAllowedException.java:54)
	at android.app.ForegroundServiceStartNotAllowedException$1.createFromParcel(ForegroundServiceStartNotAllowedException.java:50)
	at android.os.Parcel.readParcelableInternal(Parcel.java:4816)
	at android.os.Parcel.readParcelable(Parcel.java:4778)
	at android.os.Parcel.createExceptionOrNull(Parcel.java:3006)
	at android.os.Parcel.createException(Parcel.java:2995)
	at android.os.Parcel.readException(Parcel.java:2978)
	at android.os.Parcel.readException(Parcel.java:2920)
	at android.app.IActivityManager$Stub$Proxy.setServiceForeground(IActivityManager.java:6114)
	at android.app.Service.startForeground(Service.java:743)
	at org.oxycblt.auxio.AuxioService$$ExternalSyntheticLambda0.invoke(SourceFile:388)
	at org.oxycblt.auxio.AuxioService.updateForeground(SourceFile:202)
	at org.oxycblt.auxio.music.service.IndexingHolder.onIndexingStateChanged(SourceFile:5)
	at org.oxycblt.auxio.music.MusicRepositoryImpl.access$emitIndexingProgress(SourceFile:97)
	at org.oxycblt.auxio.music.MusicRepositoryImpl$emitIndexingProgress$1.invokeSuspend(Unknown Source:12)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(SourceFile:9)
	at kotlinx.coroutines.DispatchedTask.run(SourceFile:109)
	at androidx.core.app.ActivityRecreator$1.run(SourceFile:36)
	at kotlinx.coroutines.scheduling.TaskImpl.run(SourceFile:3)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(SourceFile:93)
	Suppressed: android.app.ForegroundServiceStartNotAllowedException: Service.startForeground() not allowed due to mAllowStartForeground false: service org.oxycblt.auxio/.AuxioService
		... 20 more

Duplicates

@foss- foss- added the bug Something isn't working label Jan 11, 2025
@OxygenCobalt
Copy link
Owner

I'm literally doing nothing wrong now. I'm just going to artifically delay the service launch by a couple hundred milliseconds to work around whatever is race condition is causing this.

@OxygenCobalt
Copy link
Owner

OxygenCobalt commented Jan 14, 2025

Try 4.0.0-dev4 @foss-?

@foss-
Copy link
Author

foss- commented Jan 14, 2025

App still crashes but gives no crash log when re-opened. This happens sometimes on first song after tapping shuffle, sometimes first song plays time and a second tap on shuffle is needed. App becomes unresponsive for a brief moment then closes and users is on home screen.

@OxygenCobalt
Copy link
Owner

Wait, this is two distinct issues.

  1. A crash occurring on playback
  2. The annoying fussy foreground problem that I keep having to accomodate and is likely unfixable since android is really poorly designed

I need a crash report for #1. @foss- can you reproduce the issue and then take a bug report?

@OxygenCobalt OxygenCobalt changed the title crash when using shuffle and after birefly playing music Crash on playing music Jan 15, 2025
@OxygenCobalt OxygenCobalt added the playback Related to music playback label Jan 15, 2025
@foss-
Copy link
Author

foss- commented Jan 16, 2025

The bug report contains too much info. Is this logcat info sufficient? It was created right after auxio crashes after tapping shuffle.

In this case no audio ever played.

1 month: https://bin.disroot.org/?bd13202f37cb43fa#5osTFqr5XvQRots15gnhMPwQFsxDa6DkFQbZgQ6mbSS3

@OxygenCobalt
Copy link
Owner

Out of memory crash, need to figure out what's going on @foss-

@OxygenCobalt
Copy link
Owner

Okay, turns out Musikr's native code is full of memory leaks. It probably is an OOM on your library. Will fix.

@OxygenCobalt
Copy link
Owner

Try this @foss-?

Auxio_Canary.zip

@foss-
Copy link
Author

foss- commented Jan 19, 2025

Tapping shuffle results in message Auxio Debug isn't responding after a few seconds.

android.app.ForegroundServiceStartNotAllowedException: Service.startForeground() not allowed due to mAllowStartForeground false: service org.oxycblt.auxio.debug/org.oxycblt.auxio.AuxioService
	at android.app.ForegroundServiceStartNotAllowedException$1.createFromParcel(ForegroundServiceStartNotAllowedException.java:54)
	at android.app.ForegroundServiceStartNotAllowedException$1.createFromParcel(ForegroundServiceStartNotAllowedException.java:50)
	at android.os.Parcel.readParcelableInternal(Parcel.java:4816)
	at android.os.Parcel.readParcelable(Parcel.java:4778)
	at android.os.Parcel.createExceptionOrNull(Parcel.java:3006)
	at android.os.Parcel.createException(Parcel.java:2995)
	at android.os.Parcel.readException(Parcel.java:2978)
	at android.os.Parcel.readException(Parcel.java:2920)
	at android.app.IActivityManager$Stub$Proxy.setServiceForeground(IActivityManager.java:6114)
	at android.app.Service.startForeground(Service.java:743)
	at org.oxycblt.auxio.AuxioService.updateForeground$lambda$2(AuxioService.kt:159)
	at org.oxycblt.auxio.AuxioService.$r8$lambda$8zoHeh9zw9kcW0pXXX3N05EG1ng(Unknown Source:0)
	at org.oxycblt.auxio.AuxioService$$ExternalSyntheticLambda0.invoke(D8$$SyntheticClass:0)
	at org.oxycblt.auxio.music.service.IndexingHolder.createNotification(IndexingHolder.kt:123)
	at org.oxycblt.auxio.music.service.MusicServiceFragment.createNotification(MusicServiceFragment.kt:100)
	at org.oxycblt.auxio.AuxioService.updateForeground(AuxioService.kt:157)
	at org.oxycblt.auxio.music.service.IndexingHolder.onIndexingStateChanged(IndexingHolder.kt:144)
	at org.oxycblt.auxio.music.MusicRepositoryImpl.emitIndexingProgress(MusicRepository.kt:415)
	at org.oxycblt.auxio.music.MusicRepositoryImpl.access$emitIndexingProgress(MusicRepository.kt:235)
	at org.oxycblt.auxio.music.MusicRepositoryImpl$emitIndexingProgress$1.invokeSuspend(Unknown Source:15)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:101)
	at kotlinx.coroutines.internal.LimitedDispatcher$Worker.run(LimitedDispatcher.kt:113)
	at kotlinx.coroutines.scheduling.TaskImpl.run(Tasks.kt:89)
	at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:589)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:823)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:720)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:707)
	Suppressed: android.app.ForegroundServiceStartNotAllowedException: Service.startForeground() not allowed due to mAllowStartForeground false: service org.oxycblt.auxio.debug/org.oxycblt.auxio.AuxioService
		... 28 more

When tapping a song to play app crashes and closes.

@OxygenCobalt
Copy link
Owner

That error you provided is a music loading error, you need to take another logcat on the song playback crash @foss-.

@foss-
Copy link
Author

foss- commented Jan 21, 2025

Does this logcat inlcude the information you are looking for?

1 month: https://bin.disroot.org/?e7a19007948e4331#2fKogXwUu3UyLdCAguwdjvkYju1Hn11X6tNrHSwVBcUG

@OxygenCobalt
Copy link
Owner

Does this logcat inlcude the information you are looking for?

1 month: https://bin.disroot.org/?e7a19007948e4331#2fKogXwUu3UyLdCAguwdjvkYju1Hn11X6tNrHSwVBcUG

Yeah, apparently at some point I turn an internal object into a string, which results in a... 16mb allocation that instantly knocks out the VM.

Might need to audit some accidental printf debugging I left in the app, give me a moment @foss-

Thanks for stresstesting too, I dont have a big library so you and e-zk's libs are basically my only way of knowing if I broke those or not

@OxygenCobalt
Copy link
Owner

Here's a new APK @foss-. This removes the debug log that allocated too much memory and crashed the app, but I'm partially concerned that your phone also has a strangely low memory limit and could be GC'ing constantly during playback (causing the unresponsiveness). In this case, I need to deep dive on what's changing memory-wise between versions.

Auxio_Canary.zip

@foss-
Copy link
Author

foss- commented Jan 22, 2025

sent logcat via email

@OxygenCobalt
Copy link
Owner

Yeah @foss-, your device has some very weird memory use patterns. Constant garbage collection, near total memory use, and eventually ExoPlayer just causes an OOM. Very strange. It also doesn't help that Auxio only has 256mb available to it, which is basically peanuts.

I'm going to measure memory use on my own device and compare.

@OxygenCobalt
Copy link
Owner

OxygenCobalt commented Jan 22, 2025

Hi again @foss-, I've analyzed the memory use between v3.6.3 and v4.0.0 and there does seem to be something like +100mb of memory use for some unknown reason. I really don't know why, will try to investigate.

@OxygenCobalt
Copy link
Owner

OxygenCobalt commented Jan 22, 2025

Quick question: Does changing Settings -> Content -> Album covers to "Save space" do anything @foss-?

Something that could be happening is that the covers I'm loading are just too big.

@foss-
Copy link
Author

foss- commented Jan 23, 2025

That could well be. Changed Settings > Content > Album covers to Save space.

After the library is loaded Auxio crashes after tapping the first song. Double checked and the cover of that track is large: 1,2 MB. Created a 106 KB variant of the cover and replaced the file. Reloaded library in Auxio debug version and instead of crashing the file now played.

Currently batch resizing all cover images to a reduced size. Will report back.

@OxygenCobalt
Copy link
Owner

OxygenCobalt commented Jan 24, 2025

That would make sense @foss-, ExoPlayer also tries to load the cover (I can't change this annoyingly), so it's probably heaping on more memory on top of the existing poor memory use. I need to debug some other deeper memory problem, there is at least double the memory use between Auxio v3.6.3 and v4.0.0 and I can't tell why.

@foss-
Copy link
Author

foss- commented Jan 25, 2025

This was a major change to my library and the dust has again settled. No large cover image files.

The shuffle crash is persisting in 4.0.0-dev4:

android.app.ForegroundServiceStartNotAllowedException: Service.startForeground() not allowed due to mAllowStartForeground false: service org.oxycblt.auxio/.AuxioService
	at android.app.ForegroundServiceStartNotAllowedException$1.createFromParcel(ForegroundServiceStartNotAllowedException.java:54)
	at android.app.ForegroundServiceStartNotAllowedException$1.createFromParcel(ForegroundServiceStartNotAllowedException.java:50)
	at android.os.Parcel.readParcelableInternal(Parcel.java:4816)
	at android.os.Parcel.readParcelable(Parcel.java:4778)
	at android.os.Parcel.createExceptionOrNull(Parcel.java:3006)
	at android.os.Parcel.createException(Parcel.java:2995)
	at android.os.Parcel.readException(Parcel.java:2978)
	at android.os.Parcel.readException(Parcel.java:2920)
	at android.app.IActivityManager$Stub$Proxy.setServiceForeground(IActivityManager.java:6114)
	at android.app.Service.startForeground(Service.java:743)
	at org.oxycblt.auxio.AuxioService$$ExternalSyntheticLambda0.invoke(SourceFile:388)
	at org.oxycblt.auxio.AuxioService.updateForeground(SourceFile:202)
	at org.oxycblt.auxio.music.service.IndexingHolder.onIndexingStateChanged(SourceFile:5)
	at org.oxycblt.auxio.music.MusicRepositoryImpl.access$emitIndexingProgress(SourceFile:97)
	at org.oxycblt.auxio.music.MusicRepositoryImpl$emitIndexingProgress$1.invokeSuspend(Unknown Source:12)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(SourceFile:9)
	at kotlinx.coroutines.DispatchedTask.run(SourceFile:109)
	at androidx.core.app.ActivityRecreator$1.run(SourceFile:36)
	at kotlinx.coroutines.scheduling.TaskImpl.run(SourceFile:3)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(SourceFile:93)
	Suppressed: android.app.ForegroundServiceStartNotAllowedException: Service.startForeground() not allowed due to mAllowStartForeground false: service org.oxycblt.auxio/.AuxioService
		... 20 more

Oh this is also happening when just tapping another song while one song is playing, no shuffle involved.

Re-testing with debug build: tapping a track and app crashes.

3.6.3 is the last working release as far as my library is concerned.

@OxygenCobalt
Copy link
Owner

Okay @foss-, I just have to bisect the memory use problem on my end and figure out what caused the surge. I don't know when I will have the time, hold tight.

@OxygenCobalt
Copy link
Owner

Okay, figured out the issue. The way I abused kotlin flows to distribute work several times over wound up making circular references that would leak huge chunks of memory. I have to completely rebuild the system.

@OxygenCobalt
Copy link
Owner

OxygenCobalt commented Jan 30, 2025

Okay, so not even that was the issue. It's a memory leak stemming from a bugged memory allocation in the Java standard library. After switching to manually allocating the memory in native code, the memory leak seems to have disappeared @foss-. Can you try this APK?

Auxio_Canary.zip

@foss-
Copy link
Author

foss- commented Jan 30, 2025

crashes on first tap on shuffle and crashes on first tap on a track - sorry I don't have better news. Not getting any debug output, so here's a logcat (1 month):
https://bin.disroot.org/?bc10bee51c809320#5mZuhN5STD6Dt9mN6mHC1STGjLFWkqQjpR4r3abZvHPy

20:06:00 song tapped
20:06:06 app closes

@OxygenCobalt
Copy link
Owner

Okay, this is inexplicable at this point @foss-. I shaved off something like 200mb of leaked memory and it's still not enough. I'll see if perhaps a release build "works", if not I think you might have to run a heap dump and send it to me so I can identify what's still leaking.

@OxygenCobalt
Copy link
Owner

Hi @foss-, can you see if dev5 is an improvement at all? I can't tell if it's just a debug artifact or not.

@foss-
Copy link
Author

foss- commented Jan 31, 2025

Thanks, PID changes after auxio crashes so updated steps worked. Now I need to figure out:

  • how to delete the heapdump folder on android device
  • where to find your public OpenPGP key

@OxygenCobalt
Copy link
Owner

Thanks, PID changes after auxio crashes so updated steps worked. Now I need to figure out:

  • how to delete the heapdump folder on android device
  • where to find your public OpenPGP key
  • The heapdump is saved in the tmp folder, so itll get deleted on the next reboot I believe.
  • My pubkey is on my profile README in the dropdown at the bottom.

@foss-

@foss-
Copy link
Author

foss- commented Jan 31, 2025

Perfect - you got mail.

@OxygenCobalt
Copy link
Owner

OxygenCobalt commented Jan 31, 2025

Are you sure @foss-? I haven't gotten an e-mail yet. Did you send it to my profile email?

@OxygenCobalt
Copy link
Owner

Nevermind @foss-, just received it.

@OxygenCobalt
Copy link
Owner

Okay @foss-, looking at your heapdump, it seems like the problem is that ExoPlayer is completely overloaded with a huge queue. It seems like the new cover URIs finally pushed it over the edge. Is there any state restoring going on when you started the app?

@foss-
Copy link
Author

foss- commented Jan 31, 2025

When I close the app and then reopen it does the loading process which takes 1-2 minutes. Then I see the library. Is that what you were asking?

@OxygenCobalt OxygenCobalt changed the title Crash on playing music Instability and OOMs with large playback queues Jan 31, 2025
@OxygenCobalt
Copy link
Owner

No, is there any playback going on @foss-? i.e the playback bar shows up. Because in the heapdump, I see a pretty big queue appear and use tens of megabytes of memory.

@foss-
Copy link
Author

foss- commented Jan 31, 2025

Oh I see - yes, a track is loaded at the bottom and tapping the bottom controls and sliding up the queue I see a very large queue. is there a way to reset that?

@OxygenCobalt
Copy link
Owner

Not necessarily @foss-, there's #478, but I haven't implemented that since working with the bottom sheet UI is a nightmare.

There's a few courses of action I can take immediately:

  1. Adding a (configurable) hard-cap on queue size to stop catastrophic memory use. I'd guess like 8192 songs or something arbitrary like that.
  2. Adding a temporary settings action to clear out the current playback state entirely, but you can still wind up in the mysterious OOM case.
  3. Paging the size of the MediaSession queue to some arbitrary amount, but ExoPlayer is such a memory hog at large queue sizes that this doesn't fully solve the problem.

Long-term, I can try to mitigate a lot of the memory use with better management of string IDs, and waiting on Media3's planned paging player. I think Number 1 is probably the best course of action.

@foss-
Copy link
Author

foss- commented Jan 31, 2025

Deleted app and re-installed to get rid of the queue. But that was not possible, it's still there.

Good progress and options to move forward are on the table 👍

@OxygenCobalt
Copy link
Owner

OxygenCobalt commented Jan 31, 2025

But that was not possible, it's still there.

...?!?!?!? The playback state should in no way continue to persist like that. I am very confused about what's going on here @foss-

Does clearing app storage work?

@foss-
Copy link
Author

foss- commented Jan 31, 2025

Uhm this is interesting. The queue is peristing. And the queue apparently is all tracks sorted alphabetically starting with 01. I have no idea why all tracks keep being added to the queue, but that is what seems to be happening. Sadly did not notice this sooner although it's obvious 🙄

@OxygenCobalt
Copy link
Owner

Uhm this is interesting. The queue is peristing. And the queue apparently is all tracks sorted alphabetically starting with 01. I have no idea why all tracks keep being added to the queue, but that is what seems to be happening. Sadly did not notice this sooner although it's obvious 🙄

Lets say you edit the queue and then re-install. What happens? If it reverts then theres no persistence, the app is just jumping to play the entire library for no discernable reason. @foss-

@foss-
Copy link
Author

foss- commented Jan 31, 2025

Tried dragging a song up to change order - but app crashes

Tried removing single tracks and I am certain those re-appeared, this is if the app didn't crash on attempt to delete a track

So yes, it seems the entire library keeps re-appearing as queue

@OxygenCobalt
Copy link
Owner

Okay, here's a debug build that will crash the moment a playback command is sent. Can you log the crash on this build so I can ID what codepath is even causing this? (Seriously, so many things can trigger a playback) @foss-?

Auxio_CrashTest.zip

@foss-
Copy link
Author

foss- commented Feb 1, 2025

You got mail. Let me know if the debug data was helpful.

OT question as I just started using Android Auto: is it correct that for Auxio to show in the Android Auto launcher it needs to be installed from PlayStore and that is pending as per #572 so while Android Auto is supported in theory it can not yet be used in practice?

@OxygenCobalt
Copy link
Owner

I don't need the heapdump but the logcat output containing the crash @foss-, can you send that?

OT question as I just started using Android Auto: is it correct that for Auxio to show in the Android Auto launcher it needs to be installed from PlayStore and that is pending as per #572 so while Android Auto is supported in theory it can not yet be used in practice?

You have to enable android auto's developer settings and then turn on "enable unknown apps".

@foss-
Copy link
Author

foss- commented Feb 1, 2025

Logcat for latest debug build (1 month):
https://bin.disroot.org/?adc17d5498b8824b#31crqj2yBUU9jpT33zJycrSdkS8CsgyCWt1yYCss681D

You have to enable android auto's developer settings and then turn on "enable unknown apps".

Fantastic - thank you.

@OxygenCobalt
Copy link
Owner

OxygenCobalt commented Feb 1, 2025

Did you start playback at all @foss-? I want to see what happens on a fresh install (uninstall and reinstall), without any playback occurring. Currently the codepath seems to be triggered by a UI interaction, which doesn't seem right.

@foss-
Copy link
Author

foss- commented Feb 1, 2025

Maybe I misunderstand what you mean? I tap a song but no playback ever happens. So what do I do? Uninstall, reinstall latest debug and then what action do you want to trigger the crash?

@OxygenCobalt
Copy link
Owner

Uninstall, reinstall, and select a folder, then wait @foss-. Do nothing. Since for some reason song playback is appearing out of nowhere, I need to see why that is happening.

@foss-
Copy link
Author

foss- commented Feb 2, 2025

You got mail: Logcat after launching auxio after re-install, selecting music folder, letting scan finish and then no further interaction.

@OxygenCobalt
Copy link
Owner

Okay, so I see no logs relating to playback @foss-. Did the playback bar show up when you were testing?

The only thing I think that could trigger the bug now is a mysterious state restore error.

@foss-
Copy link
Author

foss- commented Feb 3, 2025

Odd, re-opened 4.0.0-dev5, playback bar was there. Played a few tracks and when now looking at the queue it shows all tracks from a single album of which I played a track from the songs tab. No lag, no playback issues, skipping works.

Re-opened your latest debug build. This opened without playback bar which imo also differs from what I saw in the past.

So from what I see, the issue with the queue leading to unstable behavior is gone. Question is, should I press shuffle to see if I get back into unstable state?

@OxygenCobalt
Copy link
Owner

Odd, re-opened 4.0.0-dev5, playback bar was there. Played a few tracks and when now looking at the queue it shows all tracks from a single album of which I played a track from the songs tab. No lag, no playback issues, skipping works.

Makes sense, since you switched from a 36k song queue to a dozen-song queue. Way easier for Auxio to chew on.

Re-opened your latest debug build. This opened without playback bar which imo also differs from what I saw in the past.

?!?!?!?!?!?!?!. Looks like this is either a misunderstanding in communication or a heisenbug. Guess there's nothing that can be done.

So from what I see, the issue with the queue leading to unstable behavior is gone. Question is, should I press shuffle to see if I get back into unstable state?

If you do this, it'll just trigger the instability caused by kinda unavoidable issues. Don't really need that.

Guess this issue is not a problem then for release. Leaving it open as a bigger thread for the issues behind huge queues.

@foss-
Copy link
Author

foss- commented Feb 3, 2025

While playback did work, auxio keept howing the message "Auxio isn't responding" after attempting to alphabet scroll songs tab.

When selecing any song, that message shows again. Song still plays.

@OxygenCobalt
Copy link
Owner

While playback did work, auxio keept howing the message "Auxio isn't responding" after attempting to alphabet scroll songs tab.

When selecing any song, that message shows again. Song still plays.

Makes sense, I don't think the new fast scroller is very efficient with huge lists (unsure why), and ExoPlayer is going to chug BADLY with 36k songs @foss-. Going to place this in the realm of huge library edge cases and continue w/4.0.0.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working playback Related to music playback
Projects
None yet
Development

No branches or pull requests

2 participants