fvp icon indicating copy to clipboard operation
fvp copied to clipboard

FVP reports incorrect playback progress when buffering.

Open Predidit opened this issue 1 year ago • 24 comments

Describe the bug 在使用fvp实现的平台上,当播放部分视频流遇到卡顿时,fvp会报告视频播放进度为视频长度,这导致播放中断与未预期的向下一集的跳转。ffmpeg日志中的播放进度正常。

某些视频流在5分钟前会在fvp上稳定复现一次卡顿与进度报告错误,虽然从日志上看卡顿似乎是因为网络问题,但这一卡顿并不会在 media_kit 或是 vlc 中发生,在加载了fvp库,但并没有通过 fvp.registerWith 声明所在平台使用 fvp 插件实现的场合也不会发生。

Expected behavior 我在使用的fvp配置如下

      fvp.registerWith(options: {
        'platforms': ['windows', 'linux'],
      });

示例视频:https://groupvideo.photo.qq.com/1071_0bc3bmabaaaaqqailbmwantc6cyecafqaeca.f0.mp4?dis_k=c3cda9bbe9ba747153ce829f15e67844&dis_t=1722482050 此链接不支持带 referer 的请求,在网页播放需要打开新的空白标签页并粘贴地址。在不进行快进与跳转的情况下播放此视频流,在进度到达5分钟之前可以触发此问题。

Log

000001B14A1ACE70>202118 00:03:22.1/00:24:30 cache 0v 2.4s/132934KB 235KB/s |+2|<4ms update 41.3ms 24.2fps draw 1/4 +0ms
000001B14A1ACE70>202243 00:03:22.2/00:24:30 cache 0v 2.2s/132876KB 235KB/s |+2|<4ms update 41.4ms 24.1fps draw 2/4 +0ms
000001B14A1ACE70>202368 00:03:22.3/00:24:30 cache 0v 2.3s/132845KB 235KB/s |+1|<4ms update 41.7ms 23.7fps draw 2/4 +0ms
000001B14A1ACE70>202493 00:03:22.4/00:24:30 cache 0v 2.2s/132804KB 235KB/s |+2|<4ms update 41.3ms 24.2fps draw 2/4 +0ms
000001B14A1ACE70>202619 00:03:22.6/00:24:30 cache 0v 2.0s/132766KB 235KB/s |+1|<4ms update 41.3ms 24.0fps draw 2/3 +0ms
000001B14A1ACE70>202744 00:03:22.7/00:24:30 cache 0v 1.7s/132752KB 235KB/s |+3|<4ms update 41.4ms 24.2fps draw 1/2 +0ms
000001B14A1ACE70>202869 00:03:22.8/00:24:30 cache 0v 1.8s/132735KB 235KB/s |+1|<4ms update 42.0ms 23.7fps draw 1/2 +0ms
000001B14A1ACE70>202994 00:03:22.9/00:24:30 cache 0v 1.7s/132701KB 235KB/s |+2|<4ms update 41.9ms 24.2fps draw 2/4 +0ms
000001B14A1ACE70>203119 00:03:23.1/00:24:30 cache 0v 1.5s/132662KB 235KB/s |+1|<4ms update 42.1ms 23.8fps draw 1/4 +0ms
000001B14A1ACE70>203244 00:03:23.2/00:24:30 cache 0v 1.3s/132620KB 235KB/s |+3|<4ms update 41.7ms 24.3fps draw 2/8 +0ms
000001B14A1ACE70>203369 00:03:23.3/00:24:30 cache 0v 1.2s/132575KB 235KB/s |+1|<4ms update 42.0ms 23.8fps draw 2/8 +0ms
000001B14A1ACE70>203494 00:03:23.4/00:24:30 cache 0v 1.0s/132562KB 235KB/s |+3|<4ms update 42.1ms 24.0fps draw 2/8 +0ms
000001B14A1ACE70>203620 00:03:23.6/00:24:30 cache 0v 1.0s/132556KB 235KB/s |+3|<4ms update 41.5ms 24.0fps draw 2/8 +0ms
000001B14A1ACE70>203745 00:03:23.7/00:24:30 cache 0v 0.9s/132526KB 235KB/s |+3|<4ms update 41.5ms 24.0fps draw 2/8 +0ms
000001B14A1ACE70>203870 00:03:23.8/00:24:30 cache 0v 0.8s/132517KB 235KB/s |+2|<4ms update 41.5ms 24.2fps draw 2/8 +0ms
000001B14A1ACE70>203995 00:03:23.9/00:24:30 cache 0v 0.7s/132508KB 235KB/s |-2|<4ms update 41.7ms 24.0fps draw 2/4 +0ms
000001B14A1ACE70>204120 00:03:24.1/00:24:30 cache 0v 0.5s/132273KB 235KB/s |+2|<4ms update 41.8ms 23.9fps draw 2/4 +0ms
000001B14A1ACE70>204247 00:03:24.2/00:24:30 cache 0v 0.4s/132237KB 235KB/s |-3|<4ms update 41.9ms 23.8fps draw 2/3 +0ms
000001B14A1ACE70>204370 00:03:24.3/00:24:30 cache 0v 0.2s/132200KB 235KB/s |+3|<4ms update 41.9ms 24.2fps draw 2/3 +0ms
000001B14A1ACE70>204495 00:03:24.4/00:24:30 cache 0v 0.0s/132164KB 235KB/s |+0|<4ms update 41.8ms 23.8fps draw 2/4 +0ms
000001B14A1ACE70>204624 00:03:24.6/00:24:30 cache 0v 0.0s/132153KB 235KB/s |-6|>4ms update 42.1ms 23.7fps draw 2/4 +0ms
000001B14A1ACE70>204652 00:03:24.6/00:24:30 cache 0v 0.0s/132152KB 5KB/s
000001B14A1ACE70>204662 00:03:24.6/00:24:30 cache 0v 0.0s/127709KB 5KB/s |+3|<4ms update 559.3ms 24.0fps draw 2/4 +0ms
000001B14A1ACE70>204871 00:03:24.8/00:24:30 cache 0v 0.0s/127709KB 5KB/s |+2|<4ms update 567.1ms 1.9fps draw 5/49 +0ms
flutter: ┌───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
flutter: │ #0   KazumiLogger.log (package:kazumi/utils/logger.dart:33:11)
flutter: │ #1   _VideoPageController.changeEpisode (package:kazumi/pages/video/video_controller.dart:61:20)
flutter: ├┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄
flutter: │ 💡 跳转到第2话
flutter: └───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────

