Exoplayer: [v2.12.0] preparing SimpleExoPlayer with local MP3 takes significantly longer

[y20k]

Issue description

I am using ExoPlayer in a podcast app. It plays back local MP3 files, which are often quite large. Since it is a podcast app, it saves the listening progress. It uses seekTo before starting playback, to enable users to continue listening where they stopped.

Prior to v2.12.0 prepare, seekTo and playWhenReady = true and took 0.5 seconds on my test device. These steps now take 5 seconds. Since v2.12.0 I am using setMediaItem(MediaItem mediaItem) and prepare instead of the depricated prepare(MediaSource mediaSource). I tried to use setMediaSource(MediaSource mediaSource)and prepare - but that makes no difference.

My uneducated guess would be that v2.12.0 does examine/index local MP3 files in a different way than prior versions.

Reproduction steps

You cannot reproduce the issue in an emulator. I only experience it on an actual phone. I you want to investigate this deeper you might want to

• to check out and compile my app (see below)
• add https://atp.fm/rss
• compare delay until playback begins

Production Version: uses v2.11.7 - 0.5s Startup time
https://github.com/y20k/escapepod/tree/v0.9.3
Code used to prepare the player
https://github.com/y20k/escapepod/blob/v0.9.3/app/src/main/java/org/y20k/escapepod/PlayerService.kt#L329

Current Codebase: uses v2.12.0 - 5s delay before playback
https://github.com/y20k/escapepod/tree/b660ddff744eb4b963a9a2af30987133cb654fff
Code used to prepare the player
https://github.com/y20k/escapepod/blob/b660ddff744eb4b963a9a2af30987133cb654fff/app/src/main/java/org/y20k/escapepod/PlayerService.kt#L326

Version of ExoPlayer being used

v2.12.0

Device(s) and version(s) of Android being used

OnePlus 5 - Android 9 (Issue cannot be replicated in Emulator afaik)

[kim-vde]

Thanks for reporting this issue. I will try to reproduce it. What should I write in the "Find Podcast" search bar to find https://atp.fm/rss and which podcast should I select?

[y20k]

You can just paste the feed URL into the search box. That circumvents the search and will add the Podcast.

[kim-vde]

I am afraid I can't reproduce. Can you explain exactly how you measured the time (e.g. start and end times in the code)?

[y20k]

Can you explain exactly how you measured the time

I used an external stop watch to measure the time it takes from tapping the play button until playback starts. The difference is striking - at least on my device (not in an emulator).

If you are not able to reproduce the issue using an actual (older?) phone, than I suspect there must be something wrong with my phone. In that case I apologize for stealing your time :-/

[kim-vde]

No need to apologize :) Device specific issues are common and we try to find workarounds in ExoPlayer whenever possible.

My test phone is a Pixel 2 XL. I tried to flash it to Android 9 to see if it could be plateform related but I was again unable to reproduce. The podcast takes less than a second to start once I hit the play button.

It would be helpful if you could debug and narrow down what portion of the code is time consuming on ExoPlayer 12.0. Something else you could try is to play the mp3 file on our demo app to see if you encounter the same issue there.

[kim-vde]

Additional note: @christosts tried to reproduce on a OnePlus 3T but didn't notice any difference between 2.11.7 and 2.12.0.

[y20k]

It would be helpful if you could debug and narrow down what portion of the code is time consuming on ExoPlayer 12.0.

Okay. I will try to find a way. :+1:

It would be super, if you could leave this issue open for another week, because I have no free time at hand this week.

[y20k]

I measured the difference between the old way of prepare()ing a player to the new way, by writing two timestamps into Logcat. The first, when the player gets prepared, the second when playback starts (playWhenReady = true).

1. Preparing the old way with a MediaSource (OnePlus 5)
   preparing player => 21:32:13.240
   playback started => 21:32:13.463

2. Preparing the new way with a MediaItem (OnePlus 5)
   preparing player => 21:30:29.558
   playback started => 21:30:33.137

Again I was using the above mentioned podcast. The playback position was set to approximately 60 minutes. The device, I was using, is a OnePlus 5 with Android 9 (LineageOS).

Same test in an emulator (Pixel XL API 29). The difference here is not as noticeable as on the OnePlus 5, but I was glad to see that there definitely is a difference.

1. Preparing the old way with a MediaSource (Emulator)
   preparing player => 21:34:05.485
   playback started => 21:34:05.566

2. Preparing the new way with a MediaItem (Emulator)
   preparing player => 21:36:37.197
   playback started => 21:36:38.113

Here the code used for this test. If you filter the Logcat messages for "EXOPLAYER-TEST" you should see the timestamps.

1. Preparing the old way with a MediaSource
   https://github.com/y20k/escapepod/tree/a443c1f7e94dd2a66a691ec38ba16e662156da72

