踩坑之路:MediaPlayer播放完成偶现onCompleti

作者: CDF_cc7d | 来源:发表于2020-10-24 11:35 被阅读0次

背景

前段时间再做一个需求

是一个过渡页面，
过渡页面播放音频(播放"终回"音频)
音频播放完毕，跳转到下一个页面

需求其实挺简单的，然后很快就把代码写完了。跑了两遍也都是正常执行，于是二话不说就提测了。后来某天测试提出过渡页面会卡住，不会跳转到下一个页面。如下所示，一直卡在终回页面上面

不会跳转.gif

于是我第一时间想到就是难道是我忘记设置结束的回调方法了?特意去查看了下代码:

                val voicePlayer = VoicePlayerUnMute()
                voicePlayer.play(mRoundVoiceRes)
                voicePlayer.setOnCompletionListener {
                    LogHelper.i(TAG, "onNextPage tag = $tag")
                    onNextPage()
                }

这里的VoicePlayerUnMute是封装的MediaPlayer，然后播放指定的音频文件，设置了setOnCompletionListener ，代码好像没什么问题，于是跑过去问了下情况，了解到这个是个偶现的bug。

既然代码上面看上去没啥问题，会不会是MediaPlayer在播放的时候出现了Error，导致onCompletion回调没有执行？于是我又加了一点代码:

                val voicePlayer = VoicePlayerUnMute()
                voicePlayer.play(mRoundVoiceRes)
                voicePlayer.setOnCompletionListener {
                    LogHelper.i(TAG, "onNextPage tag = $tag")
                    onNextPage()
                }
                voicePlayer.setOnErrorListener { _: MediaPlayer, _: Int, _: Int ->
                    LogHelper.i(TAG,"播放出现了错误")
                    false
                }

由于是偶现的问题，所以我多试了几次，确实是会出现几次页面卡住跳转不过去的现象，但是onError里面并没有打印出相应的Log。这下有点懵圈了，没有出现播放错误，那到底是出了什么问题？

粗略的看了下onCompletion回调的执行，搜索了一下发现有两处:

            case MEDIA_PLAYBACK_COMPLETE:
                {
                    mOnCompletionInternalListener.onCompletion(mMediaPlayer);
                    OnCompletionListener onCompletionListener = mOnCompletionListener;
                    if (onCompletionListener != null)
                        onCompletionListener.onCompletion(mMediaPlayer);
                }
                stayAwake(false);
                return;

            case MEDIA_ERROR:
                Log.e(TAG, "Error (" + msg.arg1 + "," + msg.arg2 + ")");
                boolean error_was_handled = false;
                OnErrorListener onErrorListener = mOnErrorListener;
                if (onErrorListener != null) {
                    error_was_handled = onErrorListener.onError(mMediaPlayer, msg.arg1, msg.arg2);
                }
                {
                    mOnCompletionInternalListener.onCompletion(mMediaPlayer);
                    OnCompletionListener onCompletionListener = mOnCompletionListener;
                    if (onCompletionListener != null && ! error_was_handled) {
                        onCompletionListener.onCompletion(mMediaPlayer);
                    }
                }
                stayAwake(false);
                return;

一处是播放完成的时候回调，一处是播放出现错误的时候出现了回调。这个时候才发现刚才的猜想完全就是错误的。所以现在为止还是没有找到原因所在。

我又重新操作了几次，发现这几次不跳转的情况中，有播放完的，也有播放到一半停住的。所以是什么地方调用MediaPlayer的stop或者pause了？后来想想又感觉不可能，自己的player对象是个局部变量，用的地方就这么一处，怎么可能会调用这几个方法。这下就更加疑惑了，MediaPlayer内部实现逻辑太复杂，一次性想要吃透太困难了，现在bug又必须得尽早改掉，这事看上去越来越棘手了。

没办法，只能暂时比对一下正常情况下和异常情况下的MediaPlayer的log吧:

