v0.21.2 video playback performance regression

[FrostKiwi]

With the update to v0.21.2 my OnePlus One is unable to playback 1080p60 videos smoothly any more. Instead it drops it's framerate to below 10fps and becomes a slide show. Going down to 720p60 solves the issue.
This was not the case before v0.21.2.
Anyone else having this experience or is it just my device?

Checklist

• I am using the latest version - v0.21.2
• I checked, but didn't find any duplicates (open OR closed) of this issue in the repo.
• I have read the contribution guidelines given at https://github.com/TeamNewPipe/NewPipe/blob/HEAD/.github/CONTRIBUTING.md.
• This issue contains only one bug. I will open one issue for every bug report I want to file.

Device info

• Android version/Custom ROM version: Android 10, LineageOS 17.1
• Device model: OnePlus One (A0001)

[AudricV]

Maybe this was caused with the last ExoPlayer update (#5856)? @Redirion What do you think?
Also @FrostKiwi what format are you using to stream videos? MP4 or WEBM?

From a personnal note, on my device, an Honor 9X running EMUI 10, I can't play smoothly videos in 1080p60 with WEBM but I can with MP4. This happens before this release and is related to my device and its performances.

[FrostKiwi]

Maybe this was caused with the last ExoPlayer update (#5856)? @Redirion What do you think?

I'll go ahead and mess with downgrades then, thx for the reference

I can't play smoothly videos in 1080p60 with WEBM but I can with MP4.

Unfortunately, it concerns MPEG-4 as well :S

[FrostKiwi]

@TiA4f8R
Arright, here are the downgrading results:
Downgraded to v0.21.0 - MPEG-4 1080p60 videoplayback is smooth
Upraded to v0.21.1 - MPEG-4 1080p60 videoplayback is smooth
Upraded to v0.21.2 - MPEG-4 1080p60 videoplayback is a 10fps slideshow mess. Besides that, turning the phone from vertical to horizontal with this version takes forever, like up to 3 seconds.
The one major feature introduced with 0.21.2 was the playback control while buffering...

[AudricV]

I always think it's a problem with ExoPlayer.
@FrostKiwi Can you capture logs from a debug APK with ADB, like this one based on 4a9c790 and post only the entries of the app in this issue? Thanks!

[FrostKiwi]

@TiA4f8R
Here is the ADB logcat output, from the moment I started that NewPipe Debug apk.

Actions performed in log in chronological order: I opened NewPipe Debug, opened a video, changed to 1080p60, NewPipe Debug crashed, misclicked and opened for a splitsecond the releasebuild of Newpipe, opened NewPipe Debug again, started the video again, changed to 1080p60, watched the video in the 10fps slideshow lag awfulness and finally closed the app.
catlog.txt

If by "capture logs from a debug APK with ADB" you were not referring to logcat, pls elaborate and tell me how to capture the log in the format you asked for.

[AudricV]

I was indeed refering to Android's logcat, thank you! Now you will need to a wait that a developer checks what's wrong (I am not one). This can take some time.

[TobiGr]

I can onyl make guesses, but that's what I've found:

Framedrops

We are getting a bunch of lines which are similar to this one:

05-02 14:54:01.494 22575 22575 I Choreographer: Skipped 52 frames!  The application may be doing too much work on its main thread.

These are always preceeded by some kind of animate() method being called. Looks like some animations require too much CPU time. I cannot think of any changes in animation handling from 0.21.1 to 0.21.2. That's why I guess the unterlying issue might be something else which triggers the animation.

Log 1

05-02 14:54:01.350 22575 22575 D VideoDetailFragment@e21e61e: handleResult() called with: result = [StreamInfo[url="https://www.youtube.com/watch?v=3Nj96AS_QJ8", name="Valve needs to be communicating right."]]
05-02 14:54:01.350 22575 22575 D ViewUtils: animate():    false →  [ProgressBar:loading_progress_bar] [ALPHA 0:0] execOnEnd=null
05-02 14:54:01.351 22575 22575 D ViewUtils: animate():    false →  [LinearLayout:error_panel] [ALPHA 150:0] execOnEnd=null
05-02 14:54:01.351 22575 22575 D ViewUtils: animate(): view was already gone > view = [android.widget.LinearLayout{2b8a38c G.E...... ......I. 0,0-0,0 #7f0a011c app:id/error_panel}]
05-02 14:54:01.363 22575 22575 D LeakCanary: Watching instance of android.widget.RelativeLayout (org.schabi.newpipe.fragments.list.comments.CommentsFragment received Fragment#onDestroyView() callback (references to its views should be cleared to prevent leaks)) with key b610cb7f-2897-4d36-80e3-401d3e43f40f
05-02 14:54:01.364 22575 22575 D LeakCanary: Watching instance of androidx.loader.app.LoaderManagerImpl$LoaderViewModel (androidx.loader.app.LoaderManagerImpl$LoaderViewModel received ViewModel#onCleared() callback) with key 0ec5eb39-c1f8-46af-a101-95f154d94a88
05-02 14:54:01.364 22575 22575 D LeakCanary: Watching instance of leakcanary.internal.ViewModelClearedWatcher (leakcanary.internal.ViewModelClearedWatcher received ViewModel#onCleared() callback) with key 354faa72-cb95-4d1b-816e-84bf1f26e100
05-02 14:54:01.365 22575 22575 D LeakCanary: Watching instance of org.schabi.newpipe.fragments.list.comments.CommentsFragment with key 9b2ad367-0f97-4061-bd12-604eff849407
05-02 14:54:01.365 22575 22575 D StateSaver: onDestroy() called with: savedState = [131946954587161 > ]
05-02 14:54:01.365 22575 22575 D LeakCanary: Watching instance of org.schabi.newpipe.fragments.list.comments.CommentsFragment (org.schabi.newpipe.fragments.list.comments.CommentsFragment received Fragment#onDestroy() callback) with key e08a8cdd-17ff-411b-a2e9-05c8a5024fed
05-02 14:54:01.369 22575 22575 D LeakCanary: Watching instance of android.widget.RelativeLayout (org.schabi.newpipe.fragments.list.videos.RelatedItemsFragment received Fragment#onDestroyView() callback (references to its views should be cleared to prevent leaks)) with key 0e4819ef-c4b3-4547-9dc6-912554a70c29
05-02 14:54:01.370 22575 22575 D LeakCanary: Watching instance of androidx.loader.app.LoaderManagerImpl$LoaderViewModel (androidx.loader.app.LoaderManagerImpl$LoaderViewModel received ViewModel#onCleared() callback) with key 456a5c3c-50c5-4382-99b2-832432f80e5c
05-02 14:54:01.370 22575 22575 D LeakCanary: Watching instance of leakcanary.internal.ViewModelClearedWatcher (leakcanary.internal.ViewModelClearedWatcher received ViewModel#onCleared() callback) with key db21eeef-c02b-469e-a52a-a8f52f2fff45
05-02 14:54:01.371 22575 22575 D LeakCanary: Watching instance of org.schabi.newpipe.fragments.list.videos.RelatedItemsFragment with key e801cc4f-0075-432e-9781-b36394f53f9d
05-02 14:54:01.371 22575 22575 D StateSaver: onDestroy() called with: savedState = [131946862158186 > ]
05-02 14:54:01.371 22575 22575 D LeakCanary: Watching instance of org.schabi.newpipe.fragments.list.videos.RelatedItemsFragment (org.schabi.newpipe.fragments.list.videos.RelatedItemsFragment received Fragment#onDestroy() callback) with key 4e449ea5-d63c-485c-a722-01b1dd6e3d99
05-02 14:54:01.373 22575 22575 D CommentsFragment@f082f8d: onCreate() called with: savedInstanceState = [null]
05-02 14:54:01.375 22575 22575 D RelatedItemsFragment@43f4ec1: onCreate() called with: savedInstanceState = [null]
05-02 14:54:01.395 22575 22575 D CommentsFragment@f082f8d: onViewCreated() called with: rootView = [android.widget.RelativeLayout{2c55138 V.E...... ......I. 0,0-0,0}], savedInstanceState = [null]
05-02 14:54:01.399 22575 22575 D CommentsFragment@f082f8d: doInitialLoadLogic() called
05-02 14:54:01.399 22575 22575 D CommentsFragment@f082f8d: startLoading() called with: forceLoad = [false]
05-02 14:54:01.400 22575 22575 D ViewUtils: animate():    false →  [LinearLayout:empty_state_view] [ALPHA 150:0] execOnEnd=null
05-02 14:54:01.400 22575 22575 D ViewUtils: animate(): view was already gone > view = [android.widget.LinearLayout{f161676 G.E...... ......I. 0,0-0,0 #7f0a0104 app:id/empty_state_view}]
05-02 14:54:01.400 22575 22575 D ViewUtils: animate():     true →  [ProgressBar:loading_progress_bar] [ALPHA 400:0] execOnEnd=null
05-02 14:54:01.401 22575 22575 D ViewUtils: animate():    false →  [LinearLayout:error_panel] [ALPHA 150:0] execOnEnd=null
05-02 14:54:01.401 22575 22575 D ViewUtils: animate(): view was already gone > view = [android.widget.LinearLayout{1a48e4 G.E...... ......I. 0,0-0,0 #7f0a011c app:id/error_panel}]
05-02 14:54:01.403 22575 27082 D InfoCache: getFromKey() called with: serviceId = [0], url = [https://www.youtube.com/watch?v=3Nj96AS_QJ8]
05-02 14:54:01.403 22575 27082 D ExtractorHelper: loadFromCache() called, info > CommentsInfo[url="https://m.youtube.com/watch?v=3Nj96AS_QJ8" (originalUrl="https://www.youtube.com/watch?v=3Nj96AS_QJ8"), name="Comments"]
05-02 14:54:01.422 22575 22575 D RelatedItemsFragment@43f4ec1: onViewCreated() called with: rootView = [android.widget.RelativeLayout{d60f175 V.E...... ......I. 0,0-0,0}], savedInstanceState = [null]
05-02 14:54:01.431 22575 22575 D RelatedItemsFragment@43f4ec1: doInitialLoadLogic() called
05-02 14:54:01.431 22575 22575 D RelatedItemsFragment@43f4ec1: startLoading() called with: forceLoad = [false]
05-02 14:54:01.431 22575 22575 D ViewUtils: animate():    false →  [LinearLayout:empty_state_view] [ALPHA 150:0] execOnEnd=null
05-02 14:54:01.431 22575 22575 D ViewUtils: animate(): view was already gone > view = [android.widget.LinearLayout{7e9817b G.E...... ......I. 0,0-0,0 #7f0a0104 app:id/empty_state_view}]
05-02 14:54:01.432 22575 22575 D ViewUtils: animate():     true →  [ProgressBar:loading_progress_bar] [ALPHA 400:0] execOnEnd=null
05-02 14:54:01.432 22575 22575 D ViewUtils: animate():    false →  [LinearLayout:error_panel] [ALPHA 150:0] execOnEnd=null
05-02 14:54:01.432 22575 22575 D ViewUtils: animate(): view was already gone > view = [android.widget.LinearLayout{5c2ff1 G.E...... ......I. 0,0-0,0 #7f0a011c app:id/error_panel}]
05-02 14:54:01.448 22575 22575 D ViewUtils: animate():     true →  [AppCompatImageView:detail_thumbnail_play_button] [ALPHA 200:0] execOnEnd=null
05-02 14:54:01.463 22575 22575 D ViewUtils: animate():     true →  [AppCompatTextView:detail_duration_view] [ALPHA 100:0] execOnEnd=null
05-02 14:54:01.493 22575 22575 D Player  : onBroadcastReceived() called with: intent = [Intent { act=org.schabi.newpipe.debug.VideoDetailFragment.ACTION_VIDEO_FRAGMENT_RESUMED flg=0x10 }]
05-02 14:54:01.494 22575 22575 I Choreographer: Skipped 52 frames!  The application may be doing too much work on its main thread.

Log 2

05-02 14:54:52.002 27693 27693 D RelatedItemsFragment@4896a3f: doInitialLoadLogic() called
05-02 14:54:52.002 27693 27693 D RelatedItemsFragment@4896a3f: handleResult() called with: result = [RelatedItemInfo[url="https://www.youtube.com/watch?v=3Nj96AS_QJ8", name="Valve needs to be communicating right."]]
05-02 14:54:52.002 27693 27693 D ViewUtils: animate():    false →  [LinearLayout:empty_state_view] [ALPHA 150:0] execOnEnd=null
05-02 14:54:52.002 27693 27693 D ViewUtils: animate(): view was already gone > view = [android.widget.LinearLayout{74893da G.E...... ......I. 0,0-0,0 #7f0a0104 app:id/empty_state_view}]
05-02 14:54:52.003 27693 27693 D ViewUtils: animate():    false →  [ProgressBar:loading_progress_bar] [ALPHA 0:0] execOnEnd=null
05-02 14:54:52.003 27693 27693 D ViewUtils: animate(): view was already gone > view = [android.widget.ProgressBar{b8f900b G.ED..... ......I. 0,0-0,0 #7f0a01f3 app:id/loading_progress_bar}]
05-02 14:54:52.003 27693 27693 D ViewUtils: animate():    false →  [LinearLayout:error_panel] [ALPHA 150:0] execOnEnd=null
05-02 14:54:52.003 27693 27693 D ViewUtils: animate(): view was already gone > view = [android.widget.LinearLayout{d85dee8 G.E...... ......I. 0,0-0,0 #7f0a011c app:id/error_panel}]
05-02 14:54:52.003 27693 27693 D ViewUtils: animate():     true →  [RecyclerView:items_list] [ALPHA 300:0] execOnEnd=null
05-02 14:54:52.004 27693 27693 D ViewUtils: animate(): view was already visible > view = [androidx.recyclerview.widget.RecyclerView{b5ac901 VFED.V... ......I. 0,0-0,0 #7f0a01b7 app:id/items_list}]
05-02 14:54:52.064 27693 27693 D SearchFragment@a615680: onResume() called
05-02 14:54:52.065 27693 27693 D SearchFragment@a615680: hideKeyboardSearch() called
05-02 14:54:52.065 27693 27693 D SearchFragment@a615680: hideSuggestionsPanel() called
05-02 14:54:52.066 27693 27693 D ViewUtils: animate():    false →  [LinearLayout:suggestions_panel] [LIGHT_SLIDE_AND_ALPHA 200:0] execOnEnd=null
05-02 14:54:52.066 27693 27693 D ViewUtils: animate(): view was already gone > view = [android.widget.LinearLayout{24fef2c GFE...... ......ID 0,0-0,0 #7f0a0333 app:id/suggestions_panel}]
05-02 14:54:52.086 27693 27693 D Player  : onBroadcastReceived() called with: intent = [Intent { act=android.intent.action.CONFIGURATION_CHANGED flg=0x70200010 }]
05-02 14:54:52.089 27693 27693 D Player  : onConfigurationChanged() called
05-02 14:54:52.094 27693 27693 D Player  : updateScreenSize() called: screenWidth = [1920.0], screenHeight = [1080.0]
05-02 14:54:52.097 27693 27693 D Player  : Thumbnail - updateEndScreenThumbnail() called with: currentThumbnail = [android.graphics.Bitmap@ab381c2], 600x337, scaled end screen height = 337.0, scaled end screen width = 600
05-02 14:54:52.098 27693 27693 I Choreographer: Skipped 67 frames!  The application may be doing too much work on its main thread.

Buffering

I did not yet compare the log with a "normal" log, but your log contains the word "buffer" very often: In the ~7000 lines, we got ~1800 lines with info about buffer stuff.

05-02 14:53:48.982   236  1629 W         : buffer descriptor with invalid usage bits 0x2002000

05-02 14:54:22.504  9831 21063 D CCodecBuffers: [c2.android.aac.decoder#182:1D-Output.Impl[N]] Client returned a buffer it does not own according to our record: 4

05-02 14:54:52.517 27693 27818 E BufferQueueProducer: [SurfaceTexture-1-27693-0] detachBuffer: slot 2 is not owned by the producer (state = FREE)

05-02 14:54:56.130 27693 27818 I CCodecConfig: query failed after returning 12 values (BAD_INDEX)

05-02 14:55:01.366 27693 27789 D PipelineWatcher: onInputBufferReleased: frameIndex not found (729); ignored

---

I do not have time to look into this, but my next steps would be:

1. Get a 0.21.1 debug version
   1. and check how often the animations are performed
   2. check if we have that many debug info related to buffering
2. Try the exoplayer update Update to ExoPlayer 2.12.3 #5457
3. Try to understand what these lines say:

05-02 14:54:45.318   299 13446 E qcreverb: 	[vendor/qcom/proprietary/mm-audio-noship/audio-effects/safx/android-adapter/qcreverb/qcreverb.c:531] Assertion fail: pConfig->inputCfg.format == AUDIO_FORMAT_PCM_16_BIT
05-02 14:54:48.820   299   379 E qcbassboost: 	[vendor/qcom/proprietary/mm-audio-noship/audio-effects/safx/android-adapter/qcbassboost/qcbassboost.c:395] Assertion fail: pConfig->inputCfg.format == AUDIO_FORMAT_PCM_16_BIT
05-02 14:54:48.831   299  5350 E qcvirt  : 	[vendor/qcom/proprietary/mm-audio-noship/audio-effects/safx/android-adapter/qcvirt/qcvirt.c:568] Assertion fail: pConfig->inputCfg.format == AUDIO_FORMAT_PCM_16_BIT
05-02 14:54:48.844   299   384 E qcreverb: 	[vendor/qcom/proprietary/mm-audio-noship/audio-effects/safx/android-adapter/qcreverb/qcreverb.c:531] Assertion fail: pConfig->inputCfg.format == AUDIO_FORMAT_PCM_16_BIT

4. Ask @Redirion for help

[Redirion]

it looks like the development of your Lineageos version for your device has advanced to a new version. 18.1.
Are you using the latest nightly of 17.1? If not you could try to upgrade to that. And if you already do, you could try 18.1
https://download.lineageos.org/bacon

But yes please also try the updated ExoPlayer to see if that makes a difference

[Redirion]

ah @TobiGr you have linked the wrong update.
The correct PR is #6206

@FrostKiwi please try that ExoPlayer version and please comment on my Lineageos question

[FrostKiwi]

ah @TobiGr you have linked the wrong update.
The correct PR is #6206

@FrostKiwi please try that ExoPlayer version and please comment on my Lineageos question

Tried the debug build provided by PR #6206
Same deal. choppy slideshow during 1080p60 playback. The Animations of the NewPipe app btw still play at full framerate and are smooth. (The slide animations, rotate animations... it's just the video that's choppy)

I am on the 11th April build of LineageOS 17.1 as provided by this ROM
Although LineageOS 18.1 has been out for a year for my device, it was still young and stability was wonky, so I stuck around with 17.1 till now. If it helps tracking down the issue, I can wipe and cleanflash my device to 18.1.

[Redirion]

MediaCodecInfo: NoSupport [codec.profileLevel, avc1.64002A, video/avc] [OMX.qcom.video.decoder.avc, video/avc] [bacon, A0001, OnePlus, 29]

VideoCapabilities: Unrecognized profile/level 0/3 for video/mpeg2
VideoCapabilities: Unrecognized profile 2130706433 for video/avc

Can you please try if it works better with webm?

[Redirion]

this is curious:
CacheDataSink: fragmentSize is below the minimum recommended value of 2097152. This may cause poor cache performance.