[mythtv-users] Random pauses - log file

Andrew Allison andrew.allison at gmail.com
Mon Nov 7 20:34:27 UTC 2011 

Still trying to track down those random pauses

Here's a copy my frontend log will all logging enabled. It is a video
played from the video folder to help narrow down the problem.

I noticed there is 2 errors listed about 19 lines down.
can not open dri and 
can not open /dev/rtc

About 28 lines from the bottom where the program is waiting for the
buffer to fill.

I'd attach the complete log, but it's 20 meg for a short video.

Thanks in advance.
	Andrew


2011-11-07 14:58:58.761646 I [3970/3970] CoreContext
filtermanager.cpp:82 (FilterManager) - FilterManager: Loading filter
'/usr/local/lib/mythtv/filters/libpostprocess.so'
2011-11-07 14:58:58.761681 I [3970/3970] CoreContext
filtermanager.cpp:82 (FilterManager) - FilterManager: Loading filter
'/usr/local/lib/mythtv/filters/libquickdnr.so'
2011-11-07 14:58:58.761717 I [3970/3970] CoreContext
filtermanager.cpp:82 (FilterManager) - FilterManager: Loading filter
'/usr/local/lib/mythtv/filters/libyadif.so'
2011-11-07 14:58:58.761784 I [3970/3970] CoreContext
filtermanager.cpp:190 (GetFilterInfo) - FilterManager:
GetFilterInfo(convert) returning: 0x0
2011-11-07 14:58:58.761808 I [3970/3970] CoreContext
filtermanager.cpp:190 (GetFilterInfo) - FilterManager:
GetFilterInfo(linearblend) returning: 0x477fae0
2011-11-07 14:58:58.761863 I [3970/3970] CoreContext
videooutbase.cpp:551 (SetupDeinterlace) - VideoOutput: Using deinterlace
method linearblend
2011-11-07 14:58:58.761896 I [3970/3970] CoreContext vsync.cpp:265
(TryInit) - VSYNC: DRMVideoSync: Could not open device /dev/dri/card0,
No such file or directory
2011-11-07 14:58:58.761923 E [3970/3970] CoreContext vsync.cpp:356
(TryInit) - VSYNC: RTCVideoSync: Could not open /dev/rtc:
                        eno: Permission denied (13)