2020-10-20 19:44:26.425 21860-21860/com.youdao.youdaomath D/MediaPlayer: handleMessage msg:(1, 0, 0)
2020-10-20 19:44:26.425 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: getCurrentPosition
2020-10-20 19:44:26.426 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: isPlaying: 0
2020-10-20 19:44:26.429 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: invoke 72
2020-10-20 19:44:26.432 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: isPlaying: 0
2020-10-20 19:44:26.432 21860-21860/com.youdao.youdaomath I/VoicePlayerUnMute2: [VoicePlayerUnMute2] start
2020-10-20 19:44:26.432 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: getDuration_l
2020-10-20 19:44:26.435 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: start
2020-10-20 19:44:26.437 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: MediaPlayer::setVolume(1.000000, 1.000000)
2020-10-20 19:44:26.507 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: message received msg=6, ext1=0, ext2=0
2020-10-20 19:44:26.507 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: unrecognized message: (6, 0, 0)
2020-10-20 19:44:26.508 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: callback application
2020-10-20 19:44:26.508 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: back from callback
2020-10-20 19:44:26.509 21860-21860/com.youdao.youdaomath D/MediaPlayer: handleMessage msg:(6, 0, 0)
2020-10-20 19:44:26.509 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: getCurrentPosition
2020-10-20 19:44:26.510 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: isPlaying: 1
2020-10-20 19:44:26.791 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: message received msg=211, ext1=0, ext2=0
2020-10-20 19:44:26.791 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: unrecognized message: (211, 0, 0)
2020-10-20 19:44:26.791 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: callback application
2020-10-20 19:44:26.791 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: back from callback
2020-10-20 19:44:26.792 21860-21860/com.youdao.youdaomath D/MediaPlayer: handleMessage msg:(211, 0, 0)
2020-10-20 19:44:27.834 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: message received msg=2, ext1=0, ext2=0
2020-10-20 19:44:27.834 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: playback complete
2020-10-20 19:44:27.834 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: callback application
2020-10-20 19:44:27.835 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: back from callback
2020-10-20 19:44:27.835 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: message received msg=211, ext1=0, ext2=0
2020-10-20 19:44:27.835 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: unrecognized message: (211, 0, 0)
2020-10-20 19:44:27.835 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: callback application
2020-10-20 19:44:27.835 21860-21860/com.youdao.youdaomath D/MediaPlayer: handleMessage msg:(2, 0, 0)
2020-10-20 19:44:27.836 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: back from callback

上面这个是正常情况下的log

2020-10-20 19:58:26.416 21860-21860/com.youdao.youdaomath D/MediaPlayer: handleMessage msg:(1, 0, 0)
2020-10-20 19:58:26.416 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: getCurrentPosition
2020-10-20 19:58:26.417 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: isPlaying: 0
2020-10-20 19:58:26.420 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: invoke 72
2020-10-20 19:58:26.424 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: isPlaying: 0
2020-10-20 19:58:26.424 21860-21860/com.youdao.youdaomath I/VoicePlayerUnMute2: [VoicePlayerUnMute2] start
2020-10-20 19:58:26.425 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: getDuration_l
2020-10-20 19:58:26.428 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: start
2020-10-20 19:58:26.431 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: MediaPlayer::setVolume(1.000000, 1.000000)
2020-10-20 19:58:26.488 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: message received msg=6, ext1=0, ext2=0
2020-10-20 19:58:26.488 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: unrecognized message: (6, 0, 0)
2020-10-20 19:58:26.488 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: callback application
2020-10-20 19:58:26.488 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: back from callback
2020-10-20 19:58:26.489 21860-21860/com.youdao.youdaomath D/MediaPlayer: handleMessage msg:(6, 0, 0)
2020-10-20 19:58:26.490 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: getCurrentPosition
2020-10-20 19:58:26.490 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: isPlaying: 1
2020-10-20 19:58:26.763 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: message received msg=211, ext1=0, ext2=0
2020-10-20 19:58:26.763 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: unrecognized message: (211, 0, 0)
2020-10-20 19:58:26.763 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: callback application
2020-10-20 19:58:26.763 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: back from callback
2020-10-20 19:58:26.763 21860-21860/com.youdao.youdaomath D/MediaPlayer: handleMessage msg:(211, 0, 0)
2020-10-20 19:58:27.232 21860-21875/com.youdao.youdaomath D/MediaPlayer: finalize native_finalize called
2020-10-20 19:58:27.232 21860-21875/com.youdao.youdaomath W/MediaPlayer-JNI: MediaPlayer finalized without being released
2020-10-20 19:58:27.232 21860-21875/com.youdao.youdaomath V/MediaPlayerNative: setListener
2020-10-20 19:58:27.232 21860-21875/com.youdao.youdaomath V/MediaPlayerNative: disconnect
2020-10-20 19:58:27.260 21860-21875/com.youdao.youdaomath V/MediaPlayerNative: destructor
2020-10-20 19:58:27.261 21860-21875/com.youdao.youdaomath V/MediaPlayerNative: disconnect
2020-10-20 19:58:27.261 21860-21875/com.youdao.youdaomath D/MediaPlayer: finalize native_finalize finished
2020-10-20 19:58:28.256 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: message received msg=2, ext1=0, ext2=0
2020-10-20 19:58:28.256 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: playback complete
2020-10-20 19:58:28.256 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: callback application
2020-10-20 19:58:28.256 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: back from callback
2020-10-20 19:58:28.257 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: message received msg=211, ext1=0, ext2=0
2020-10-20 19:58:28.257 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: unrecognized message: (211, 0, 0)
2020-10-20 19:58:28.257 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: callback application
2020-10-20 19:58:28.257 21860-21860/com.youdao.youdaomath D/MediaPlayer: handleMessage msg:(2, 0, 0)
2020-10-20 19:58:28.257 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: back from callback
2020-10-20 19:58:28.263 21860-21860/com.youdao.youdaomath D/MediaPlayer: handleMessage msg:(211, 0, 0)

