Playback crashes when memory usage is high

robinbanbury commented 5 years ago

Expected Behaviour

Audio playback does not crash when device memory usage is high

Actual Behaviour

Playlist is wiped and playback stops when device memory usage is high.

2019-03-16 18:22:12.084697+0000 GigLicker[3207:706217] RmxAudioPlayer.onStatus: Playback Position Changed(40) [36118384-9379924-76370446-326068075]:  [object Object] // last 'normal' message before error
2019-03-16 18:22:12.511812+0000 GigLicker[3207:706217] Queue changed current item to: (null)
2019-03-16 18:22:12.511853+0000 GigLicker[3207:706217] New item ID: (null)
2019-03-16 18:22:12.511870+0000 GigLicker[3207:706217] Queue is at end: YES
2019-03-16 18:22:12.556931+0000 GigLicker[3207:706217] RmxAudioPlayer, removeAllTracks, ==> RMXSTATUS_PLAYLIST_CLEARED
2019-03-16 18:22:12.557050+0000 GigLicker[3207:706217] music-controls-clear
2019-03-16 18:22:12.557065+0000 GigLicker[3207:706217] RmxAudioPlayer, queuePlayerCleared, MEMORY_WARNING
2019-03-16 18:22:12.882796+0000 GigLicker[3207:706217] RmxAudioPlayer.onStatus: Track Removed(115) [34848654-176398-223859742-323062077]:  [object Object]
2019-03-16 18:22:12.932868+0000 GigLicker[3207:706217] Got RmxAudioPlayer onStatus:
2019-03-16 18:22:12.935161+0000 GigLicker[3207:706217] {"type":115,"trackId":"34848654-176398-223859742-323062077","value":{"artist":"The Wurzels","trackId":"34848654-176398-223859742-323062077","isStream":true,"assetUrl":"https://api.soundcloud.com/tracks/323062077/stream","title":"Old Rosie","album":"SoundCloud","albumArt":"https://i1.sndcdn.com/artworks-IBQkaW5WX4bk-0-large.jpg"}}

// ... lots of RMXSTATUS_ITEM_REMOVED statuses while playlist gets wiped ..

2019-03-16 18:22:13.139513+0000 GigLicker[3207:706217] RmxAudioPlayer.onStatus: Track Changed(100) [NONE]:  [object Object]
2019-03-16 18:22:13.139573+0000 GigLicker[3207:706217] Got RmxAudioPlayer onStatus:
2019-03-16 18:22:13.139636+0000 GigLicker[3207:706217] {"type":100,"trackId":"NONE","value":{"currentIndex":9223372036854776000,"currentItem":{},"hasNext":0,"hasPrevious":1,"isAtEnd":true,"isAtBeginning":false}}
2019-03-16 18:22:13.140477+0000 GigLicker[3207:706217] RmxAudioPlayer.onStatus: Stopped(60) [INVALID]:
2019-03-16 18:22:13.140540+0000 GigLicker[3207:706217] Got RmxAudioPlayer onStatus:
2019-03-16 18:22:13.140601+0000 GigLicker[3207:706217] {"type":60,"trackId":"INVALID"}
2019-03-16 18:22:13.140993+0000 GigLicker[3207:706217] RmxAudioPlayer.onStatus: Playlist Cleared(120) [INVALID]:
2019-03-16 18:22:13.141057+0000 GigLicker[3207:706217] Got RmxAudioPlayer onStatus:
2019-03-16 18:22:13.141177+0000 GigLicker[3207:706217] {"type":120,"trackId":"INVALID"}
2019-03-16 18:22:13.141457+0000 GigLicker[3207:706217] RmxAudioPlayer.onStatus: Playlist Cleared(120) [INVALID]:  [object Object]
2019-03-16 18:22:13.141535+0000 GigLicker[3207:706217] Got RmxAudioPlayer onStatus:
2019-03-16 18:22:13.141783+0000 GigLicker[3207:706217] {"type":120,"trackId":"INVALID","value":{"reason":"memory-warning"}}
2019-03-16 18:22:13.156704+0000 GigLicker[3207:706217] RmxAudioPlayer.onStatus: Playback Position Changed(40) [undefined]:
2019-03-16 18:22:13.170345+0000 GigLicker[3207:706217] Error in Success callbackId: RmxAudioPlayer343424179 : TypeError: undefined is not an object (evaluating 'status['value']['currentPosition']')
2019-03-16 18:22:38.104186+0000 GigLicker[3207:706217] Audio session interruption received: NSConcreteNotification 0x281b634b0 {name = AVAudioSessionInterruptionNotification; object = <AVAudioSession: 0x2817394f0>; userInfo = {
    AVAudioSessionInterruptionTypeKey = 1;
}}
2019-03-16 18:22:38.106038+0000 GigLicker[3207:706217] AVAudioSessionInterruptionTypeBegan. Was suspended: 0
2019-03-16 18:22:38.258119+0000 GigLicker[3207:706217] {"line":1,"column":157,"sourceURL":"http://localhost:8080/var/containers/Bundle/Application/6DFCE11D-8A92-47EE-B282-9EB5D1CC6D42/GigLicker.app/www/index.html#/home"}
2019-03-16 18:25:13.533344+0000 GigLicker[3207:706217] [ProcessSuspension] Background task expired while holding WebKit ProcessAssertion (isMainThread? 1).

