ANR on player release

[aarondib]

Issue description

According to log reports from users, after upgrade to r2.8.1 (from r2.6.1), on about 1% of app sessions we have ANR on SimpleExoPlayer.release().
Never seen this issue (reports) on versions <=r2.6.1.

Reproduction steps

Play some stream and then call SimpleExoPlayer.release(), called in main thread.

Link to test content

Unknown for a while.

Version of ExoPlayer being used

r2.8.1.

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

Different devices and Android versions: Nvidia Shield TV, Xiaomi Mi-Box, etc.

A full bug report captured from the device

"main" tid=1 Waiting

"main" prio=5 tid=1 Waiting | group="main" sCount=1 dsCount=0 obj=0x762777f0 self=0x7527e95a00 | sysTid=32258 nice=-10 cgrp=default sched=0/0 handle=0x752beaea98 | state=S schedstat=( 264497782805 29710697109 1267932 ) utm=22158 stm=4291 core=7 HZ=100 | stack=0x7ff8a69000-0x7ff8a6b000 stackSize=8MB | held mutexes=
at java.lang.Object.wait! (Native method)
- waiting on <0x0225fb39> (a com.google.android.exoplayer2.ExoPlayerImplInternal)
at com.google.android.exoplayer2.ExoPlayerImplInternal.release (unavailable)
- locked <0x0225fb39> (a com.google.android.exoplayer2.ExoPlayerImplInternal)
com.google.android.exoplayer2.ExoPlayerImpl.release (unavailable)
com.google.android.exoplayer2.SimpleExoPlayer.release (unavailable)
...

[andrewlewis]

• It would be useful to see a bug report so we can check what the playback thread is doing (it is responsible for notifying the thread waiting in release that resources have been returned to the system). If you have one, please could you attach it here or email it to dev.exoplayer@gmail.com with subject "Issue ANR on player release #4352"?
• Do you have any information on whether all devices are affected equally, or certain devices are affected more than others?
• To help narrow down which changes between 2.6.1 and 2.8.1 might have caused this, it would be good to know if the app is doing anything that would exercise recently added functionality like: setting/clearing the player's surface during playback, or using blocking message sending (we couldn't see any issues with this, but thought it was worth checking just in case). Thanks!

[ojw28]

Agreed we need a full bug report (or at least the stack traces of all of the threads) to debug this.

[aarondib]

1. Could this "bug report" be get from Google Play Console's ANR reports? And will it has enough data to analyze playback thread?

2. Looks like, all devices are affected equally. It will be more precise when more users install app update.

3. We did not added any new features when upgraded from 2.6.1 to 2.8.1.
   No manual message sending.
   But surface changing during playback had been added a long time ago. For example, when Surface occasionally happens to be recreated during playback.

[aarondib]

@andrewlewis sent you an e-mail with ANR bug reports from different devices.

[ojw28]

Looking at the stack traces, it looks like release is blocked on the playback thread, which is typical for this kind of ANR. The playback thread is blocked on various different codec related platform calls (e.g. MediaCodec.native_stop), without a clear pattern.

We do see this kind of ANR happen occasionally on devices, when the underlying platform media server gets into a bad state. This is not something we'd expect to occur more frequently with 2.8.0 than earlier releases, however, and I'm not aware of anything that we did that's likely to have exacerbated the issue.

Are you certain these ANRs are increased as of 2.8.0, rather than some other change, such as them being better reported than they were previously? What ANR rate did you see when releasing the player previously? It should have been higher than 0 if ANRs were being reported correctly, since we've been aware of rare/sporadic ANRs when calling release for quite a long time.

[aarondib]

@ojw28 Thanks!

We have not seen any of ExoPlayer related ANR reports before. Even can't find any of them.
It appears in the last version which uses upgraded 2.8.1 version. The app is on beta stage currently and not looks like it's too much of them but comparable value with the others.
We'll put the app with 2.8.1 as a release and then inform you of the result ANR rate.

Do you have any ideas why could we have not seen ExoPlayer related ANRs before?

[ojw28]

That's (unfortunately!) strange, unless you were previously not calling release on the player. Is that possible? If not, then I think I would expect at least the odd ANR to be reported. Please do let us know what you discover.