上面这个是异常情况的log

这一看还真看出点名堂来,仔细发现异常情况下多了下面这段log:

2020-10-20 19:58:27.232 21860-21875/com.youdao.youdaomath D/MediaPlayer: finalize native_finalize called
2020-10-20 19:58:27.232 21860-21875/com.youdao.youdaomath W/MediaPlayer-JNI: MediaPlayer finalized without being released
2020-10-20 19:58:27.232 21860-21875/com.youdao.youdaomath V/MediaPlayerNative: setListener
2020-10-20 19:58:27.232 21860-21875/com.youdao.youdaomath V/MediaPlayerNative: disconnect
2020-10-20 19:58:27.260 21860-21875/com.youdao.youdaomath V/MediaPlayerNative: destructor
2020-10-20 19:58:27.261 21860-21875/com.youdao.youdaomath V/MediaPlayerNative: disconnect
2020-10-20 19:58:27.261 21860-21875/com.youdao.youdaomath D/MediaPlayer: finalize native_finalize finished

看样子似乎是被release调了？
根据第二行log：

2020-10-20 19:58:27.232 21860-21875/com.youdao.youdaomath W/MediaPlayer-JNI: MediaPlayer finalized without being released

认定应该是JNI里面打出来的log，MediaPlayer是android.media包下面的类文件，那么JNI名字应该是android_media_MediaPlayer.cpp，于是在源码社区搜索了一下这个文件:

image.png

确实是有相应的文件，那么就打开文件搜索下"MediaPlayer finalized without being released"这个log:

static void
android_media_MediaPlayer_native_finalize(JNIEnv *env, jobject thiz)
{
    ALOGV("native_finalize");
    sp<MediaPlayer> mp = getMediaPlayer(env, thiz);
    if (mp != NULL) {
        ALOGW("MediaPlayer finalized without being released");
    }
    android_media_MediaPlayer_release(env, thiz);
}

以此反推，MediaPlayer.java里面应该是调用了native_finalize方法，继续往下搜索:

private native final void native_finalize();

果然有这么一个方法，在查看下调用的地方:

    @Override
    protected void finalize() {
        baseRelease();
        native_finalize();
    }

finalize方法调用，看到这里，我直接裂开了有没有。finalize方法是虚拟机在GC的时候调用的，具体可以看下这篇Java虚拟机内存管理机制。我的Player对象就直接被GC了么？目前暂时也没有去证明，既然找到了原因，那就改以下代码，直接将player对象设置成类的成员变量：

    /**
     * 播放回合的音频播放器
     */
    private var mRoundVoicePlayer = VoicePlayerUnMute()

                mRoundVoicePlayer.play(mRoundVoiceRes)
                mRoundVoicePlayer.setOnCompletionListener {
                    LogHelper.i(TAG, "onNextPage tag = $tag")
                    onNextPage()
                }

然后再试效果:

修改后.gif

的确应该是改好了(原来试验10次大概会出现3次卡主不动，改完之后就试了十几次都没再出现过了)

真是一个让人胃疼的Bug。。。

踩坑之路:MediaPlayer播放完成偶现onCompleti

背景

相关文章

网友评论

延伸阅读

深度阅读

栏目导航

热点阅读