I found that the message RmxAudioPlayer, queuePlayerCleared, MEMORY_WARNING is logged in the onMemoryWarning method, which presumably is called after the OS issues a warning about high memory usage.

Does anyone know if the OS memory warning is being sent because of low available memory on the device, or because this plugin/app is using up too much memory? I don't see any spikes in the plugin/app memory usage when the error occurs, and I only seem to get the error when my app is in the background. So my guess would be the former - that it's something the OS is doing when memory is low on the device, to free up memory used by background apps. That seems to align with the contents of this article.

If that's the case, maybe it's better not to wipe the playlist when the memory warning is received? That might be controversial, but I rarely see other music-playing apps such as Spotify or SoundCloud stop playing music when my phone is busy, so I have my doubts that those apps do anything drastic with their active playlist when they get this kind of warning.

If anyone has any advice or suggestions to the contrary on this (or to explain to me what obvious thing I'm doing wrong with my memory management!), I'm open to hearing that! :-)

Reproduce Scenario

iOS with Ionic, streaming tracks from SoundCloud using stream URLs

Steps to Reproduce

Load several tracks onto the playlist, and start playing one of the songs
Put the app into the background
Increase the memory usage on the device, e.g. by opening and using many other apps, tabs in browsers etc.
In my case, this started happening when device memory usage was over 75% (under 500MB remaining), but very inconsistently even then
When the message RmxAudioPlayer, queuePlayerCleared, MEMORY_WARNING appears in the logs, the bug has been reproduced

Platform and Version

iOS 12.1.4

Cordova CLI version and cordova platform version

Cordova CLI version 7.1.0 Cordova iOS version 4.5.4

Plugin version

0.7.1

codinronan commented 5 years ago

Hey @robincsmith you are probably right, as you note I was just following the supposed "best practice". This particular message is sent to the app when the device is low on memory, which may or may not be due to this specific app - the OS broadcasts to ALL apps to attempt to reclaim memory.

I spent some time profiling this a few days ago and this plugin really doesn't use much memory, no more than expected anyway. What do you think of just ignoring the warning?

robinbanbury commented 5 years ago

Yes, I believe you are right about the cause of the 'low memory' message and about the memory footprint of this plugin.

Like I say, I've not observed well-established music-playing apps halting playback so abruptly when the device is low on memory, even when they are in the background.

If background audio playback can be a critical feature for developers using this plugin, it doesn't seem right to simply destroy the playlist. Maybe there's something a that can be done to free up some less critical memory? Then the memory warning message can be passed on as this user suggests. If there's nothing you can think of, then perhaps this warning can be ignored - all the non-critical memory will have been freed up and only memory critical for operation (i.e. playlist playback) remains.

Happy to help you on this issue where I am able :-)

--

P.S. I started looking at a workaround for this issue, by setting a flag in-app when the {"type":120,"trackId":"INVALID","value":{"reason":"memory-warning"}} status is thrown, and recover afterwards when the user next opens the app and selects a song to play. But I found that after the 'memory-warning' status is thrown, no further statuses get thrown, even after a new playlist is loaded into the app and starts playing (effectively putting the app in a kind of 'degraded' state). Could that be caused by the call to [super onMemoryWarning];?

robinbanbury commented 5 years ago

I've done some testing on the fix this week (using v0.9.1 of the plugin) and it's working really well. Happy to close this issue.

Something that I didn't know about before this week - you can simulate an iOS memory warning during testing! It's available in XCode under Debug > Simulate Memory Warning when running an app on a device simulator. Really handy for testing this fix.

Rolamix / cordova-plugin-playlist