2. Preparing the new way with a MediaItem
   https://github.com/y20k/escapepod/tree/819047c57c33ad5a451ad525f1cfa6fd7b313186

[kim-vde]

I tried to reproduce on my test phone and there is indeed a difference.

The time difference is of ~200 ms for the old way and of ~1.5 seconds for the new one. I'll have a closer look to see what's the reason.

[kim-vde]

I tried to reproduce your issue on our demo app because I cannot add time logs in ExoPlayer code from your app. Here is what I discovered:

• The player takes indeed some time to be prepared on my device for the file you provided (~ 1.5 seconds).
• It takes much less time for other MP3 files (~200 ms).
• It is the case for versions 2.12.0, 2.11.8 and 2.11.7 of ExoPlayer.
• The majority of the time consists in opening the DataSource.

What I would do is try to reproduce the issue on our demo app and check:

• If the preparation is as slow as with your app.
• If the bottleneck is also the opening of the DataSource (which is probably linked to the server latency). You can for example add logs in ProgressiveMediaPeriod.load().
• If you notice differences between versions.

It is much easier for us to use the demo app as a base to understand the issue and it also allows you to add logs to ExoPlayer.

[y20k]

I will take a look and see, if I can pinpoint the problem a bit more precisely.

If the bottleneck is also the opening of the DataSource (which is probably linked to the server latency)

Just to make sure that there is not misunderstanding. My app only plays back local mp3 files. There should be no problem with server latency.

[kim-vde]

Just to make sure that there is not misunderstanding. My app only plays back local mp3 files. There should be no problem with server latency.

Ah yes, right. I used URL https://traffic.libsyn.com/atpfm/atp397.mp3 for testing (which is in https://atp.fm/rss). If I play it locally, the preparation time drops to ~300 ms in the demo app.

You should try to reproduce your issue in the demo app so that we can investigate more thoroughly.

[y20k]

I tried to reproduce the issue in the ExoPlayer Demo app (respective commit in fork). In the demo app playback of a local podcast mp3 file is fast. No issues here.

Now I need to find out what my app is doing differently. What I did so far: I overwrote a lot of methods in my AnalyticsListener to see, if I that can point me to a bug in my code (see commit).

Here is the result of the additional logging: onTimelineChanged is called twice and in between those events most of the delay happens. Do you have any idea what actions can cause a timeline change? Or what that means?

CALLBACK                  TIMECODE        ADDITIONAL INFORMATION
onTimelineChanged         05:26:11.540 -> 0 (1 = SOURCE_UPDATE | 0 = PLAYLIST_CHANGED)
onMediaItemTransition     05:26:11.542
onPlaybackStateChanged    05:26:11.544
onPlayWhenReadyChanged    05:26:11.546
onLoadStarted             05:26:11.574
onIsLoadingChanged        05:26:11.575 -> true
onTimelineChanged         05:26:11.576 -> 1 (1 = SOURCE_UPDATE | 0 = PLAYLIST_CHANGED)
onTimelineChanged         05:26:14.386 -> 1 (1 = SOURCE_UPDATE | 0 = PLAYLIST_CHANGED)
onAudioEnabled            05:26:14.536
onTracksChanged           05:26:14.538
onLoadCompleted           05:26:14.644
onLoadStarted             05:26:14.647
onDownstreamFormatChanged 05:26:14.652
onPlaybackStateChanged    05:26:15.187
onIsPlayingChanged        05:26:15.190
onIsLoadingChanged        05:26:15.574 -> false

PS. the same logging applied to the old way of preparing the player (in my app). Not sure, what to make of this :-/

CALLBACK                  TIMECODE        ADDITIONAL INFORMATION
onTimelineChanged         02:19:36.939 -> 0 (1 = SOURCE_UPDATE | 0 = PLAYLIST_CHANGED)
onMediaItemTransition     02:19:36.941
onPlaybackStateChanged    02:19:36.943
onSeekStarted             02:19:36.944
onPositionDiscontinuity   02:19:36.945
onSeekProcessed           02:19:36.946
onPlayWhenReadyChanged    02:19:36.949
onLoadStarted             02:19:36.976
onTimelineChanged         02:19:36.977 -> 1 (1 = SOURCE_UPDATE | 0 = PLAYLIST_CHANGED)
onIsLoadingChanged        02:19:36.979 -> true
onTimelineChanged         02:19:37.008 -> 1 (1 = SOURCE_UPDATE | 0 = PLAYLIST_CHANGED)
onAudioEnabled            02:19:37.103
onTracksChanged           02:19:37.104
onLoadCompleted           02:19:37.105
onLoadStarted             02:19:37.106
onDownstreamFormatChanged 02:19:37.114
onPlaybackStateChanged    02:19:37.137
onIsPlayingChanged        02:19:37.138
onIsLoadingChanged        02:19:37.476 -> false

[y20k]