2011-11-07 14:58:58.763072 I [3970/3970] CoreContext mythplayer.cpp:1735
(InitAVSync) - Player(0): Video timing method: USleep with busy wait
2011-11-07 14:58:58.763106 I [3970/3970] CoreContext mythplayer.cpp:1739
(InitAVSync) - Player(0): Display Refresh Rate: 60.002 Video Frame Rate:
29.970
2011-11-07 14:58:58.763126 I [3970/3970] CoreContext mythplayer.cpp:1703
(SetFrameInterval) - Player(0): SetFrameInterval ps:1 scan:1
2011-11-07 14:58:58.763544 I [3970/3970] CoreContext
playercontext.cpp:471 (StartPlaying) - playCtx: StartPlaying(): took 0
ms to start player.
2011-11-07 14:58:58.763586 I [3970/3970] CoreContext tv_play.cpp:4894
(StartPlayer) - TV: Created player.
2011-11-07 14:58:58.763663 I [3970/3970] CoreContext tv_play.cpp:4901
(StartPlayer) - TV: StartPlayer(0, WatchingVideo, main) -- end ok
2011-11-07 14:58:58.763722 I [3970/3970] CoreContext tv_play.cpp:2097
(HandleStateChange) - TV: Changing from None to WatchingVideo
2011-11-07 14:58:58.763770 I [3970/4032] RingBuffer ringbuffer.cpp:853
(run) - RingBuf(/storage1/Videos/Aldo Nova/Aldo Nova - Monkey On Your
Back.mpg): safe_read(... at 4161536, 32768) -> 32768, took 0 ms (1000Mbps)
2011-11-07 14:58:58.765060 I [3970/4034] AudioOutputBase
audio/audiooutputbase.cpp:1588 (OutputAudioLoop) - AO: OutputAudioLoop:
Play Event
2011-11-07 14:58:58.769790 I [3970/4032] RingBuffer ringbuffer.cpp:853
(run) - RingBuf(/storage1/Videos/Aldo Nova/Aldo Nova - Monkey On Your
Back.mpg): safe_read(... at 0, 32768) -> 32768, took 0 ms (1000Mbps)
2011-11-07 14:58:58.771671 I [3970/4035] Decoder
avformatdecoder.cpp:3160 (ProcessVideoFrame) - AFD: video timecode 45000
500 500 0
2011-11-07 14:58:58.772584 I [3970/4035] Decoder
avformatdecoder.cpp:3160 (ProcessVideoFrame) - AFD: video timecode 48003
533 533 500
2011-11-07 14:58:58.773186 I [3970/4035] Decoder
avformatdecoder.cpp:3160 (ProcessVideoFrame) - AFD: video timecode 51006
566 566 533
2011-11-07 14:58:58.774129 I [3970/4035] Decoder
avformatdecoder.cpp:3160 (ProcessVideoFrame) - AFD: video timecode 54009
600 600 566
2011-11-07 14:58:58.774685 I [3970/4035] Decoder
avformatdecoder.cpp:3160 (ProcessVideoFrame) - AFD: video timecode 57012
633 633 600
2011-11-07 14:58:58.774778 I [3970/4032] RingBuffer ringbuffer.cpp:853
(run) - RingBuf(/storage1/Videos/Aldo Nova/Aldo Nova - Monkey On Your
Back.mpg): safe_read(... at 32768, 32768) -> 32768, took 0 ms (1000Mbps)
2011-11-07 14:58:58.775650 I [3970/4035] Decoder
avformatdecoder.cpp:3160 (ProcessVideoFrame) - AFD: video timecode 60015
666 666 633
2011-11-07 14:58:58.776264 I [3970/4035] Decoder
avformatdecoder.cpp:3160 (ProcessVideoFrame) - AFD: video timecode 63018
700 700 666
2011-11-07 14:58:58.777228 I [3970/4035] Decoder
avformatdecoder.cpp:3160 (ProcessVideoFrame) - AFD: video timecode 66021
733 733 700
2011-11-07 14:58:58.777831 I [3970/4035] Decoder
avformatdecoder.cpp:3160 (ProcessVideoFrame) - AFD: video timecode 69024
766 766 733
2011-11-07 14:58:58.777924 I [3970/4035] Decoder
audio/audiooutputbase.cpp:1314 (AddData) - AO: AddData frames=1536,
bytes=6144, used=1, free=3071999, timecode=532 needsupmix=0
2011-11-07 14:58:58.777947 I [3970/4035] Decoder
audio/audiooutputbase.cpp:1078 (SetAudiotime) - AO: SetAudiotime atc=532
tc=532 f=1536 pfu=0 pfs=0
2011-11-07 14:58:58.777953 I [3970/4035] Decoder
avformatdecoder.cpp:4131 (ProcessAudioPacket) - AFD: audio timecode
47880 47880 532 564
2011-11-07 14:58:58.778050 I [3970/4032] RingBuffer ringbuffer.cpp:853
(run) - RingBuf(/storage1/Videos/Aldo Nova/Aldo Nova - Monkey On Your
Back.mpg): safe_read(... at 65536, 32768) -> 32768, took 0 ms (1000Mbps)
2011-11-07 14:58:58.778955 I [3970/4035] Decoder
avformatdecoder.cpp:3160 (ProcessVideoFrame) - AFD: video timecode 72027
800 800 766
2011-11-07 14:58:58.779604 I [3970/4035] Decoder
avformatdecoder.cpp:3160 (ProcessVideoFrame) - AFD: video timecode 75030
833 833 800
2011-11-07 14:58:58.780589 I [3970/4035] Decoder
avformatdecoder.cpp:3160 (ProcessVideoFrame) - AFD: video timecode 78033
867 867 833
2011-11-07 14:58:58.781239 I [3970/4035] Decoder
avformatdecoder.cpp:3160 (ProcessVideoFrame) - AFD: video timecode 81036
900 900 867
2011-11-07 14:58:58.781337 I [3970/4032] RingBuffer ringbuffer.cpp:853
(run) - RingBuf(/storage1/Videos/Aldo Nova/Aldo Nova - Monkey On Your
Back.mpg): safe_read(... at 98304, 32768) -> 32768, took 0 ms (1000Mbps)
2011-11-07 14:58:58.782248 I [3970/4035] Decoder
avformatdecoder.cpp:3160 (ProcessVideoFrame) - AFD: video timecode 84039
933 933 900
2011-11-07 14:58:58.782972 I [3970/4035] Decoder
avformatdecoder.cpp:3160 (ProcessVideoFrame) - AFD: video timecode 87042
967 967 933
2011-11-07 14:58:58.783979 I [3970/4035] Decoder
avformatdecoder.cpp:3160 (ProcessVideoFrame) - AFD: video timecode 90045
1000 1000 967
2011-11-07 14:58:58.784190 I [3970/4032] RingBuffer ringbuffer.cpp:853
(run) - RingBuf(/storage1/Videos/Aldo Nova/Aldo Nova - Monkey On Your
Back.mpg): safe_read(... at 131072, 32768) -> 32768, took 0 ms (1000Mbps)
2011-11-07 14:58:58.784653 I [3970/4035] Decoder
avformatdecoder.cpp:3160 (ProcessVideoFrame) - AFD: video timecode 93048
1033 1033 1000
2011-11-07 14:58:58.784748 I [3970/4035] Decoder
audio/audiooutputbase.cpp:1314 (AddData) - AO: AddData frames=1536,
bytes=6144, used=6145, free=3065855, timecode=564 needsupmix=0
2011-11-07 14:58:58.784759 I [3970/4035] Decoder
audio/audiooutputbase.cpp:1078 (SetAudiotime) - AO: SetAudiotime atc=564
tc=564 f=1536 pfu=0 pfs=0
2011-11-07 14:58:58.784770 I [3970/4035] Decoder
avformatdecoder.cpp:4131 (ProcessAudioPacket) - AFD: audio timecode
50760 50760 564 596
2011-11-07 14:58:58.784845 I [3970/4035] Decoder
avformatdecoder.cpp:2639 (HandleGopStart) - AFD: gopset not set, syncing
positionMap
2011-11-07 14:58:58.784851 I [3970/4035] Decoder decoderbase.cpp:302
(SyncPositionMap) - Dec: Resyncing position map. posmapStarted = 0
livetv(0) watchingRec(0)
2011-11-07 14:58:58.784854 I [3970/4035] Decoder
avformatdecoder.cpp:2645 (HandleGopStart) - AFD: Initial key frame
distance: 15.
2011-11-07 14:58:58.784857 I [3970/4035] Decoder
avformatdecoder.cpp:2704 (HandleGopStart) - AFD: positionMap[ 18 ] ==
165902.
2011-11-07 14:58:58.784983 I [3970/4032] RingBuffer ringbuffer.cpp:853
(run) - RingBuf(/storage1/Videos/Aldo Nova/Aldo Nova - Monkey On Your
Back.mpg): safe_read(... at 163840, 32768) -> 32768, took 0 ms (1000Mbps)
2011-11-07 14:58:58.785355 I [3970/4034] AudioOutputBase
audio/audiooutputbase.cpp:1029 (GetAudiotime) - AO: GetAudiotime
audt=500 atc=564 mb=12288 sb=0 tb=12288 sr=48000 obpf=4 bpf=4 sf=1
1228800000 64
2011-11-07 14:58:58.785403 I [3970/4034] AudioOutputBase
audio/audiooutputalsa.cpp:524 (WriteAudio) - WriteAudio: Preparing 9600
bytes (2400 frames)
2011-11-07 14:58:58.785624 I [3970/4034] AudioOutputBase
audio/audiooutputbase.cpp:1604 (OutputAudioLoop) - AO: audio waiting for
buffer to fill: have 2688 want 9600
2011-11-07 14:58:58.786359 I [3970/4035] Decoder
avformatdecoder.cpp:3160 (ProcessVideoFrame) - AFD: video timecode 96051
1067 1067 1033
2011-11-07 14:58:58.786998 I [3970/4035] Decoder
avformatdecoder.cpp:3160 (ProcessVideoFrame) - AFD: video timecode 99054
1100 1100 1067
2011-11-07 14:58:58.787955 I [3970/4035] Decoder
avformatdecoder.cpp:3160 (ProcessVideoFrame) - AFD: video timecode
102057 1133 1133 1100
2011-11-07 14:58:58.788549 I [3970/4035] Decoder
avformatdecoder.cpp:3160 (ProcessVideoFrame) - AFD: video timecode
105060 1167 1167 1133
2011-11-07 14:58:58.788608 I [3970/4035] Decoder
audio/audiooutputbase.cpp:1314 (AddData) - AO: AddData frames=1536,
bytes=6144, used=2689, free=3069311, timecode=596 needsupmix=0
2011-11-07 14:58:58.788616 I [3970/4035] Decoder
audio/audiooutputbase.cpp:1078 (SetAudiotime) - AO: SetAudiotime atc=596
tc=596 f=1536 pfu=0 pfs=0
2011-11-07 14:58:58.788621 I [3970/4035] Decoder
avformatdecoder.cpp:4131 (ProcessAudioPacket) - AFD: audio timecode
53640 53640 596 628
2011-11-07 14:58:58.788796 I [3970/4032] RingBuffer ringbuffer.cpp:853
(run) - RingBuf(/storage1/Videos/Aldo Nova/Aldo Nova - Monkey On Your
Back.mpg): safe_read(... at 196608, 32768) -> 32768, took 0 ms (1000Mbps)
2011-11-07 14:58:58.789623 I [3970/4035] Decoder
avformatdecoder.cpp:3160 (ProcessVideoFrame) - AFD: video timecode
108063 1200 1200 1167

More information about the mythtv-users mailing list