[prcaen]

Hey,
We are using the 2.7.3 and we are facing the same issue.
So this is not specific to 2.8.X version.

[aarondib]

After the final release we do not see any valuable ANR growth. However, we saw it (ExoPlayer-related ANRs) in reports of Beta-versions. Probably, was caught "problematc" beta testers.

Also, during research we've found some specific devices on which changing Surface on-the-fly causes ANRs. Will open separate issue on this. Thanks!

[abubalanandan]

Hi,

I'm seeing the same ANR issue on both the release() method of the exoplayer and also the blockingSendMessages of the exoplayer. Am on exoplayer 2.2.0. Seeing that this issue has still not been resolved, is there good reason to update to the latest version and try? Also, any workarounds for this issue? I have attached stack traces for both issues.
blockingSendMessages.txt
release_trace.txt

[sixones]

We are experiencing this issue in 2.7.1 as well, stacktrace from the Google Play Console, as you can see we call SimpleExoPlayer.release.

  at java.lang.Object.wait (Object.java)
- waiting on <0x057d9834> (a com.google.android.exoplayer2.k)
  at com.google.android.exoplayer2.ExoPlayerImplInternal.release (ExoPlayerImplInternal.java:232)
- locked <0x057d9834> (a com.google.android.exoplayer2.k)
  at com.google.android.exoplayer2.ExoPlayerImpl.release (ExoPlayerImpl.java:342)
  at com.google.android.exoplayer2.SimpleExoPlayer.release (SimpleExoPlayer.java:681)
  at com.plexapp.plex.videoplayer.local.v2.Exo2VideoPlayer.disconnect

This looks to be only picked up now because of the changes to ANR's on the Google Play Console, rather than an issue in a new version of ExoPlayer v2 (at least from what we can tell).

[Tolriq]

@ojw28 / @tonihei After all discussions about threading and the adding of your internal stat handler that creates the race conditions #4278.

I finally followed the recommendations and switched to all access on mainthread and I'm now facing this ANR too. (Google Vitals, unable to reproduce yet)

"main" prio=5 tid=1 Waiting
  | group="main" sCount=1 dsCount=0 obj=0x749478d0 self=0x7f92095a00
  | sysTid=9432 nice=0 cgrp=default sched=0/0 handle=0x7f95f53a98
  | state=S schedstat=( 0 0 0 ) utm=1130 stm=86 core=4 HZ=100
  | stack=0x7fd81f0000-0x7fd81f2000 stackSize=8MB
  | held mutexes=
  at java.lang.Object.wait! (Native method)
- waiting on <0x026f6e6f> (a com.google.android.exoplayer2.l)
  at com.google.android.exoplayer2.l.a (ExoPlayerImplInternal.java:228)
- locked <0x026f6e6f> (a com.google.android.exoplayer2.l)
  at com.google.android.exoplayer2.j.c (ExoPlayerImpl.java:372)
  at com.google.android.exoplayer2.al.c (SimpleExoPlayer.java:788)
  at org.leetzone.android.yatsewidget.f.c.e$b.run (MusicPlayer.kt:200)
  at android.os.Handler.handleCallback (Handler.java:751)
  at android.os.Handler.dispatchMessage (Handler.java:95)
  at android.os.Looper.loop (Looper.java:154)
  at android.app.ActivityThread.main (ActivityThread.java:6186)
  at java.lang.reflect.Method.invoke! (Native method)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run (ZygoteInit.java:889)
  at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:779)

Related code is;

    handler.sendEmptyMessage(MSG_RELEASE);
    boolean wasInterrupted = false;
    while (!released) {
      try {
        wait();
      } catch (InterruptedException e) {
        wasInterrupted = true;
      }
    }

IMO you can't ask people to call that on main thread as there's so many possible reasons for a message sent to a thread to be delayed or not arriving at all.

Hard to choose between very rare race conditions or rare ANR.

And a little disappointed that the issue was known yet pushing toward main thread :(
since we've been aware of rare/sporadic ANRs when calling release for quite a long time.
I should have rewritten the code to do everything on a background thread instead.

Is there a way to reduce risk of race conditions with your stat handler when moving back the release call to background thread?