Predidit avatar Aug 01 '24 03:08 Predidit

ffmpeg 下载数据出错了,应该是超过一定时间没流量会让当前回话失效

avio timeout detected: 24807ms elapsed
avio timeout detected: 24807ms elapsed
avio timeout detected: 24807ms elapsed
[FFmpeg:https] Stream ends prematurely at 54525952, should be 421567516
[FFmpeg:mov,mp4,m4a,3gp,3g2,mj2] Packet corrupt (stream = 0, dts = 4477473).
[FFmpeg:h264] Invalid NAL unit size (49083 > 13261).
[FFmpeg:h264] missing picture in access unit with size 13265
[FFmpeg:mov,mp4,m4a,3gp,3g2,mj2] stream 1, offset 0x3408bee: partial file
default 0x157e0fa60 FrameReader::update MediaStatus 0X114=>0X154
read packet error. FrameReader@0x157e0fa60 sending Packet::End to all packet queues. PacketIO@0x157e152c0 ->url: https://groupvideo.photo.qq.com/1071_0bc3bmabaaaaqqailbmwantc6cyecafqaeca.f0.mp4?dis_k=c3cda9bbe9ba747153ce829f15e67844&dis_t=1722482050
0x157e0fa60 #video stream#0 end semaphore acquire
flutter: fvp.FINE: 12:57:52.996: 840463083 player5769325920 onMediaStatus: MediaStatus(+loaded+prepared+buffering) => MediaStatus(+loaded+prepared+buffering+end)
***buffering progress 100%***
default 0x157e0fa60 FrameReader::update MediaStatus 0X154=>0X164
null output image buffer @186.644791: 0x0, status: -12909
 VT decode error: -12909

我这边默认的缓冲就几秒,满了就停止下载,我看mpv是一直在下载,如果也设成很大的值测了下没问题

registerWith(options: {
  'player': {
      'buffer': '2000+600000'     // if data is not enough, cache 2s, max is 600s
  }
});

