I need the entire log line. What does the rest say in parenthesis?
Each android tv has different buffer requirements for seamless audio playback.
03-31 23:03:05.800 17789 17837 V mpv : [ao/audiotrack] Setting bufferSize = 28800 (driver=16416, min=19200, max=28800)
03-31 23:03:05.800 17789 17837 V mpv : [ao/audiotrack] device buffer: 14400 samples.
03-31 23:03:05.800 17789 17837 V mpv : [ao/audiotrack] using soft-buffer of 14400 samples.
03-31 23:03:05.800 17789 17837 I mpv : [cplayer] AO: [audiotrack] 48000Hz stereo 2ch s16
03-31 23:03:05.800 17789 17837 V mpv : [cplayer] AO: Description: Android AudioTrack audio outputThank you. I will upload a new beta tomorrow with a fix for this problem.
Thank you. For the heck of it I went to an OTA channel and enabled surround sound. I got a totally different line.
04-01 00:57:45.676 17789 17837 V mpv : [ao/audiotrack] Setting bufferSize = 4800 (driver=4104, min=0, max=0)
That's normal for Dolby stream since it does passthrough
1 Like
If you see buffering pauses w/ Dolby please paste the logs for the buffering events similar to before.
If I have Surround enabled and watch a OTA 480i SD channel it's bad. I can pause it for a few seconds and then it plays fine.
Do you want that?
Edit; just in case
04-01 01:07:38.769 17789 17789 V PlayerActivity: onStart
04-01 01:07:38.770 17789 17789 V PlayerActivity: onResume
04-01 01:07:38.787 17789 17789 V mpvstats: AV: 417.377 A-V: 0.000 Dropped: 0 Cache: 0.000s + 0KB
04-01 01:07:38.824 17789 17855 D mali_winsys: EGLint new_window_surface(egl_winsys_display *, void *, EGLSurface, EGLConfig, egl_winsys_surface **, EGLBoolean) returns 0x3000
04-01 01:07:38.886 17789 17789 V VideoPlayer: surfaceCreated: video
04-01 01:07:38.887 17789 17837 D mpv : [cplayer] Setting option 'wid' = 12658 (flags = 64) -> 0
04-01 01:07:38.888 17789 17837 D mpv : [cplayer] Setting option 'android-surface-size' = "1920x1080" (flags = 64) -> 0
04-01 01:07:38.904 17789 17789 V VideoPlayer: surfaceCreated: subtitles
04-01 01:07:38.905 17789 17837 D mpv : [cplayer] Setting option 'mediacodec-embed-osd-surface' = 12650 (flags = 64) -> 0
04-01 01:07:38.907 17789 17837 D mpv : [cplayer] Run command: loadfile, flags=64, args=[hdhr://6.4, replace, start=none,pause=no,sid=no]
04-01 01:07:38.908 17789 17837 V mpv : event: start-file
04-01 01:07:38.908 17789 17837 D mpv : [cplayer] Setting option 'start' = 'none' (flags = 80)
04-01 01:07:38.908 17789 17837 D mpv : [cplayer] Setting option 'pause' = 'no' (flags = 80)
04-01 01:07:38.908 17789 17837 D mpv : [cplayer] Setting option 'sid' = 'no' (flags = 80)
04-01 01:07:38.908 17789 17837 I mpv : [cplayer] Playing: hdhr://6.4
04-01 01:07:38.908 17789 17837 V mpv : [stream_callback] Opening hdhr://6.4
04-01 01:07:38.910 17789 26673 V Streamer: ch6.4 has 2 possible sources
04-01 01:07:38.910 17789 26673 V Streamer: trying 10481E46: http://192.168.5.45:5004/auto/v6.4?transcode=none
04-01 01:07:38.914 17789 26673 V Streamer: http socket receiveBufferSize = 1048576
04-01 01:07:38.948 17789 17789 V PlayerActivity: state STOPPED -> LOADING
04-01 01:07:39.128 17789 26673 V Streamer: started with 2333829932 byte buffer in /data/user/0/com.getchannels.dvr.app.beta/cache/channels-streamer.ts
04-01 01:07:39.128 17789 26673 V Streamer: seek(0) = 0 -> 0
04-01 01:07:39.129 17789 17837 D mpv : [stream_callback] Stream opened successfully.
04-01 01:07:39.129 17789 17837 V mpv : [demux] Trying demuxers for level=force.
04-01 01:07:39.129 17789 17837 D mpv : [demux] Trying demuxer: lavf (force-level: force)
04-01 01:07:39.196 17789 17855 W libEGL : EGLNativeWindowType 0xb2dc1808 disconnect failed
04-01 01:07:39.225 17789 17837 V mpv : [lavf] Found 'mpegts' at score=50 size=2048.
04-01 01:07:39.226 17789 17837 V mpv : [lavf] avformat_open_input() finished after 2632 bytes.
04-01 01:07:39.227 17789 17837 D mpv : [ffmpeg/demuxer] mpegts: Before avformat_find_stream_info() pos: 0 bytes read:2632 seeks:0 nb_streams:2
04-01 01:07:40.042 17789 17837 V mpv : [ffmpeg/demuxer] mpegts: Skipping duration calculation in estimate_timings_from_pts
04-01 01:07:40.042 17789 26673 V Streamer: seek(0) = 421120 -> 0
04-01 01:07:40.043 17789 17837 D mpv : [ffmpeg/demuxer] mpegts: After avformat_find_stream_info() pos: 0 bytes read:421120 seeks:1 frames:42
04-01 01:07:40.043 17789 17837 V mpv : [lavf] avformat_find_stream_info() finished after 0 bytes.
04-01 01:07:40.043 17789 17837 V mpv : [demux] Detected file format: mpegts (libavformat)
04-01 01:07:40.043 17789 17837 V mpv : [cplayer] Opening done: hdhr://6.4
04-01 01:07:40.044 17789 17837 V mpv : event: tracks-changed
04-01 01:07:40.044 17789 17837 V mpv : event: tracks-changed
04-01 01:07:40.044 17789 17837 V mpv : event: metadata-update
04-01 01:07:40.044 17789 17837 D mpv : [global] config path: 'sub' -/-> '/data/user/0/com.getchannels.dvr.app.beta/files/mpv/sub'
04-01 01:07:40.044 17789 17837 V mpv : [lavf] select track 0
04-01 01:07:40.044 17789 17837 V mpv : [lavf] select track 1
04-01 01:07:40.044 17789 17837 I mpv : [cplayer] (+) Video --vid=1 (mpeg2video 704x480 29.970fps)
04-01 01:07:40.044 17789 17837 I mpv : [cplayer] (+) Audio --aid=1 --alang=eng (ac3 2ch 48000Hz 192kbps)
04-01 01:07:40.047 17789 26677 D mali_winsys: EGLint new_window_surface(egl_winsys_display *, void *, EGLSurface, EGLConfig, egl_winsys_surface **, EGLBoolean) returns 0x3000
04-01 01:07:40.062 17789 17837 V mpv : [vd] Container reported FPS: 29.970030
04-01 01:07:40.062 17789 17837 V mpv : [vd] Codec list:
04-01 01:07:40.062 17789 17837 V mpv : [vd] mpeg2video - MPEG-2 video
04-01 01:07:40.062 17789 17837 V mpv : [vd] mpegvideo (mpeg2video) - MPEG-1 video
04-01 01:07:40.062 17789 17837 V mpv : [vd] mpeg2_mediacodec (mpeg2video) - MPEG-2 Android MediaCodec decoder
04-01 01:07:40.063 17789 17837 V mpv : [vd] Opening decoder mpeg2video
04-01 01:07:40.063 17789 17837 V mpv : [vd] Looking at hwdec mpeg2_mediacodec-mediacodec-copy...
04-01 01:07:40.063 17789 17837 V mpv : [vd] Trying hardware decoding via mpeg2_mediacodec-mediacodec-copy.
04-01 01:07:40.063 17789 17837 V mpv : [vd] Using underlying hw-decoder 'mpeg2_mediacodec'
04-01 01:07:40.063 17789 17837 V mpv : [vd] Pixel formats supported by decoder: mediacodec
04-01 01:07:40.063 17789 17837 V mpv : [vd] Codec profile: Main (0x4)
04-01 01:07:40.063 17789 17837 V mpv : [vd] Requesting pixfmt 'mediacodec' from decoder.
04-01 01:07:40.063 17789 17837 V mpv : [ffmpeg/video] mpeg2_mediacodec: Using surface 0x0
04-01 01:07:40.063 17789 17837 W mpv : [ffmpeg/video] mpeg2_mediacodec: Unsupported or unknown profile
04-01 01:07:40.069 17789 17836 D MtkACodecPlugin: MtkACodecPlugin createAPlugin
04-01 01:07:40.070 17789 26679 D MtkACodecPlugin: OMX.MTK.VIDEO.DECODER.MPEG2 needRmClient (680)
04-01 01:07:40.070 17789 26679 D MtkACodecPlugin: OMX.MTK.VIDEO.DECODER.MPEG2 mNeedVdpImgrz (686)
04-01 01:07:40.073 17789 26679 I OMXClient: IOmx service obtained
04-01 01:07:40.099 17789 26678 D MtkMediaCodecPlugin: No surfaceTextureClient, [OMX.MTK.VIDEO.DECODER.MPEG2] set mOutputPath = 1024 L(158)
04-01 01:07:40.112 17789 26679 I ACodec : codec does not support config priority (err -1010)
04-01 01:07:40.160 17789 17837 E mpv : [ffmpeg/video] mpeg2_mediacodec: Output color format 0x7f000103 (value=2130706691) is not supported
04-01 01:07:40.160 17789 17837 E mpv : [ffmpeg/video] mpeg2_mediacodec: Output color format is not supported
04-01 01:07:40.160 17789 17837 E mpv : [ffmpeg/video] mpeg2_mediacodec: Failed to configure context
04-01 01:07:40.160 17789 17837 E mpv : [ffmpeg/video] mpeg2_mediacodec: MediaCodec 0x918a1000 failed to start
04-01 01:07:40.201 17789 17836 D MediaCodec: mState = 0, mHaveKick = 0, L(711)
04-01 01:07:40.202 17789 17836 D MtkACodecPlugin: MtkACodecPlugin destoryAPlugin
04-01 01:07:40.203 17789 17837 E mpv : [vd] Could not open codec.
04-01 01:07:40.204 17789 17837 V mpv : [vd] Falling back to software decoding.
04-01 01:07:40.204 17789 17837 V mpv : event: audio-reconfig
04-01 01:07:40.204 17789 17837 V mpv : [vd] Detected 4 logical cores.
04-01 01:07:40.204 17789 17837 V mpv : [vd] Requesting 5 threads for decoding.
04-01 01:07:40.204 17789 17837 V mpv : [vd] Selected codec: mpeg2video (MPEG-2 video)
04-01 01:07:40.205 17789 17837 V mpv : [vf] User filter list:
04-01 01:07:40.205 17789 17837 V mpv : [vf] (empty)
04-01 01:07:40.206 17789 17837 V mpv : event: audio-reconfig
04-01 01:07:40.206 17789 17837 V mpv : event: file-loaded
04-01 01:07:40.206 17789 17837 V mpv : [ad] Codec list:
04-01 01:07:40.206 17789 17837 V mpv : [ad] raw_ac3 (ac3) - raw audio pass-through decoder
04-01 01:07:40.206 17789 17789 V PlayerActivity: state LOADING -> LOADED
04-01 01:07:40.206 17789 17837 V mpv : [ad] Opening decoder raw_ac3
04-01 01:07:40.206 17789 17837 V mpv : [ad] Selected codec: raw_ac3 (raw audio pass-through decoder)
04-01 01:07:40.206 17789 17837 V mpv : [af] User filter list:
04-01 01:07:40.206 17789 17837 V mpv : [af] (empty)
04-01 01:07:40.206 17789 17837 V mpv : [cplayer] Starting playback...
04-01 01:07:40.211 17789 17837 V mpv : property: track-list has 2 entries
04-01 01:07:40.226 17789 17836 W AudioTrack: Use of stream types is deprecated for operations other than volume control
04-01 01:07:40.226 17789 17836 W AudioTrack: See the documentation of AudioTrack() for what to use instead with android.media.AudioAttributes to qualify your playback use case
04-01 01:07:40.256 17789 17837 V mpv : event: audio-reconfig
04-01 01:07:40.256 17789 17837 V mpv : event: video-reconfig
04-01 01:07:40.259 17789 17837 V mpv : event: unpause
04-01 01:07:40.259 17789 17837 V mpv : event: tracks-changed
04-01 01:07:40.259 17789 17837 V mpv : event: video-reconfig
04-01 01:07:40.260 17789 17837 V mpv : [ad] In: channels=2 samplerate=48000 bitrate=192000
04-01 01:07:40.260 17789 17837 V mpv : property: buffering = true
04-01 01:07:40.260 17789 17789 V PlayerActivity: state LOADED -> BUFFERING
04-01 01:07:40.262 17789 17837 V mpv : property: track-list has 3 entries
04-01 01:07:40.262 17789 17837 V mpv : [af] [in] 48000Hz stereo 2ch raw-ac3 192kbps
04-01 01:07:40.262 17789 17837 V mpv : [af] [userspeed] 48000Hz stereo 2ch raw-ac3 192kbps
04-01 01:07:40.262 17789 17837 V mpv : [af] [userspeed] (disabled)
04-01 01:07:40.262 17789 17837 V mpv : [af] [convert] 48000Hz stereo 2ch raw-ac3 192kbps
04-01 01:07:40.262 17789 17837 V mpv : [ao] Trying audio driver 'audiotrack'
04-01 01:07:40.262 17789 17837 V mpv : [ao/audiotrack] requested format: 48000 Hz, stereo channels, raw-ac3
04-01 01:07:40.262 17789 17837 V mpv : [ao/audiotrack] Setting bufferSize = 2400 (driver=4104, min=0, max=0)
04-01 01:07:40.262 17789 17837 V mpv : [ao/audiotrack] device buffer: 2400 samples.
04-01 01:07:40.263 17789 17837 V mpv : [ao/audiotrack] using soft-buffer of 5376 samples.
04-01 01:07:40.263 17789 17837 I mpv : [cplayer] AO: [audiotrack] 48000Hz stereo 2ch raw-ac3 192kbps
04-01 01:07:40.263 17789 17837 V mpv : [cplayer] AO: Description: Android AudioTrack audio output
04-01 01:07:40.263 17789 17837 V mpv : [af] [convert] (disabled)
04-01 01:07:40.263 17789 17837 V mpv : [af] [out] 48000Hz stereo 2ch raw-ac3 192kbps
04-01 01:07:40.263 17789 17837 D mpv : [vd] DR parameter change to 704x480 yuv420p align=16
04-01 01:07:40.263 17789 17837 D mpv : [vd] Allocating new DR image...
04-01 01:07:40.263 17789 17837 D mpv : [vd] ...failed..
04-01 01:07:40.263 17789 17837 V mpv : [vd] DR failed - disabling.
04-01 01:07:40.263 17789 17837 V mpv : [vd] Using software decoding.
04-01 01:07:40.263 17789 17837 V mpv : [vd] Decoder format: 704x480 [40:33] yuv420p auto/auto/auto/limited/auto CL=mpeg2/4/h264 (auto 0.000000/0.000000/0.000000)
04-01 01:07:40.263 17789 17837 V mpv : [vf] [in] 704x480 [40:33] yuv420p bt.601/bt.601-525/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
04-01 01:07:40.263 17789 17837 V mpv : [vf] [userdeint] 704x480 [40:33] yuv420p bt.601/bt.601-525/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
04-01 01:07:40.263 17789 17837 V mpv : [vf] [userdeint] (disabled)
04-01 01:07:40.263 17789 17837 V mpv : [vf] [autorotate] 704x480 [40:33] yuv420p bt.601/bt.601-525/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
04-01 01:07:40.263 17789 17837 V mpv : [vf] [autorotate] (disabled)
04-01 01:07:40.263 17789 17837 V mpv : [vf] [convert] 704x480 [40:33] yuv420p bt.601/bt.601-525/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
04-01 01:07:40.264 17789 17837 V mpv : [vf] [convert] (disabled)
04-01 01:07:40.264 17789 17837 V mpv : [vf] [out] 704x480 [40:33] yuv420p bt.601/bt.601-525/bt.1886/limited/display SP=1.000000 CL=mpeg2/4/h264
04-01 01:07:40.264 17789 17837 I mpv : [cplayer] VO: [gpu] 704x480 => 853x480 yuv420p
04-01 01:07:40.264 17789 17837 V mpv : [cplayer] VO: Description: Shader-based GPU Renderer
04-01 01:07:40.264 17789 17837 V mpv : [cplayer] first video frame after restart shown
04-01 01:07:40.264 17789 17837 I mpv : [cplayer] Track switched:
04-01 01:07:40.264 17789 17837 I mpv : [cplayer] (+) Video --vid=1 (mpeg2video 704x480 29.970fps)
04-01 01:07:40.264 17789 17837 I mpv : [cplayer] (+) Audio --aid=1 --alang=eng (ac3 2ch 48000Hz 192kbps)
04-01 01:07:40.264 17789 17837 V mpv : [cplayer] Set property: aid=1 -> 1
04-01 01:07:40.264 17789 17837 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 13%) [0.133467s].
04-01 01:07:40.264 17789 17837 I mpv : [cplayer] (+) Video --vid=1 (mpeg2video 704x480 29.970fps)
04-01 01:07:40.264 17789 17837 I mpv : [cplayer] (+) Audio --aid=1 --alang=eng (ac3 2ch 48000Hz 192kbps)
04-01 01:07:40.264 17789 17837 I mpv : [cplayer] Subs --sid=1 (*) (eia_608)
04-01 01:07:40.264 17789 17837 D mpv : [cplayer] Setting option 'cache-pause-initial' = "0.3" (flags = 64) -> 0
04-01 01:07:40.264 17789 17837 D mpv : [cplayer] Setting option 'cache-pause-wait' = "0.25" (flags = 64) -> 0
04-01 01:07:40.264 17789 17837 D mpv : [cplayer] Setting option 'cache-pause-fill' = "0.75" (flags = 64) -> 0
04-01 01:07:40.473 17789 17837 V mpv : event: playback-restart
04-01 01:07:40.473 17789 17837 V mpv : [cplayer] starting audio playback
04-01 01:07:40.474 17789 17837 V mpv : [cplayer] playback restart complete @ 0.859767
04-01 01:07:40.914 17789 17837 V mpv : event: unpause
04-01 01:07:40.914 17789 17837 V mpv : [cplayer] End buffering (waited 0.654588 secs) [0.320000s].
04-01 01:07:40.923 17789 17837 V mpv : property: buffering = false
04-01 01:07:40.924 17789 17789 V PlayerActivity: state BUFFERING -> PLAYING
04-01 01:07:41.002 17789 17837 V mpv : event: unpause
04-01 01:07:41.002 17789 17837 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 0%) [0.000000s].
04-01 01:07:41.002 17789 17837 V mpv : property: buffering = true
04-01 01:07:41.003 17789 17789 V PlayerActivity: state PLAYING -> BUFFERING
04-01 01:07:41.004 17789 17789 V mpvstats: demuxer-cache-state: {seekable-ranges=[], cache-end=1.5360000000000582, reader-pts=1.5360000000000582, cache-duration=0.0, eof=false, underrun=true, idle=false, total-bytes=891584, fw-bytes=377600, debug-low-level-seeks=0, debug-ts-last=24551.9123, ts-per-stream=[{type=video, duration=0.867533333330357, reader=24551.04476666667, end=24551.9123}, {type=audio, duration=0.0, reader=24551.6209, end=24551.6209}]}
04-01 01:07:41.116 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 0% -> 4%) [0.032000s].
04-01 01:07:41.116 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 4% -> 0%) [0.000000s].
04-01 01:07:41.116 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 0% -> 17%) [0.128000s].
04-01 01:07:41.416 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 17% -> 38%) [0.288000s].
04-01 01:07:41.460 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 38% -> 59%) [0.448000s].
04-01 01:07:41.667 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 59% -> 81%) [0.608000s].
04-01 01:07:41.790 17789 17789 V mpvstats: AV: 0.927 A-V: -0.009 Dropped: 0 Cache: 0.768s + 0KB
04-01 01:07:41.922 17789 17837 V mpv : event: unpause
04-01 01:07:41.922 17789 17837 V mpv : [cplayer] End buffering (waited 0.951755 secs) [0.768000s].
04-01 01:07:41.928 17789 17837 V mpv : property: buffering = false
04-01 01:07:41.929 17789 17789 V PlayerActivity: state BUFFERING -> PLAYING
04-01 01:07:42.138 17789 26691 W AudioTrack: releaseBuffer() track 0xb2ceed00 disabled due to previous underrun, restarting
04-01 01:07:42.774 17789 17789 V mpvstats: AV: 1.761 A-V: -0.001 Dropped: 12 Cache: 0.800s + 0KB
04-01 01:07:42.847 17789 26691 W AudioTrack: releaseBuffer() track 0xb2ceed00 disabled due to previous underrun, restarting
04-01 01:07:42.879 17789 17837 W mpv : [cplayer]
04-01 01:07:42.879 17789 17837 W mpv : [cplayer] Audio/Video desynchronisation detected! Possible reasons include too slow
04-01 01:07:42.880 17789 17837 W mpv : [cplayer] hardware, temporary CPU spikes, broken drivers, and broken files. Audio
04-01 01:07:42.880 17789 17837 W mpv : [cplayer] position will not match to the video (see A-V status field).
04-01 01:07:42.880 17789 17837 W mpv : [cplayer]
04-01 01:07:43.050 17789 26691 W AudioTrack: releaseBuffer() track 0xb2ceed00 disabled due to previous underrun, restarting
04-01 01:07:43.193 17789 17837 V mpv : event: unpause
04-01 01:07:43.193 17789 17837 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 0%) [0.000000s].
04-01 01:07:43.195 17789 17837 V mpv : property: buffering = true
04-01 01:07:43.195 17789 17789 V PlayerActivity: state PLAYING -> BUFFERING
04-01 01:07:43.197 17789 17789 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=0.0, end=3.583999999998923}], cache-end=3.6159999999981665, reader-pts=3.6159999999981665, cache-duration=0.0, eof=false, underrun=true, idle=false, total-bytes=1978304, fw-bytes=321216, debug-low-level-seeks=0, debug-ts-last=24553.280333333336, ts-per-stream=[{type=video, duration=0.7674333333307004, reader=24553.280333333336, end=24554.047766666667}, {type=audio, duration=0.0, reader=24553.7009, end=24553.7009}]}
04-01 01:07:43.201 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 0% -> 21%) [0.160000s].
04-01 01:07:43.201 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 21% -> 8%) [0.064000s].
04-01 01:07:43.444 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 8% -> 29%) [0.224000s].
04-01 01:07:43.694 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 29% -> 72%) [0.544000s].
04-01 01:07:43.775 17789 17789 V mpvstats: AV: 3.195 A-V: 0.167 Dropped: 43 Cache: 0.544s + 0KB
04-01 01:07:43.945 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 72% -> 93%) [0.704000s].
04-01 01:07:44.200 17789 17837 V mpv : event: unpause
04-01 01:07:44.200 17789 17837 V mpv : [cplayer] End buffering (waited 1.003032 secs) [1.024000s].
04-01 01:07:44.206 17789 17837 V mpv : property: buffering = false
04-01 01:07:44.206 17789 17789 V PlayerActivity: state BUFFERING -> PLAYING
04-01 01:07:44.777 17789 17789 V mpvstats: AV: 3.996 A-V: 0.000 Dropped: 52 Cache: 0.128s + 0KB
04-01 01:07:44.792 17789 17789 V mpvstats: AV: 4.030 A-V: 0.000 Dropped: 52 Cache: 0.128s + 0KB
04-01 01:07:46.558 17789 17837 V mpv : event: unpause
04-01 01:07:46.558 17789 17837 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 0%) [0.000000s].
04-01 01:07:46.560 17789 17837 V mpv : property: buffering = true
04-01 01:07:46.560 17789 17789 V PlayerActivity: state PLAYING -> BUFFERING
04-01 01:07:46.562 17789 17789 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=0.0, end=6.943999999999505}], cache-end=6.9759999999987485, reader-pts=6.9759999999987485, cache-duration=0.0, eof=false, underrun=true, idle=false, total-bytes=3775488, fw-bytes=795008, debug-low-level-seeks=0, debug-ts-last=24557.417800000003, ts-per-stream=[{type=video, duration=1.5348666666686768, reader=24555.882933333334, end=24557.417800000003}, {type=audio, duration=0.0, reader=24557.0609, end=24557.0609}]}
04-01 01:07:46.591 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 0% -> 21%) [0.160000s].
04-01 01:07:46.714 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 21% -> 42%) [0.320000s].
04-01 01:07:46.915 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 42% -> 63%) [0.480000s].
04-01 01:07:47.166 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 63% -> 85%) [0.640000s].
04-01 01:07:47.216 17789 17836 W AudioTrack: retrograde timestamp position corrected, -107520 = 0 - 107520
04-01 01:07:47.218 17789 17837 V mpv : event: unpause
04-01 01:07:47.218 17789 17837 V mpv : [cplayer] End buffering (waited 0.657649 secs) [0.800000s].
04-01 01:07:47.224 17789 17837 V mpv : property: buffering = false
04-01 01:07:47.225 17789 17789 V PlayerActivity: state BUFFERING -> PLAYING
04-01 01:07:47.295 17789 17837 V mpv : event: unpause
04-01 01:07:47.296 17789 17837 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 0%) [0.000000s].
04-01 01:07:47.296 17789 17837 V mpv : property: buffering = true
04-01 01:07:47.304 17789 17789 V PlayerActivity: state PLAYING -> BUFFERING
04-01 01:07:47.304 17789 17789 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=0.0, end=7.266166666664503}], cache-end=7.775999999998021, reader-pts=7.775999999998021, cache-duration=0.0, eof=false, underrun=true, idle=false, total-bytes=4107456, fw-bytes=614080, debug-low-level-seeks=0, debug-ts-last=24556.850566666668, ts-per-stream=[{type=video, duration=1.4347666666653822, reader=24556.850566666668, end=24558.285333333333}, {type=audio, duration=0.0, reader=24557.8609, end=24557.8609}]}
04-01 01:07:47.360 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 0% -> 21%) [0.160000s].
04-01 01:07:47.360 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 21% -> 17%) [0.128000s].
04-01 01:07:47.665 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 17% -> 38%) [0.288000s].
04-01 01:07:47.715 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 38% -> 59%) [0.448000s].
04-01 01:07:47.790 17789 17789 V mpvstats: AV: 6.766 A-V: 0.014 Dropped: 79 Cache: 0.448s + 0KB
04-01 01:07:47.811 17789 17789 V mpvstats: AV: 6.766 A-V: 0.014 Dropped: 79 Cache: 0.448s + 0KB
04-01 01:07:47.915 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 59% -> 81%) [0.608000s].
04-01 01:07:48.168 17789 17837 V mpv : event: unpause
04-01 01:07:48.168 17789 17837 V mpv : [cplayer] End buffering (waited 0.871082 secs) [0.928000s].
04-01 01:07:48.174 17789 17837 V mpv : property: buffering = false
04-01 01:07:48.176 17789 17789 V PlayerActivity: state BUFFERING -> PLAYING
04-01 01:07:48.792 17789 17789 V mpvstats: AV: 8.134 A-V: 0.000 Dropped: 103 Cache: 0.032s + 0KB
04-01 01:07:48.892 17789 17837 V mpv : event: unpause
04-01 01:07:48.892 17789 17837 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 0%) [0.000000s].
04-01 01:07:48.893 17789 17837 V mpv : property: buffering = true
04-01 01:07:48.893 17789 17789 V PlayerActivity: state PLAYING -> BUFFERING
04-01 01:07:48.894 17789 17789 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=0.0, end=8.767666666666628}], cache-end=9.376000000000204, reader-pts=9.376000000000204, cache-duration=0.0, eof=false, underrun=true, idle=false, total-bytes=4644992, fw-bytes=452736, debug-low-level-seeks=0, debug-ts-last=24558.35206666667, ts-per-stream=[{type=video, duration=1.5348666666686768, reader=24558.352066666666, end=24559.886933333335}, {type=audio, duration=0.0, reader=24559.460900000002, end=24559.460900000002}]}
04-01 01:07:48.965 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 0% -> 21%) [0.160000s].
04-01 01:07:49.166 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 21% -> 42%) [0.320000s].
04-01 01:07:49.416 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 42% -> 63%) [0.480000s].
04-01 01:07:49.465 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 63% -> 85%) [0.640000s].
04-01 01:07:49.667 17789 17836 W AudioTrack: retrograde timestamp position corrected, -27904 = 0 - 27904
04-01 01:07:49.670 17789 17837 V mpv : event: unpause
04-01 01:07:49.673 17789 17837 V mpv : [cplayer] End buffering (waited 0.775228 secs) [0.800000s].
04-01 01:07:49.677 17789 17837 V mpv : property: buffering = false
04-01 01:07:49.677 17789 17789 V PlayerActivity: state BUFFERING -> PLAYING
04-01 01:07:49.806 17789 17789 V mpvstats: AV: 9.135 A-V: 0.000 Dropped: 126 Cache: 0.576s + 0KB
04-01 01:07:49.883 17789 26691 W AudioTrack: releaseBuffer() track 0xb2ceed00 disabled due to previous underrun, restarting
04-01 01:07:50.016 17789 17837 V mpv : event: unpause
04-01 01:07:50.017 17789 17837 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 0%) [0.000000s].
04-01 01:07:50.017 17789 17837 V mpv : property: buffering = true
04-01 01:07:50.017 17789 17789 V PlayerActivity: state PLAYING -> BUFFERING
04-01 01:07:50.018 17789 17789 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=0.0, end=10.463999999999942}], cache-end=10.495999999999185, reader-pts=10.495999999999185, cache-duration=0.0, eof=false, underrun=true, idle=false, total-bytes=5061760, fw-bytes=515008, debug-low-level-seeks=0, debug-ts-last=24560.9213, ts-per-stream=[{type=video, duration=1.5348666666686768, reader=24559.386433333333, end=24560.9213}, {type=audio, duration=0.0, reader=24560.5809, end=24560.5809}]}
04-01 01:07:50.073 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 0% -> 4%) [0.032000s].
04-01 01:07:50.074 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 4% -> 0%) [0.000000s].
04-01 01:07:50.074 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 0% -> 17%) [0.128000s].
04-01 01:07:50.074 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 17% -> 8%) [0.064000s].
04-01 01:07:50.418 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 8% -> 51%) [0.384000s].
04-01 01:07:50.668 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 51% -> 72%) [0.544000s].
04-01 01:07:50.717 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 72% -> 93%) [0.704000s].
04-01 01:07:50.808 17789 17789 V mpvstats: AV: 9.302 A-V: 0.935 Dropped: 127 Cache: 0.704s + 0KB
04-01 01:07:50.827 17789 17789 V mpvstats: AV: 9.302 A-V: 0.935 Dropped: 127 Cache: 0.704s + 0KB
04-01 01:07:50.921 17789 17837 V mpv : event: unpause
04-01 01:07:50.922 17789 17837 V mpv : [cplayer] End buffering (waited 0.902576 secs) [0.864000s].
04-01 01:07:50.925 17789 17837 V mpv : property: buffering = false
04-01 01:07:50.926 17789 17789 V PlayerActivity: state BUFFERING -> PLAYING
04-01 01:07:51.145 17789 26691 W AudioTrack: releaseBuffer() track 0xb2ceed00 disabled due to previous underrun, restarting
04-01 01:07:51.297 17789 17837 V mpv : event: unpause
04-01 01:07:51.297 17789 17837 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 0%) [0.000000s].
04-01 01:07:51.298 17789 17837 V mpv : property: buffering = true
04-01 01:07:51.298 17789 17789 V PlayerActivity: state PLAYING -> BUFFERING
04-01 01:07:51.299 17789 17789 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=0.0, end=10.569466666667722}], cache-end=11.775999999998021, reader-pts=11.775999999998021, cache-duration=0.0, eof=false, underrun=true, idle=false, total-bytes=5639616, fw-bytes=698176, debug-low-level-seeks=0, debug-ts-last=24562.1225, ts-per-stream=[{type=video, duration=1.5348666666650388, reader=24560.587633333336, end=24562.1225}, {type=audio, duration=0.0, reader=24561.8609, end=24561.8609}]}
04-01 01:07:51.355 17789 17837 V mpv : [cplayer] Still buffering (buffer went from 0% -> 21%) [0.160000s].
04-01 01:07:51.355 17789 17837 V mpv : [cplayer] StillSame here. SD channels are completely unwatchable with Surround enabled. I have disabled it for now.
Did watch the video I posted above? Tell me if yours ever does that.
I have never seen that happen before, but due to the other issues with decoding I haven't put a ton of time into Channels on that TV. There are a lot of networks I have never even tried watching on Channels. Fox News is certainly a channel that I have never watched, so I can't say at this point whether it is an issue for me.
Is the video from the cable channel or TVE? Or does it do the same on both?
Is is TVE. The problem shown in the video is the only issue left I have with TVE now that I can use a different decoder thanks to tmm1.
Does it happen on all TVE channels, or only Fox News?
It's happened on a few.... Like diy and HGTV. I've been watching a lot of Fox news lately.
I just watched DIY (TVE) for over 20 minutes without a blip. Not sure if that was long enough that I would have seen the issue, but everything seemed fine.
On another note, changing the transcoding to 1080p rather than original, and re-enabling Surround, is working so far on SD channels that had serious issues whenever Surround was enabled using original.
1 Like
I'm anxiously awaiting a new release in hopes it fixes the buffering.
A new beta was uploaded to the Play Store with a possible fix. I have another change I'm also considering but I left it out for now.
1 Like
Weird, I still don't see it being available....
I had to remove myself from the beta in the Play store, Uninstall the beta and reinstall the non-beta then install the beta from the app.
You might have to check it when you first open the player.
Did you try the beta on the fire tv?
Sucks! Its still happening on my Sony TV
04-02 00:25:57.271 15602 15602 V mpvstats: AV: 1355.322 A-V: 0.000 Dropped: 0 Cache: 14.293s + 0KB
04-02 00:26:00.271 15602 15602 V mpvstats: AV: 1358.325 A-V: 0.000 Dropped: 0 Cache: 12.288s + 0KB
04-02 00:26:00.393 15602 15612 I ls.dvr.app.bet: Background concurrent copying GC freed 304396(12MB) AllocSpace objects, 0(0B) LOS objects, 49% free, 12MB/25MB, paused 416us total 120.974ms
04-02 00:26:03.272 15602 15602 V mpvstats: AV: 1361.328 A-V: 0.000 Dropped: 0 Cache: 12.245s + 0KB
04-02 00:26:06.272 15602 15602 V mpvstats: AV: 1364.331 A-V: 0.000 Dropped: 0 Cache: 13.141s + 0KB
04-02 00:26:09.272 15602 15602 V mpvstats: AV: 1367.334 A-V: 0.000 Dropped: 0 Cache: 14.464s + 0KB
04-02 00:26:11.904 15602 15648 D mpv : [ffmpeg/video] h264: Reinit context to 1280x720, pix_fmt: yuv420p
04-02 00:26:11.970 15602 15648 V mpv : [vd] Decoder format: 1280x720 [0:1] yuv420p bt.709/bt.709/bt.1886/limited/auto CL=mpeg2/4/h264 (auto 0.000000/0.000000/0.000000)
04-02 00:26:11.970 15602 15648 V mpv : [vd] Forcing user-set aspect ratio.
04-02 00:26:12.273 15602 15602 V mpvstats: AV: 1370.312 A-V: 0.000 Dropped: 0 Cache: 13.611s + 0KB
04-02 00:26:15.274 15602 15602 V mpvstats: AV: 1373.315 A-V: 0.000 Dropped: 0 Cache: 11.307s + 0KB
04-02 00:26:18.274 15602 15602 V mpvstats: AV: 1376.318 A-V: 0.000 Dropped: 0 Cache: 14.379s + 0KB
04-02 00:26:21.275 15602 15602 V mpvstats: AV: 1379.321 A-V: 0.000 Dropped: 0 Cache: 15.445s + 0KB
04-02 00:26:24.276 15602 15602 V mpvstats: AV: 1382.324 A-V: 0.000 Dropped: 0 Cache: 16.640s + 0KB
04-02 00:26:27.277 15602 15602 V mpvstats: AV: 1385.350 A-V: 0.000 Dropped: 0 Cache: 13.653s + 0KB
04-02 00:26:30.278 15602 15602 V mpvstats: AV: 1388.353 A-V: 0.000 Dropped: 0 Cache: 11.349s + 0KB
04-02 00:26:33.279 15602 15602 V mpvstats: AV: 1391.356 A-V: 0.000 Dropped: 0 Cache: 12.544s + 0KB
04-02 00:26:36.280 15602 15602 V mpvstats: AV: 1394.359 A-V: 0.000 Dropped: 0 Cache: 9.557s + 0KB
04-02 00:26:39.280 15602 15602 V mpvstats: AV: 1397.328 A-V: 0.000 Dropped: 0 Cache: 10.624s + 0KB
04-02 00:26:42.280 15602 15602 V mpvstats: AV: 1400.320 A-V: 0.000 Dropped: 0 Cache: 11.691s + 0KB
04-02 00:26:45.282 15602 15602 V mpvstats: AV: 1403.323 A-V: 0.000 Dropped: 0 Cache: 11.563s + 0KB
04-02 00:26:48.282 15602 15602 V mpvstats: AV: 1406.326 A-V: 0.000 Dropped: 0 Cache: 13.300s + 0KB
04-02 00:26:51.284 15602 15602 V mpvstats: AV: 1409.329 A-V: 0.000 Dropped: 0 Cache: 10.655s + 0KB
04-02 00:26:54.284 15602 15602 V mpvstats: AV: 1412.332 A-V: 0.000 Dropped: 0 Cache: 11.721s + 0KB
04-02 00:26:56.838 15602 15648 W mpv : [ad] Invalid audio PTS: 1415.390833 -> 1416.402933
04-02 00:26:57.286 15602 15602 V mpvstats: AV: 1415.235 A-V: 0.879 Dropped: 0 Cache: 11.776s + 0KB
04-02 00:27:00.287 15602 15602 V mpvstats: AV: 1419.206 A-V: 0.137 Dropped: 0 Cache: 11.520s + 0KB
04-02 00:27:03.288 15602 15602 V mpvstats: AV: 1422.342 A-V: 0.000 Dropped: 0 Cache: 8.533s + 0KB
04-02 00:27:06.288 15602 15602 V mpvstats: AV: 1425.345 A-V: 0.000 Dropped: 0 Cache: 11.776s + 0KB
04-02 00:27:09.290 15602 15602 V mpvstats: AV: 1428.348 A-V: 0.000 Dropped: 0 Cache: 8.789s + 0KB
04-02 00:27:12.291 15602 15602 V mpvstats: AV: 1431.351 A-V: 0.000 Dropped: 0 Cache: 5.717s + 0KB
04-02 00:27:15.292 15602 15602 V mpvstats: AV: 1434.343 A-V: 0.000 Dropped: 0 Cache: 2.731s + 0KB
04-02 00:27:18.102 15602 15648 V mpv : event: unpause
04-02 00:27:18.103 15602 15648 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 26%) [0.266933s].
04-02 00:27:18.106 15602 15648 V mpv : property: buffering = true
04-02 00:27:18.106 15602 15602 V PlayerActivity: state PLAYING -> BUFFERING
04-02 00:27:18.108 15602 15602 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=1386.517499888889, end=1437.112511}], cache-end=1437.5796554444444, reader-pts=1437.312722111111, cache-duration=0.266933333333327, eof=false, underrun=true, idle=false, total-bytes=31724992, fw-bytes=161984, debug-low-level-seeks=0, debug-ts-last=1437.5963444444444, ts-per-stream=[{type=video, duration=0.266933333333327, reader=1437.329411111111, end=1437.5963444444444}, {type=audio, duration=0.0, reader=1437.6249555555555, end=1437.6249555555555}]}
04-02 00:27:18.297 15602 15602 V mpvstats: AV: 1437.179 A-V: 0.000 Dropped: 0 Cache: 0.267s + 0KB
04-02 00:27:21.298 15602 15602 V mpvstats: AV: 1437.179 A-V: 0.000 Dropped: 0 Cache: 0.267s + 0KB
04-02 00:27:24.298 15602 15602 V mpvstats: AV: 1437.179 A-V: 0.000 Dropped: 0 Cache: 0.267s + 0KB
04-02 00:27:27.300 15602 15602 V mpvstats: AV: 1437.179 A-V: 0.000 Dropped: 0 Cache: 0.267s + 0KB
04-02 00:27:30.300 15602 15602 V mpvstats: AV: 1437.179 A-V: 0.000 Dropped: 0 Cache: 0.267s + 0KB
04-02 00:27:33.302 15602 15602 V mpvstats: AV: 1437.179 A-V: 0.000 Dropped: 0 Cache: 0.267s + 0KB
04-02 00:27:35.347 15602 15648 V mpv : event: unpause
04-02 00:27:35.348 15602 15648 V mpv : [cplayer] End buffering (waited 17.243174 secs) [1.237333s].
04-02 00:27:35.358 15602 15648 V mpv : property: buffering = false
04-02 00:27:35.358 15602 15602 V PlayerActivity: state BUFFERING -> PLAYING
04-02 00:27:35.514 15602 15602 V mpvstats: AV: 1437.480 A-V: 0.000 Dropped: 5 Cache: 2.603s + 0KB
04-02 00:27:36.303 15602 15602 V mpvstats: AV: 1438.280 A-V: 0.000 Dropped: 5 Cache: 7.680s + 0KB
04-02 00:27:39.304 15602 15602 V mpvstats: AV: 1441.283 A-V: 0.000 Dropped: 5 Cache: 26.069s + 0KB
04-02 00:27:42.305 15602 15602 V mpvstats: AV: 1444.286 A-V: 0.000 Dropped: 5 Cache: 27.136s + 0KB
04-02 00:27:45.305 15602 15602 V mpvstats: AV: 1447.278 A-V: 0.000 Dropped: 5 Cache: 28.117s + 0KB
04-02 00:27:48.307 15602 15602 V mpvstats: AV: 1450.281 A-V: 0.000 Dropped: 5 Cache: 29.867s + 0KB
04-02 00:27:51.308 15602 15602 V mpvstats: AV: 1453.284 A-V: 0.000 Dropped: 5 Cache: 27.008s + 0KB
04-02 00:27:54.309 15602 15602 V mpvstats: AV: 1456.287 A-V: 0.000 Dropped: 5 Cache: 28.075s + 0KB
04-02 00:27:57.310 15602 15602 V mpvstats: AV: 1459.290 A-V: 0.000 Dropped: 5 Cache: 25.088s + 0KB
04-02 00:28:00.311 15602 15602 V mpvstats: AV: 1462.282 A-V: 0.000 Dropped: 5 Cache: 30.293s + 0KB
04-02 00:28:03.312 15602 15602 V mpvstats: AV: 1465.285 A-V: 0.000 Dropped: 5 Cache: 27.307s + 0KB
04-02 00:28:06.313 15602 15602 V mpvstats: AV: 1468.288 A-V: 0.000 Dropped: 5 Cache: 28.288s + 0KB
04-02 00:28:09.315 15602 15602 V mpvstats: AV: 1471.291 A-V: 0.000 Dropped: 5 Cache: 29.525s + 0KB
04-02 00:28:12.316 15602 15602 V mpvstats: AV: 1474.294 A-V: 0.000 Dropped: 5 Cache: 30.635s + 0KB
04-02 00:28:15.318 15602 15602 V mpvstats: AV: 1477.301 A-V: 0.000 Dropped: 5 Cache: 27.648s + 0KB
04-02 00:28:18.319 15602 15602 V mpvstats: AV: 1480.304 A-V: 0.000 Dropped: 5 Cache: 25.941s + 0KB
04-02 00:28:21.320 15602 15602 V mpvstats: AV: 1483.307 A-V: 0.000 Dropped: 5 Cache: 29.099s + 0KB
04-02 00:28:24.320 15602 15602 V mpvstats: AV: 1486.310 A-V: 0.000 Dropped: 5 Cache: 30.251s + 0KB
04-02 00:28:27.322 15602 15602 V mpvstats: AV: 1489.279 A-V: 0.000 Dropped: 5 Cache: 27.264s + 0KB
04-02 00:28:30.323 15602 15602 V mpvstats: AV: 1492.316 A-V: 0.000 Dropped: 5 Cache: 28.245s + 0KB
04-02 00:28:33.327 15602 15602 V mpvstats: AV: 1495.285 A-V: 0.000 Dropped: 5 Cache: 25.259s + 0KB
04-02 00:28:36.329 15602 15602 V mpvstats: AV: 1498.288 A-V: 0.000 Dropped: 5 Cache: 24.320s + 0KB
04-02 00:28:39.329 15602 15602 V mpvstats: AV: 1501.291 A-V: 0.000 Dropped: 5 Cache: 27.605s + 0KB
04-02 00:28:42.330 15602 15602 V mpvstats: AV: 1504.294 A-V: 0.000 Dropped: 5 Cache: 28.587s + 0KB
04-02 00:28:45.333 15602 15602 V mpvstats: AV: 1507.290 A-V: 0.000 Dropped: 5 Cache: 28.885s + 0KB
04-02 00:28:48.335 15602 15602 V mpvstats: AV: 1510.293 A-V: 0.000 Dropped: 5 Cache: 30.182s + 0KB
04-02 00:28:51.337 15602 15602 V mpvstats: AV: 1513.296 A-V: 0.000 Dropped: 5 Cache: 27.110s + 0KB
04-02 00:28:54.337 15602 15602 V mpvstats: AV: 1516.299 A-V: 0.000 Dropped: 5 Cache: 28.390s + 0KB
04-02 00:28:57.338 15602 15602 V mpvstats: AV: 1519.302 A-V: 0.000 Dropped: 5 Cache: 29.499s + 0KB
04-02 00:29:00.339 15602 15602 V mpvstats: AV: 1522.305 A-V: 0.000 Dropped: 5 Cache: 33.169s + 0KB
04-02 00:29:03.340 15602 15602 V mpvstats: AV: 1525.308 A-V: 0.000 Dropped: 5 Cache: 30.182s + 0KB
04-02 00:29:06.341 15602 15602 V mpvstats: AV: 1528.311 A-V: 0.000 Dropped: 5 Cache: 31.121s + 0KB
04-02 00:29:09.341 15602 15602 V mpvstats: AV: 1531.314 A-V: 0.000 Dropped: 5 Cache: 28.134s + 0KB
04-02 00:29:12.343 15602 15602 V mpvstats: AV: 1534.317 A-V: 0.000 Dropped: 5 Cache: 25.147s + 0KB
04-02 00:29:14.900 15602 15648 V mpv : [vd] Decoder format: 1280x720 [0:1] yuv420p bt.709/bt.709/bt.1886/limited/auto CL=mpeg1/jpeg (auto 0.000000/0.000000/0.000000)
04-02 00:29:14.900 15602 15648 V mpv : [vd] Forcing user-set aspect ratio.
04-02 00:29:14.900 15602 15648 V mpv : [vf] [in] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:14.916 15602 15648 V mpv : event: video-reconfig
04-02 00:29:14.916 15602 15648 V mpv : [vf] [userdeint] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:14.916 15602 15648 V mpv : [vf] [autorotate] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:14.916 15602 15648 V mpv : [vf] [convert] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:14.916 15602 15648 V mpv : [vf] [out] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:14.948 15602 15648 I mpv : [cplayer] VO: [gpu] 1280x720 => 1280x720 yuv420p
04-02 00:29:14.948 15602 15648 V mpv : [cplayer] VO: Description: Shader-based GPU Renderer
04-02 00:29:14.953 15602 15648 V mpv : event: video-reconfig
04-02 00:29:15.344 15602 15602 V mpvstats: AV: 1537.320 A-V: 0.001 Dropped: 0 Cache: 22.144s + 0KB
04-02 00:29:15.572 15602 15602 V mpvstats: AV: 1537.554 A-V: 0.001 Dropped: 0 Cache: 21.888s + 0KB
04-02 00:29:18.345 15602 15602 V mpvstats: AV: 1540.323 A-V: 0.000 Dropped: 0 Cache: 19.712s + 0KB
04-02 00:29:21.346 15602 15602 V mpvstats: AV: 1543.326 A-V: 0.000 Dropped: 0 Cache: 32.085s + 0KB
04-02 00:29:23.819 15602 15612 I ls.dvr.app.bet: Background concurrent copying GC freed 310046(12MB) AllocSpace objects, 0(0B) LOS objects, 49% free, 12MB/25MB, paused 166us total 116.692ms
04-02 00:29:24.347 15602 15602 V mpvstats: AV: 1546.329 A-V: 0.000 Dropped: 0 Cache: 33.195s + 0KB
04-02 00:29:27.349 15602 15602 V mpvstats: AV: 1549.332 A-V: 0.000 Dropped: 0 Cache: 30.165s + 0KB
04-02 00:29:29.792 15602 15648 D mpv : [ffmpeg/video] h264: Reinit context to 1920x1088, pix_fmt: yuv420p
04-02 00:29:29.919 15602 15648 V mpv : [vd] Decoder format: 1920x1080 [0:1] yuv420p bt.709/bt.709/bt.1886/limited/auto CL=mpeg1/jpeg (auto 0.000000/0.000000/0.000000)
04-02 00:29:29.919 15602 15648 V mpv : [vd] Forcing user-set aspect ratio.
04-02 00:29:29.919 15602 15648 V mpv : [vf] [in] 1920x1080 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:29.927 15602 15648 V mpv : event: video-reconfig
04-02 00:29:29.927 15602 15648 V mpv : [vf] [userdeint] 1920x1080 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:29.927 15602 15648 V mpv : [vf] [autorotate] 1920x1080 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:29.927 15602 15648 V mpv : [vf] [convert] 1920x1080 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:29.927 15602 15648 V mpv : [vf] [out] 1920x1080 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:29.957 15602 15648 I mpv : [cplayer] VO: [gpu] 1920x1080 => 1920x1080 yuv420p
04-02 00:29:29.957 15602 15648 V mpv : [cplayer] VO: Description: Shader-based GPU Renderer
04-02 00:29:29.958 15602 15648 V mpv : event: video-reconfig
04-02 00:29:30.350 15602 15602 V mpvstats: AV: 1552.339 A-V: 0.000 Dropped: 0 Cache: 31.275s + 0KB
04-02 00:29:33.350 15602 15602 V mpvstats: AV: 1555.342 A-V: 0.000 Dropped: 0 Cache: 28.203s + 0KB
04-02 00:29:36.353 15602 15602 V mpvstats: AV: 1558.351 A-V: 0.000 Dropped: 0 Cache: 29.397s + 0KB
04-02 00:29:39.355 15602 15602 V mpvstats: AV: 1561.361 A-V: 0.000 Dropped: 0 Cache: 26.411s + 0KB
04-02 00:29:42.356 15602 15602 V mpvstats: AV: 1564.337 A-V: 0.000 Dropped: 0 Cache: 23.424s + 0KB
04-02 00:29:45.356 15602 15602 V mpvstats: AV: 1567.340 A-V: 0.000 Dropped: 0 Cache: 20.437s + 0KB
04-02 00:29:48.356 15602 15602 V mpvstats: AV: 1570.350 A-V: 0.000 Dropped: 0 Cache: 17.365s + 0KB
04-02 00:29:51.359 15602 15602 V mpvstats: AV: 1573.360 A-V: 0.000 Dropped: 0 Cache: 14.336s + 0KB
04-02 00:29:54.361 15602 15602 V mpvstats: AV: 1576.369 A-V: 0.000 Dropped: 0 Cache: 11.349s + 0KB
04-02 00:29:57.362 15602 15602 V mpvstats: AV: 1579.372 A-V: 0.000 Dropped: 0 Cache: 8.363s + 0KB
04-02 00:29:57.863 15602 15648 D mpv : [ffmpeg/video] h264: Reinit context to 1280x720, pix_fmt: yuv420p
04-02 00:29:58.000 15602 15648 V mpv : [vd] Decoder format: 1280x720 yuv420p bt.709/bt.709/bt.1886/limited/auto CL=mpeg1/jpeg (auto 0.000000/0.000000/0.000000)
04-02 00:29:58.001 15602 15648 V mpv : [vd] Forcing user-set aspect ratio.
04-02 00:29:58.002 15602 15648 V mpv : [vf] [in] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:58.033 15602 15648 V mpv : [vf] [userdeint] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:58.034 15602 15648 V mpv : event: video-reconfig
04-02 00:29:58.034 15602 15648 V mpv : event: video-reconfig
04-02 00:29:58.034 15602 15648 V mpv : [vf] [autorotate] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:58.034 15602 15648 V mpv : [vf] [convert] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:58.034 15602 15648 V mpv : [vf] [out] 1280x720 [134217729:134217728] yuv420p bt.709/bt.709/bt.1886/limited/display SP=1.000000 CL=mpeg1/jpeg
04-02 00:29:58.038 15602 15648 I mpv : [cplayer] VO: [gpu] 1280x720 => 1280x720 yuv420p
04-02 00:29:58.038 15602 15648 V mpv : [cplayer] VO: Description: Shader-based GPU Renderer
04-02 00:30:00.365 15602 15602 V mpvstats: AV: 1582.365 A-V: 0.000 Dropped: 0 Cache: 5.376s + 0KB
04-02 00:30:03.366 15602 15602 V mpvstats: AV: 1585.368 A-V: 0.000 Dropped: 0 Cache: 5.291s + 0KB
04-02 00:30:06.366 15602 15602 V mpvstats: AV: 1588.371 A-V: 0.000 Dropped: 0 Cache: 2.304s + 0KB
04-02 00:30:08.846 15602 15648 V mpv : event: unpause
04-02 00:30:08.847 15602 15648 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 23%) [0.233578s].
04-02 00:30:08.847 15602 15648 V mpv : property: buffering = true
04-02 00:30:08.847 15602 15602 V PlayerActivity: state PLAYING -> BUFFERING
04-02 00:30:08.848 15602 15602 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=1543.1258221111111, end=1590.2398443333334}], cache-end=1591.174111, reader-pts=1590.9405332222223, cache-duration=0.2335777777777821, eof=false, underrun=true, idle=false, total-bytes=31728768, fw-bytes=124928, debug-low-level-seeks=0, debug-ts-last=1590.1731223333334, ts-per-stream=[{type=video, duration=0.2335777777777821, reader=1590.9572222222223, end=1591.1908}, {type=audio, duration=0.0, reader=1591.199011111111, end=1591.199011111111}]}
04-02 00:30:09.367 15602 15602 V mpvstats: AV: 1590.857 A-V: 0.000 Dropped: 0 Cache: 0.234s + 0KB
04-02 00:30:12.368 15602 15602 V mpvstats: AV: 1590.857 A-V: 0.000 Dropped: 0 Cache: 0.234s + 0KB
04-02 00:30:13.722 15602 22455 V ApiServer: REQUEST: GET /log
04-02 00:30:13.726 15602 22455 I hls : goroutine 17 [running, locked to thread]:
04-02 00:30:13.726 15602 22455 I hls : main.FullStackTrace(0x9204c070, 0x92038f50)
04-02 00:30:13.726 15602 22455 I hls : /Users/fancybox/source/channels-android/vendor/libhls/channels-server/hls/libhls/hls_c.go:249 +0x80
04-02 00:30:13.726 15602 22455 I hls : main.hls_log_stack()
04-02 00:30:13.726 15602 22455 I hls : /Users/fancybox/source/channels-android/vendor/libhls/channels-server/hls/libhls/hls_c.go:259 +0x14
04-02 00:30:13.726 15602 22455 I hls : main._cgoexpwrap_277a0c6059f4_hls_log_stack()
04-02 00:30:13.726 15602 22455 I hls : _cgo_gotypes.go:299 +0x14
04-02 00:30:13.726 15602 22455 I hls :
04-02 00:30:13.726 15602 22455 I hls : goroutine 6 [syscall]:
04-02 00:30:13.726 15602 22455 I hls : os/signal.signal_recv(0x0)
04-02 00:30:13.726 15602 22455 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/runtime/sigqueue.go:147 +0x14c
04-02 00:30:13.726 15602 22455 I hls : os/signal.loop()
04-02 00:30:13.726 15602 22455 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/os/signal/signal_unix.go:23 +0x14
04-02 00:30:13.726 15602 22455 I hls : created by os/signal.Notify.func1
04-02 00:30:13.726 15602 22455 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/os/signal/signal.go:127 +0x38
04-02 00:30:13.726 15602 22455 I hls :
04-02 00:30:13.726 15602 22455 I hls : goroutine 19 [select]:
04-02 00:30:13.726 15602 22455 I hls : github.com/grafov/kiwi.processSink(0x92096080)
04-02 00:30:13.726 15602 22455 I hls : /Users/fancybox/go/pkg/mod/github.com/grafov/[email protected]/sink.go:327 +0x90
04-02 00:30:13.726 15602 22455 I hls : created by github.com/grafov/kiwi.SinkTo
04-02 00:30:13.726 15602 22455 I hls : /Users/fancybox/go/pkg/mod/github.com/grafov/[email protected]/sink.go:111 +0x310
04-02 00:30:15.369 15602 15602 V mpvstats: AV: 1590.857 A-V: 0.000 Dropped: 0 Cache: 0.234s + 0KB
04-02 00:30:18.370 15602 15602 V mpvstats: AV: 1590.857 A-V: 0.000 Dropped: 0 Cache: 0.234s + 0KB
04-02 00:30:21.371 15602 15602 V mpvstats: AV: 1590.857 A-V: 0.000 Dropped: 0 Cache: 0.234s + 0KB
04-02 00:30:24.371 15602 15602 V mpvstats: AV: 1590.857 A-V: 0.000 Dropped: 0 Cache: 0.234s + 0KB
04-02 00:30:27.183 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 23% -> 17%) [0.170667s].
04-02 00:30:27.190 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 17% -> 41%) [0.417100s].
04-02 00:30:27.198 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 41% -> 25%) [0.256000s].
04-02 00:30:27.227 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 25% -> 89%) [0.896000s].
04-02 00:30:27.372 15602 15602 V mpvstats: AV: 1590.857 A-V: 0.000 Dropped: 0 Cache: 2.005s + 0KB
04-02 00:30:27.431 15602 15648 V mpv : event: unpause
04-02 00:30:27.432 15602 15648 V mpv : [cplayer] End buffering (waited 18.584090 secs) [2.005333s].
04-02 00:30:27.435 15602 15648 V mpv : property: buffering = false
04-02 00:30:27.435 15602 15602 V PlayerActivity: state BUFFERING -> PLAYING
04-02 00:30:27.621 15602 15602 V mpvstats: AV: 1591.258 A-V: 0.000 Dropped: 13 Cache: 1.664s + 0KB
04-02 00:30:29.389 15602 15648 V mpv : event: unpause
04-02 00:30:29.389 15602 15648 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 23%) [0.233578s].
04-02 00:30:29.389 15602 15648 V mpv : property: buffering = true
04-02 00:30:29.390 15602 15602 V PlayerActivity: state PLAYING -> BUFFERING
04-02 00:30:29.391 15602 15602 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=1547.1965443333333, end=1592.3252665555556}], cache-end=1593.3429443333334, reader-pts=1593.1093665555557, cache-duration=0.2335777777777821, eof=false, underrun=true, idle=false, total-bytes=31192896, fw-bytes=136000, debug-low-level-seeks=0, debug-ts-last=1593.0593223333335, ts-per-stream=[{type=video, duration=0.2335777777777821, reader=1593.1260555555557, end=1593.3596333333335}, {type=audio, duration=0.0, reader=1593.3750111111112, end=1593.3750111111112}]}
04-02 00:30:30.373 15602 15602 V mpvstats: AV: 1593.026 A-V: 0.000 Dropped: 13 Cache: 0.234s + 0KB
04-02 00:30:33.374 15602 15602 V mpvstats: AV: 1593.026 A-V: 0.000 Dropped: 13 Cache: 0.234s + 0KB
04-02 00:30:34.208 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 23% -> 4%) [0.042667s].
04-02 00:30:34.210 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 4% -> 30%) [0.300311s].
04-02 00:30:34.219 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 30% -> 4%) [0.042667s].
04-02 00:30:34.219 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 4% -> 35%) [0.350356s].
04-02 00:30:34.219 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 35% -> 4%) [0.042667s].
04-02 00:30:34.222 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 4% -> 38%) [0.383733s].
04-02 00:30:34.224 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 38% -> 4%) [0.042667s].
04-02 00:30:34.225 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 4% -> 40%) [0.400411s].
04-02 00:30:34.263 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 40% -> 76%) [0.768000s].
04-02 00:30:34.365 15602 15610 W System : A resource failed to call end.
04-02 00:30:34.454 15602 15648 V mpv : event: unpause
04-02 00:30:34.455 15602 15648 V mpv : [cplayer] End buffering (waited 5.063865 secs) [2.389333s].
04-02 00:30:34.455 15602 15648 V mpv : property: buffering = false
04-02 00:30:34.455 15602 15602 V PlayerActivity: state BUFFERING -> PLAYING
04-02 00:30:34.650 15602 15602 V mpvstats: AV: 1593.410 A-V: 0.000 Dropped: 28 Cache: 2.048s + 0KB
04-02 00:30:36.375 15602 15602 V mpvstats: AV: 1595.145 A-V: 0.000 Dropped: 28 Cache: 0.256s + 0KB
04-02 00:30:36.842 15602 15648 V mpv : event: unpause
04-02 00:30:36.842 15602 15648 V mpv : [cplayer] Enter buffering (buffer went from 100% -> 23%) [0.233567s].
04-02 00:30:36.842 15602 15648 V mpv : property: buffering = true
04-02 00:30:36.843 15602 15602 V PlayerActivity: state PLAYING -> BUFFERING
04-02 00:30:36.844 15602 15602 V mpvstats: demuxer-cache-state: {seekable-ranges=[{start=1549.2652776666666, end=1594.3272665555555}], cache-end=1595.9288665555555, reader-pts=1595.695299888889, cache-duration=0.23356666666654746, eof=false, underrun=true, idle=false, total-bytes=31842752, fw-bytes=161984, debug-low-level-seeks=0, debug-ts-last=1595.628555666667, ts-per-stream=[{type=video, duration=0.23356666666654746, reader=1595.711988888889, end=1595.9455555555555}, {type=audio, duration=0.0, reader=1595.9350111111112, end=1595.9350111111112}]}
04-02 00:30:39.376 15602 15602 V mpvstats: AV: 1595.612 A-V: 0.000 Dropped: 28 Cache: 0.234s + 0KB
04-02 00:30:41.590 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 23% -> 8%) [0.085333s].
04-02 00:30:41.593 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 8% -> 35%) [0.350333s].
04-02 00:30:41.602 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 35% -> 4%) [0.042667s].
04-02 00:30:41.606 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 4% -> 36%) [0.367022s].
04-02 00:30:41.606 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 36% -> 4%) [0.042667s].
04-02 00:30:41.608 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 4% -> 8%) [0.085333s].
04-02 00:30:41.609 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 8% -> 12%) [0.128000s].
04-02 00:30:41.609 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 12% -> 17%) [0.170667s].
04-02 00:30:41.609 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 17% -> 21%) [0.213333s].
04-02 00:30:41.643 15602 15648 V mpv : [cplayer] Still buffering (buffer went from 21% -> 46%) [0.469333s].
04-02 00:30:41.709 15602 15648 V mpv : event: unpause
04-02 00:30:41.709 15602 15648 V mpv : [cplayer] End buffering (waited 4.865330 secs) [1.536000s].
04-02 00:30:41.719 15602 15648 V mpv : property: buffering = false
04-02 00:30:41.719 15602 15602 V PlayerActivity: state BUFFERING -> PLAYING
04-02 00:30:42.377 15602 15602 V mpvstats: AV: 1596.429 A-V: 0.000 Dropped: 44 Cache: 3.541s + 0KB
04-02 00:30:42.671 15602 15602 V mpvstats: AV: 1596.713 A-V: 0.000 Dropped: 44 Cache: 3.285s + 0KB
04-02 00:30:44.403 15602 22469 V ApiServer: REQUEST: GET /log
04-02 00:30:44.403 15602 22469 I hls : goroutine 17 [running, locked to thread]:
04-02 00:30:44.403 15602 22469 I hls : main.FullStackTrace(0x9204c070, 0x92038f50)
04-02 00:30:44.403 15602 22469 I hls : /Users/fancybox/source/channels-android/vendor/libhls/channels-server/hls/libhls/hls_c.go:249 +0x80
04-02 00:30:44.403 15602 22469 I hls : main.hls_log_stack()
04-02 00:30:44.403 15602 22469 I hls : /Users/fancybox/source/channels-android/vendor/libhls/channels-server/hls/libhls/hls_c.go:259 +0x14
04-02 00:30:44.403 15602 22469 I hls : main._cgoexpwrap_277a0c6059f4_hls_log_stack()
04-02 00:30:44.403 15602 22469 I hls : _cgo_gotypes.go:299 +0x14
04-02 00:30:44.403 15602 22469 I hls :
04-02 00:30:44.403 15602 22469 I hls : goroutine 6 [syscall]:
04-02 00:30:44.403 15602 22469 I hls : os/signal.signal_recv(0x0)
04-02 00:30:44.403 15602 22469 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/runtime/sigqueue.go:147 +0x14c
04-02 00:30:44.403 15602 22469 I hls : os/signal.loop()
04-02 00:30:44.403 15602 22469 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/os/signal/signal_unix.go:23 +0x14
04-02 00:30:44.403 15602 22469 I hls : created by os/signal.Notify.func1
04-02 00:30:44.403 15602 22469 I hls : /usr/local/Cellar/go/HEAD-612ef03/libexec/src/os/signal/signal.go:127 +0x38
04-02 00:30:44.403 15602 22469 I hls :
04-02 00:30:44.403 15602 22469 I hls : goroutine 19 [select]:
04-02 00:30:44.403 15602 22469 I hls : github.com/grafov/kiwi.processSink(0x92096080)
04-02 00:30:44.403 15602 22469 I hls : /Users/fancybox/go/pkg/mod/github.com/grafov/[email protected]/sink.go:327 +0x90
04-02 00:30:44.403 15602 22469 I hls : created by github.com/grafov/kiwi.SinkTo
04-02 00:30:44.403 15602 22469 I hls : /Users/fancybox/go/pkg/mod/github.com/grafov/[email protected]/sink.go:111 +0x310