[burgemaster]

Hi all,

Not too annoying i know, but when watching various films, mostly MKV`s at 1080p, the video suddenly pauses? I then simply have to unpause to resume.

I have noticed lots of warnings and errors in the log?

Maybe this line?
73.12:56:35 T:1613839216 M:980320256 ERROR: Pause - pcm_pause, alsa error: -77 - File descriptor in bad state

Here is the full log:
http://pastebin.com/MEfJmkib
(PS. I did pause the movie a couple of times with the remote later on in the film.)

Ive also noticed that in the Log it says 2 channels, but its a 5.1 DTS audio track?
Would someone be as kind to see if I have something wrong or what the problem could be?

[burgemaster]

Ive seen that I can repropuce this evrytime when playing the Killa Sample. it also does the same always in the same place. It actually might not be pausing as after maybe 10-15secs it continues and plays again....

15:50:58 T:3078944640 M:1055158272 NOTICE: DVDPlayer: Opening: smb://XXXXXX:XXXX@XXXXXX/movies/Killa Sample.mkv
15:50:58 T:3078944640 M:1055158272 WARNING: CDVDMessageQueue(player):ut MSGQ_NOT_INITIALIZED
15:50:58 T:1613839216 M:1055158272 NOTICE: Creating InputStream
15:50:58 T:1613839216 M:1055150080 NOTICE: Creating Demuxer
15:51:01 T:1613839216 M:1053880320 NOTICE: Opening video stream: 0 source: 256
15:51:01 T:1613839216 M:1053880320 NOTICE: Creating video codec with codec id: 28
15:51:01 T:1613839216 M:1053880320 NOTICE: CDVDVideoCodecFFmpeg::Open() Creating VDPAU(1920x1080, 28)
15:51:01 T:1613839216 M:1052991488 NOTICE: vdp_device = 0x00000001 vdp_st = 0x00000000
15:51:01 T:1613839216 M:1052991488 NOTICE: VDPAU Decoder capabilities:
15:51:01 T:1613839216 M:1052991488 NOTICE: name level macbs width height
15:51:01 T:1613839216 M:1052991488 NOTICE: ------------------------------------
15:51:01 T:1613839216 M:1052991488 NOTICE: MPEG1 0 8192 2048 2048
15:51:01 T:1613839216 M:1052991488 NOTICE: MPEG2_SIMPLE 3 8192 2048 2048
15:51:01 T:1613839216 M:1052991488 NOTICE: MPEG2_MAIN 3 8192 2048 2048
15:51:01 T:1613839216 M:1052991488 NOTICE: H264_MAIN 41 8190 2032 2048
15:51:01 T:1613839216 M:1052991488 NOTICE: H264_HIGH 41 8190 2032 2048
15:51:01 T:1613839216 M:1052991488 NOTICE: VC1_SIMPLE 1 8190 2048 2048
15:51:01 T:1613839216 M:1052991488 NOTICE: VC1_MAIN 2 8190 2048 2048
15:51:01 T:1613839216 M:1052991488 NOTICE: VC1_ADVANCED 4 8190 2048 2048
15:51:01 T:1613839216 M:1052991488 NOTICE: ------------------------------------
15:51:01 T:1613839216 M:1052991488 NOTICE: Mixer feature: VDP_VIDEO_MIXER_FEATURE_NOISE_REDUCTION
15:51:01 T:1613839216 M:1052991488 NOTICE: Mixer feature: VDP_VIDEO_MIXER_FEATURE_SHARPNESS
15:51:01 T:1613839216 M:1052991488 NOTICE: Mixer feature: VDP_VIDEO_MIXER_FEATURE_DEINTERLACE_TEMPORAL
15:51:01 T:1613839216 M:1052991488 NOTICE: Mixer feature: VDP_VIDEO_MIXER_FEATURE_DEINTERLACE_TEMPORAL_SPATIAL
15:51:01 T:1613839216 M:1052991488 NOTICE: Mixer feature: VDP_VIDEO_MIXER_FEATURE_INVERSE_TELECINE
15:51:01 T:1613839216 M:1053052928 NOTICE: Creating 1920x1080 pixmap
15:51:01 T:1613839216 M:1051148288 NOTICE: CDVDVideoCodecFFmpeg::Open() Using codec: H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10 (VDPAU acceleration)
15:51:02 T:1613839216 M:1049448448 NOTICE: Creating video thread
15:51:02 T:1613839216 M:1049321472 NOTICE: Opening audio stream: 1 source: 256
15:51:02 T:1613839216 M:1049321472 NOTICE: Finding audio codec for: 86020
15:51:02 T:1613839216 M:1049321472 NOTICE: Creating audio thread
15:51:02 T:1520429936 M:1049321472 NOTICE: running thread: CDVDPlayerAudio:rocess()
15:51:02 T:1530919792 M:1049321472 NOTICE: running thread: video_thread
15:51:02 T:1520429936 M:1049321472 NOTICE: Creating audio device with codec id: 86020, channels: 2, sample rate: 48000, pass-through
15:51:02 T:1520429936 M:1017987072 WARNING: PulseAudio: Does not support passthrough
15:51:02 T:1530919792 M:1002749952 NOTICE: (VDPAU) screenWidth:1920 vidWidth:1920
15:51:02 T:1530919792 M:1002749952 NOTICE: (VDPAU) screenHeight:1080 vidHeight:1080
15:51:02 T:1520429936 M:959303680 WARNING: CALSADirectSound::GetSpace - get space failed. err: -32 (Broken pipe)
15:51:03 T:1530919792 M:917266432 NOTICE: (VDPAU) Total Output Surfaces Available: 2 of a max (tmp: 2 const: 4)
15:51:03 T:1530919792 M:917266432 NOTICE: (VDPAU) Creating the video mixer
15:51:03 T:1530919792 M:898691072 NOTICE: fps: 23.976025, pwidth: 1920, pheight: 1080, dwidth: 1920, dheight: 1080
15:51:03 T:1530919792 M:898691072 WARNING: CRenderManager::Configure - timeout waiting for previous frame
15:51:03 T:1530919792 M:898691072 NOTICE: Display resolution ADJUST : default: 1920x1080 @ 24.00Hz (14)
15:51:03 T:3078944640 M:898691072 NOTICE: Using GL_TEXTURE_2D
15:51:03 T:3078944640 M:898691072 NOTICE: GL: Using VDPAU render method
15:51:03 T:3078944640 M:898691072 NOTICE: GL: NPOT texture support detected
15:51:03 T:3078944640 M:898691072 NOTICE: GL: Using GL_ARB_pixel_buffer_object
15:51:04 T:1530919792 M:1044832256 ERROR: VDPAU Device Preempted - attempting recovery
15:51:04 T:1530919792 M:1044832256 ERROR: (VDPAU) Error: The display was pre-empted, or a fatal error occurred.(2) at VDPAU.cpp:1109
15:51:04 T:1530919792 M:1044832256 NOTICE: Attempting recovery
15:51:04 T:1530919792 M:1044832256 NOTICE: (VDPAU) FiniVDPAUOutput
15:51:04 T:3078944640 M:1044144128 ERROR: GLX: Same window as before, refreshing context
15:51:05 T:1530919792 M:1025572864 NOTICE: vdp_device = 0x00000001 vdp_st = 0x00000000
15:51:05 T:1530919792 M:993464320 NOTICE: (VDPAU) screenWidth:1920 vidWidth:1920
15:51:05 T:1530919792 M:993464320 NOTICE: (VDPAU) screenHeight:1080 vidHeight:1080
15:51:06 T:1530919792 M:915705856 NOTICE: (VDPAU) Total Output Surfaces Available: 2 of a max (tmp: 2 const: 4)
15:51:06 T:1530919792 M:915705856 NOTICE: (VDPAU) Creating the video mixer
15:51:06 T:3078944640 M:896942080 NOTICE: Created m_glPixmapTexture (259)
15:51:07 T:1530919792 M:887992320 NOTICE: fps: 23.952095, pwidth: 1920, pheight: 1080, dwidth: 1920, dheight: 1080
15:51:07 T:1530919792 M:887992320 NOTICE: Display resolution ADJUST : default: 1920x1080 @ 24.00Hz (14)
15:51:07 T:1530919792 M:887738368 WARNING: Decode - avcodec_decode_video didn't consume the full packet. size: 172063, consumed: 0
15:51:07 T:3078944640 M:887738368 NOTICE: Using GL_TEXTURE_2D
15:51:07 T:3078944640 M:887738368 NOTICE: GL: Using VDPAU render method
15:51:07 T:3078944640 M:887738368 NOTICE: GL: NPOT texture support detected
15:51:07 T:3078944640 M:887738368 NOTICE: GL: Using GL_ARB_pixel_buffer_object
15:51:08 T:1530919792 M:884056064 WARNING: Decode - avcodec_decode_video didn't consume the full packet. size: 141161, consumed: 0
15:51:08 T:1530919792 M:883548160 WARNING: Decode - avcodec_decode_video didn't consume the full packet. size: 132896, consumed: 0
15:51:08 T:1530919792 M:883167232 WARNING: Decode - avcodec_decode_video didn't consume the full packet. size: 120433, consumed: 0
15:51:11 T:1520429936 M:871272448 WARNING: CDVDMessageQueue(audio)::Get - asked for new data packet, with nothing available
15:51:11 T:1530919792 M:870510592 WARNING: CDVDMessageQueue(video)::Get - asked for new data packet, with nothing available
15:51:12 T:1520429936 M:863641600 WARNING: CDVDMessageQueue(audio)::Get - asked for new data packet, with nothing available
15:51:12 T:1530919792 M:863641600 WARNING: CDVDMessageQueue(video)::Get - asked for new data packet, with nothing available
15:51:13 T:1520429936 M:859193344 ERROR: Pause - pcm_pause, alsa error: -77 - File descriptor in bad state
15:51:13 T:1520429936 M:859193344 WARNING: CALSADirectSound::CALSADirectSound - device is not able to pause playback, will flush and prefix with 0 frames
15:51:24 T:1530919792 M:831995904 WARNING: Decode - avcodec_decode_video didn't consume the full packet. size: 137372, consumed: 0
15:51:38 T:1520429936 M:858324992 WARNING: CDVDMessageQueue(audio)::Get - asked for new data packet, with nothing available
15:51:38 T:1530919792 M:858324992 WARNING: CDVDMessageQueue(video)::Get - asked for new data packet, with nothing available
15:51:38 T:1613839216 M:858324992 NOTICE: CDVDPlayer::OnExit()
15:51:38 T:1613839216 M:858324992 NOTICE: DVDPlayer: eof, waiting for queues to empty
15:51:38 T:1613839216 M:858324992 NOTICE: DVDPlayer: closing audio stream
15:51:38 T:1613839216 M:858324992 NOTICE: Closing audio stream
15:51:38 T:1613839216 M:858324992 NOTICE: CDVDMessageQueue(audio)::WaitUntilEmpty
15:51:38 T:1613839216 M:858324992 NOTICE: Waiting for audio thread to exit
15:51:38 T:1520429936 M:858324992 NOTICE: thread end: CDVDPlayerAudio::OnExit()
15:51:38 T:1613839216 M:858324992 NOTICE: Closing audio device
15:51:38 T:1613839216 M:858324992 NOTICE: Deleting audio codec
15:51:38 T:1613839216 M:858324992 NOTICE: DVDPlayer: closing video stream
15:51:38 T:1613839216 M:858324992 NOTICE: Closing video stream
15:51:38 T:1613839216 M:858324992 NOTICE: CDVDMessageQueue(video)::WaitUntilEmpty
15:51:38 T:1613839216 M:858324992 NOTICE: waiting for video thread to exit
15:51:38 T:1530919792 M:858324992 NOTICE: thread end: video_thread
15:51:38 T:1613839216 M:858324992 NOTICE: deleting video codec
15:51:38 T:1613839216 M:858324992 NOTICE: CDVDPlayer::OnExit() deleting demuxer
15:51:38 T:1613839216 M:858324992 NOTICE: CDVDPlayer::OnExit() deleting input stream
15:51:38 T:3078944640 M:851734528 ERROR: GLX: Same window as before, refreshing context
15:51:39 T:3078944640 M:849195008 WARNING: Skin has invalid include: control
15:51:39 T:3078944640 M:862412800 WARNING: Previous line repeats 11 times.
15:51:39 T:3078944640 M:862412800 NOTICE: CDVDPlayer::CloseFile()
15:51:39 T:3078944640 M:862412800 WARNING: CDVDMessageQueue(player):ut MSGQ_NOT_INITIALIZED
15:51:39 T:3078944640 M:862412800 NOTICE: DVDPlayer: waiting for threads to exit
15:51:39 T:3078944640 M:862412800 NOTICE: DVDPlayer: finished waiting
15:51:39 T:3078944640 M:862412800 NOTICE: (VDPAU) Close
15:51:39 T:3078944640 M:862412800 NOTICE: (VDPAU) FiniVDPAUOutput
15:51:40 T:3078944640 M:1027526656 ERROR: VDPAU Device Preempted - attempting recovery
15:51:40 T:3078944640 M:1027526656 ERROR: (VDPAU) Error: The display was pre-empted, or a fatal error occurred.(2) at VDPAU.cpp:774

[TheSwissKnife]

I have seen similar issues, and I think the following line is the clue.


15:51:02 T:1520429936 M:959303680 WARNING: CALSADirectSound::GetSpace - get space failed. err: -32 (Broken pipe)


When I see this occurs for me (ION2 platform) I have to reboot (restart xbmc does not help) since the alsa audio device will no longer accept reasonable amounts of data. The visible pausing behaviour is probably because you have xbmc setup to sync video to audio clock and thus the video is trying to follow the messed up audio.

[burgemaster]

Thanks mate will have a look at that.. I was thinking that it maybe something around this area as there is an 11sec gap between the 2 logs. And thats exatcly how long the video paused for.
...but i dont know what im looking at lol !

15:51:13 T:1520429936 M:859193344 WARNING: CALSADirectSound::CALSADirectSound - device is not able to pause playback, will flush and prefix with 0 frames

Theres a 11sec gap in the log here....

15:51:24 T:1530919792 M:831995904 WARNING: Decode - avcodec_decode_video didn't consume the full packet. size: 137372, consumed: 0

[burgemaster]

Ive tried as you suggested turning "Audio sync" to "Video Clock, Drop/Dupe audio"

Still pauses after 9secs, for exactly 11secs then unpauses....

Maybe:
"asked for new data packet, with nothing available"

Can anyone please help?

[TheSwissKnife]

Ive tried as you suggested turning "Audio sync" to "Video Clock, Drop/Dupe audio"

Still pauses after 9secs, for exactly 11secs then unpauses....

Maybe:
"asked for new data packet, with nothing available"

Can anyone please help?

Well large discontinuities I think don't do drop/dupe, regardless of the setting...I need to check that though...

EDIT: 100ms discrepancy between audio pts and dvd clock resync's the clock regardless of the sync method setting. You need to find out why the audio is so slow to render I think.

Try to get/make a file that has only video stream to confirm that plays ok (ideally the same file with audio stream removed)... then you probably know for sure the audio is the issue.