另外,为了防止seek到已下载过的时间段重复下载(目前播放hls好像偶尔有点bug),可以加上

registerWith(options: {
    'player': {
      'demux.buffer.ranges': '8', // cache 8 time ranges. can be other integer value as string
    });

wang-bin avatar Aug 01 '24 05:08 wang-bin

这个方法好暴力,我刚刚测试了一下5分钟之前不会卡了,但是我怀疑这会在更晚的时候发生,我在测试一个较长的视频,稍后给您回复。

Predidit avatar Aug 01 '24 06:08 Predidit

这没有解决问题,错误会发生在更靠后的位置,在应用如上配置的情况下,错误会发生在约 13 分钟的位置。

在 media_kit 中我尝试减少缓存到 5 秒,media_kit 仍然在正常工作。

Predidit avatar Aug 01 '24 06:08 Predidit

mpv默认缓冲3600000s,所以没出现错误,你也改成这么大估计也没问题。mpv改成4s缓冲 mpv --cache-secs=4 -v "$URL" 也有同样的错误,不过它默认会重连就不影响播放

[cplayer] Still buffering (buffer went from 49% -> 56%) [0.566968s].                             
[cplayer] Still buffering (buffer went from 56% -> 65%) [0.659848s].                             
[cplayer] Still buffering (buffer went from 65% -> 70%) [0.706288s].                             
[cplayer] Still buffering (buffer went from 70% -> 82%) [0.822387s].                             
[cplayer] Still buffering (buffer went from 82% -> 98%) [0.984927s].                             
[cplayer] End buffering (waited 2.072586 secs) [1.077807s].                                      
[cplayer] Enter buffering (buffer went from 100% -> 3%) [0.034822s].                             
[ao/coreaudio] Stopping audio unit due to idle timeout                                         
[ffmpeg] https: Stream ends prematurely at 108003328, should be 421567516                      
[ffmpeg] https: Will reconnect at 108003328 in 0 second(s), error=Input/output error.          
[cplayer] Still buffering (buffer went from 3% -> 4%) [0.041708s].                             
[cplayer] Still buffering (buffer went from 4% -> 17%) [0.174142s].  

fvp重连可以这么设

registerWith(options: {
    'player': {
      'avio.reconnect': '1',
      'avio.reconnect_delay_max': '7',
    });

wang-bin avatar Aug 01 '24 06:08 wang-bin

在 fvp 设定重连解决了视频无法继续播放的问题,但是在之前视频播放损坏的位置,现在会出现卡顿以进行网络重连和资源加载,默认配置下,这会约每3分钟发生一次。

对于这种情况,有解决方法吗。

此外,我看到fvp似乎支持的最大缓存长度为 600000

Predidit avatar Aug 01 '24 06:08 Predidit

这种情况应该是服务端做了限制,之前也碰到过,播放端能做的就是重连、增大缓冲长度,长度没限制(可以用mpv的值)。demux.buffer.ranges也可以开启。

wang-bin avatar Aug 01 '24 06:08 wang-bin

我看到 fvp 似乎在当前缓存耗尽后才会尝试重连,但mpv似乎会在连接失败时立即重连,这样就不会出现卡顿。

这是 fvp预期的行为吗。

Predidit avatar Aug 01 '24 07:08 Predidit

可能随机的,我贴的日志mpv也是缓冲过程中重连,先是不停地缓冲卡顿,后来变成重连了。

wang-bin avatar Aug 01 '24 07:08 wang-bin

感谢您的解答,我的问题得到了解决。

不过类似的视频流似乎有不少,重连为什么不是 fvp 的一个默认行为呢。

Predidit avatar Aug 01 '24 07:08 Predidit

我也没怎么碰到过,没测过的参数并且我也不确定是什么效果的就没开,重连的话我今天加一下

wang-bin avatar Aug 01 '24 07:08 wang-bin

依然是上面的测试视频,在使用10分钟缓存的情况下,在20分钟前会发生中断。

有超过一半的概率无法重连成功,昨天我只进行了一次测试,所以并没有发现这种情况。

使用不限制的视频缓存区的话,内存开销有些过高了。

Predidit avatar Aug 02 '24 03:08 Predidit

avio.reconnect_delay_max 字段是每次重连的延时吗

Predidit avatar Aug 02 '24 03:08 Predidit

重连失败的日志是怎么样的

wang-bin avatar Aug 02 '24 03:08 wang-bin

flutter: mdk.FINE: 11:45:36.678: avio timeout detected: 44629ms elapsed
flutter: mdk.FINE: 11:45:36.680: avio timeout detected: 44630ms elapsed
flutter: mdk.FINE: 11:45:36.681: avio timeout detected: 44631ms elapsed
flutter: mdk.FINE: 11:45:36.682: avio timeout detected: 44633ms elapsed

这些日志将会一直出现,直到缓存耗尽位置,视频卡住。

Predidit avatar Aug 02 '24 03:08 Predidit

想看日志里含ffmpeg的那些行

wang-bin avatar Aug 02 '24 04:08 wang-bin

上一条回复没有将日志转储到文件,导致一些关键信息的丢失,所以我在这条回复里更新。

这个问题只会在经过一次 seek 到已缓存视频片段后发生,日志如下,这次尝试为从开始播放 3 秒后跳转到已缓存的 3分钟处

mdk.FINE: 11:54:13.692: >>>>>>>>1st audio frame (after seek) rendered: 1, ao: 15, a: 0, delta: 15 +0.023220 
mdk.FINE: 11:54:13.694: audio stream#1 AOT frame is sent 
mdk.FINE: 11:54:57.940: default 0mdk.FINE: 11:54:13.692: >>>>>>>>1st audio frame (after seek) rendered: 1, ao: 15, a: 0, delta: 15 +0.023220 
mdk.FINE: 11:54:13.694: audio stream#1 AOT frame is sent 
mdk.FINE: 11:54:57.940: default 0000017AB3A39890 FrameReader::update MediaStatus 0X124=>0X1A4 
ed+buffered) => MediaStatus(+loaded+prepared+buffered+seeking) 
mdk.FINE: 11:54:57.954: seek_drop_non_video_: 171577 ms, seek_wait_frame_: 0... 
171.595465, 321.619465] s 
mdk.FINE: 11:54:57.961: audio stream#1 sending 1 invalid AOT frame @171.595464s. seeking: 0 
p frames until seek target 171.5770s... 
mdk.INFO: 11:54:57.961: 0000017AAB6CAE70 seek end audio frame @171.595464 seek_pos_: 171581, sync_ao_ 1 
mdk.FINE: 11:54:57.970: video stream#0 is seeking #1... got flush pkt. flush decoder and  drop frames until seek target 171.5770s... 
mdk.FINE: 11:54:57.992: audio stream#1 AOT frame is sent 
k) rendered: 1, ao: 171610, a: 171595, delta: 15 +0.023220 
fvp.FINE: 11:54:58.062: 313798813 player1626335815760 onMediaStatus: MediaStatus(+lomdk.FINE: 11:54:58.063: default FrameReader 0000017AB3A39890 callbacks 0, seeking 0 flag 0, seekComplete#1 @171588 
mdk.FINE: 11:54:58.092: video stream#0 AOT frame is sent 
mdk.FINE: 11:56:18.425: avio timeout detected: 10001ms elapsed 
mdk.FINE: 11:56:18.426: avio timeout detected: 10002ms elapsed 
mdk.FINE: 11:56:18.428: avio timeout detected: 10004ms elapsed 
mdk.FINE: 11:56:18.429: avio timeout detected: 10005ms elapsed 
mdk.FINE: 11:56:18.431: avio timeout detected: 10007ms elapsed 
mdk.FINE: 11:56:18.432: avio timeout detected: 10008ms elapsed 
mdk.FINE: 11:56:18.434: avio timeout detected: 10010ms elapsed 
mdk.FINE: 11:56:18.435: avio timeout detected: 10011ms elapsed 
mdk.FINE: 11:56:18.437: avio timeout detected: 10013ms elapsed 
mdk.FINE: 11:56:18.438: avio timeout detected: 10014ms elapsed 
mdk.FINE: 11:56:18.439: avio timeout detected: 10015ms elapsed 
mdk.FINE: 11:56:18.440: avio timeout detected: 10016ms elapsed 
mdk.FINE: 11:56:18.442: avio timeout detected: 10018ms elapsed 

后续相同的日志会持续至视频缓存耗尽。

我的 fvp 配置如下

      fvp.registerWith(options: {
        'platforms': ['windows', 'linux'],
        'player': {
          'avio.reconnect': '1',
          'avio.reconnect_delay_max': '7',
          'buffer': '2000+150000',
          'demux.buffer.ranges': '8',
        }
      });

Predidit avatar Aug 02 '24 04:08 Predidit

我应该如何捕获 ffmpeg 日志。

我尝试了

'global': {'logLevel': 'All', 'ffmpeg.log': 'verbose'}

但只能得到类似于

000002933061A100>791583 00:13:11.5/00:23:40 cache 0v 1.5s/110305KB 142KB/s |+0|<4ms update 41.6ms 23.9fps draw 1/2 +0ms

的日志

Predidit avatar Aug 02 '24 04:08 Predidit

日志你还是得发完整的。默认会把ffmpeg的info日志打印出来。重连的话会有Will reconnect at日志。重连失败会sleep 1s、3s、9s、1+2*prev_delay 再次重连,要sleep的值大于reconnect_delay_max就不再重连认为出错了。你看看mpv什么行为。

wang-bin avatar Aug 03 '24 02:08 wang-bin

kazumi_debug_logs.log

我尝试重新转储了日志,但是没有看到 will reconnect at 之类的日志,这是否是默认情况下,windows平台未使用 ffmpeg 解码器,而使用 MFP 的原因。

Predidit avatar Aug 03 '24 03:08 Predidit

和解码没关心,这个是下载数据问题。昨天的日志里有看到重连吗?

wang-bin avatar Aug 03 '24 04:08 wang-bin

没有,所以我一直在怀疑我的日志获取方式不正确。

Predidit avatar Aug 03 '24 04:08 Predidit

日志没问题。你给个链接我晚点测下

wang-bin avatar Aug 03 '24 04:08 wang-bin

https://sf16-sg-default.akamaized.net/obj/tos-alisg-v-0000/oIBRNNnZicbbKCjsTZpIQekDj8U8QDjWBogApe

前面测试的链接好像失效了,这里补一个新的。

Predidit avatar Aug 03 '24 04:08 Predidit

新的链接没法复现

wang-bin avatar Aug 08 '24 04:08 wang-bin

我遇到了一个更加奇怪的链接

https://yun.366day.site/mp4hls/dmhls/dianwanka1.m3u8

这个链接不能被 VLC 播放,但是可以被 flutter 官方的 video_player 实现播放,当启用 fvp 实现后,链接同样不能播放。

我不知道为什么会这样,让fvp的表现与 video_player 一致是可能的吗

Predidit avatar Aug 19 '24 06:08 Predidit

这似乎是一个不那么标准的视频流。

这个视频流似乎在把TS片段以图片的方式托管在百度的CDN上,来滥用百度的图片托管服务。

但是这个流可以被 mpv 和 video+player 播放,我们可以播放这种视频流吗。

Predidit avatar Aug 20 '24 03:08 Predidit

似乎这是一个 TLS 问题,我得到

gnutls error: Certificate verification failure: The certificate is NOT trusted. The certificate issuer is unknown.

我不知道这是不是因为 index.m3u8 和 ts 片段不来自同一个域名,我们有办法可以跳过这个错误吗。

Predidit avatar Aug 20 '24 04:08 Predidit

vlc不能播,mpv窗口很小没画面,播放进度一直不动,然后退出了。切片是gif,这个不符合标准吧,没必要支持。

gnutls error: Certificate verification failure: The certificate is NOT trusted. The certificate issuer is unknown.

我不知道这是不是因为 index.m3u8 和 ts 片段不来自同一个域名,我们有办法可以跳过这个错误吗

不清楚,这是什么程序跑的?linux上的?

wang-bin avatar Aug 20 '24 05:08 wang-bin

这个被 video_player 官方实现所支持,我们可以实现这个功能吗。

这样作为 video_player 的插件,行为和原实现保持一致似乎是有必要的?

Predidit avatar Aug 20 '24 05:08 Predidit

切片只是 content_type 是 gif 实际上似乎不是?这似乎是为了嫖百度的cdn。

Predidit avatar Aug 20 '24 05:08 Predidit