For the sake of completeness and on the chance that you find anything here: I added the same AnalyticsListener I mentioned earlier to a fork of the Exoplayer Demo app (see PlayerActivity.java). This fork is basically unchanged, except that (1) the mentioned podcast is for convenience sake added to media.exolist.json and that (2) playback always starts at 60 minutes of the episode. These are the results:

CALLBACK                  TIMECODE        ADDITIONAL INFORMATION
onPlayWhenReadyChanged    06:43:59.426
onTimelineChanged         06:43:59.435 -> 0(1 = SOURCE_UPDATE | 0 = PLAYLIST_CHANGED)
onMediaItemTransition     06:43:59.436
onSeekStarted             06:43:59.437
onPositionDiscontinuity   06:43:59.439
onSeekProcessed           06:43:59.441
onPlaybackStateChanged    06:43:59.444
onTracksChanged           06:43:59.501
onIsLoadingChanged        06:43:59.502 -> true
onTimelineChanged         06:43:59.505 -> 1(1 = SOURCE_UPDATE | 0 = PLAYLIST_CHANGED)
onTimelineChanged         06:43:59.533 -> 1(1 = SOURCE_UPDATE | 0 = PLAYLIST_CHANGED)
onAudioEnabled            06:43:59.611
onPlayWhenReadyChanged    06:43:59.612
onLoadCanceled            06:43:59.640
onTracksChanged           06:43:59.641
onDownstreamFormatChanged 06:43:59.642
onPlaybackStateChanged    06:43:59.652
onIsPlayingChanged        06:43:59.657
onIsLoadingChanged        06:43:59.919 -> false

[kim-vde]

Actually the media item does not seem to be local. If you check it on your app, you will see that it has URI "https://traffic.libsyn.com/atpfm/atp399.mp3".

Is the media preparation also slow if you use this URI in the demo app?

[y20k]

@kim-vde You must have overseen something. The media item should have local file Uri, like file:///storage/emulated/0/Android/data/org.y20k.escapepod/files/audio/Accidental%20Tech%20Podcast/atp399.mp3. Playback does not require a network connection.

[kim-vde]

In PlayerService.kt, I added a break point in preparePlayer(), just after line val mediaItem: MediaItem = MediaItem.fromUri(episode.getMediaId()). Then I noticed that mediaItem.PlaybackProperties.uri was set to https://traffic.libsyn.com/atpfm/atp399.mp3.

Then, I added a breadpoint in ExoPlayer DefaultDataSource.java in method open and observed that the dataSource selected was an HTTP data source.

If I turn off the WiFi on my phone, the podcast doesn't play anymore (with ExoPlayer 2.12.0). I think the problem lies in how the MediaItem is built.

[y20k]

OMG. You are right. I feel embarrassed. I knew the error must have been somewhere in my code, since I could not reproduce the problem in the demo app. But I did not expect the mistake to be that obvious:

Fast playback startup (production)
=> here I used createMediaSource(Uri.parse(episode.audio) to create the MediaSource.

Slow playback startup (test)
=> here I used MediaItem.fromUri(episode.getMediaId()) to create the MediaItem

I am banging my head on the keyboard here. I should have used episode.audio to create the MediaItem. episode.getMediaId(), which I used instead, returns an unique identifier for a podcast episode. This identifier currently happens to be the URL of the original audio file. That URL was never intended to be used for playback(*).

Once I changed my code to use episode.audio to create the MediaItem, everything works great (again).

CALLBACK                  TIMECODE        ADDITIONAL INFORMATIO
onTimelineChanged         22:47:38.259 -> 0 (1 = SOURCE_UPDATE | 0 = PLAYLIST_CHANGED)
onMediaItemTransition     22:47:38.260
onPlaybackStateChanged    22:47:38.261
onPlayWhenReadyChanged    22:47:38.270
onLoadStarted             22:47:38.293
onTimelineChanged         22:47:38.295 -> 1 (1 = SOURCE_UPDATE | 0 = PLAYLIST_CHANGED)
onIsLoadingChanged        22:47:38.296 -> true
onTimelineChanged         22:47:38.329 -> 1 (1 = SOURCE_UPDATE | 0 = PLAYLIST_CHANGED)
onAudioEnabled            22:47:38.388
onTracksChanged           22:47:38.389
onDownstreamFormatChanged 22:47:38.390
onPlaybackStateChanged    22:47:38.487
onIsPlayingChanged        22:47:38.490
onIsLoadingChanged        22:47:38.756 -> false
onPlayWhenReadyChanged    22:47:40.646
onIsPlayingChanged        22:47:40.653

I really and sincerely hope, that you did not spent too much time here. I hoped to be somehow able to help with improving ExoPlayer - but in the end you helped me. (THX)

(*) I learned among other things: MP3 audio streaming works extremely well out of the box with ExoPlayer. My podcast player should probably support audio streaming in the future.

[kim-vde]

No problem, happy to help!