Ticket #10797: log_analysis.txt

File log_analysis.txt, 7.3 KB (added by David Moore <dmoo1790@…>, 7 years ago)

Analysis of log file

Line 
1        After seeking forwards a couple of minutes from the start of the recording we then try to jump back to the start.
2
32012-06-04 15:58:50.299985 I [2992/2992] CoreContext tv_play.cpp:5828 (DoPlayerSeek) - TV: DoPlayerSeek (-600 seconds)
42012-06-04 15:58:50.304685 I [2992/3048] Decoder avformatdecoder.cpp:3245 (ProcessVideoFrame) - AFD: video timecode 437342682 4859363 4859363 4859323
52012-06-04 15:58:50.305137 I [2992/3048] Decoder avformatdecoder.cpp:4248 (ProcessAudioPacket) - AFD: audio timecode 437350868 437350868 4859454 4859496
62012-06-04 15:58:50.310643 I [2992/3048] Decoder avformatdecoder.cpp:3245 (ProcessVideoFrame) - AFD: video timecode 437349882 4859443 4859443 4859363
7
8        Looks ok up to this point. Video and audio timecodes are similar.
9
10        But then an audio decoding error occurs...
11
122012-06-04 15:58:50.311032 E [2992/3048] Decoder avformatdecoder.cpp:4216 (ProcessAudioPacket) - AFD: Unknown audio decoding error
132012-06-04 15:58:50.311037 E [2992/3048] Decoder avformatdecoder.cpp:4216 (ProcessAudioPacket) - AFD: Unknown audio decoding error
14
15        ...and the audio timecodes jump backwards to much lower values than the video timecodes. This is followed by a bunch of these...
16
172012-06-04 15:58:50.311449 I [2992/3048] Decoder avformatdecoder.cpp:4248 (ProcessAudioPacket) - AFD: audio timecode 424763348 424763348 4719592 4719634
182012-06-04 15:58:50.311880 I [2992/3048] Decoder avformatdecoder.cpp:4248 (ProcessAudioPacket) - AFD: audio timecode 424767188 424767188 4719635 4719677
192012-06-04 15:58:50.312676 I [2992/3048] Decoder avformatdecoder.cpp:4248 (ProcessAudioPacket) - AFD: audio timecode 424774868 424774868 4719720 4719762
20...
212012-06-04 15:58:50.326955 I [2992/3048] Decoder avformatdecoder.cpp:4248 (ProcessAudioPacket) - AFD: audio timecode 424847828 424847828 4720531 4720573
222012-06-04 15:58:50.328009 I [2992/3048] Decoder avformatdecoder.cpp:4248 (ProcessAudioPacket) - AFD: audio timecode 424851668 424851668 4720574 4720616
232012-06-04 15:58:50.328324 I [2992/3048] Decoder avformatdecoder.cpp:4248 (ProcessAudioPacket) - AFD: audio timecode 424855508 424855508 4720616 4720658
24
25        ...which seems to show audio trying to catch up to video.
26
27        But later we get this. Note that audio timecodes have not incremented enough to reach video timecodes. Note the massive audio delay (137+ seconds!).
28
292012-06-04 15:58:50.351111 W [2992/3048] Decoder avformatdecoder.cpp:4346 (GetFrame) - AFD: Audio 137505 ms behind video but already 220 video frames queued. AV-Sync might be broken.
302012-06-04 15:58:50.351306 I [2992/3048] Decoder avformatdecoder.cpp:3245 (ProcessVideoFrame) - AFD: video timecode 437396682 4859963 4859963 4859443
312012-06-04 15:58:50.351763 I [2992/3048] Decoder avformatdecoder.cpp:4248 (ProcessAudioPacket) - AFD: audio timecode 424974548 424974548 4721939 4721981
322012-06-04 15:58:50.352078 I [2992/3048] Decoder avformatdecoder.cpp:4248 (ProcessAudioPacket) - AFD: audio timecode 424978388 424978388 4721982 4722024
332012-06-04 15:58:50.352387 I [2992/3048] Decoder avformatdecoder.cpp:4248 (ProcessAudioPacket) - AFD: audio timecode 424982228 424982228 4722024 4722066
342012-06-04 15:58:50.352692 I [2992/3048] Decoder avformatdecoder.cpp:4248 (ProcessAudioPacket) - AFD: audio timecode 424986068 424986068 4722067 4722109
352012-06-04 15:58:50.353297 W [2992/3048] Decoder avformatdecoder.cpp:4346 (GetFrame) - AFD: Audio 137854 ms behind video but already 220 video frames queued. AV-Sync might be broken.
362012-06-04 15:58:50.355777 I [2992/3048] Decoder avformatdecoder.cpp:3245 (ProcessVideoFrame) - AFD: video timecode 437400282 4860003 4860003 4859963
372012-06-04 15:58:50.355849 W [2992/3048] Decoder avformatdecoder.cpp:4346 (GetFrame) - AFD: Audio 137894 ms behind video but already 220 video frames queued. AV-Sync might be broken.
38
39        ...which carries on for a long time until...
40
41012-06-04 15:58:57.088568 I [2992/3048] Decoder avformatdecoder.cpp:3245 (ProcessVideoFrame) - AFD: video timecode 425048682 4722763 4722763 4722723
422012-06-04 15:58:57.209304 I [2992/3048] Decoder avformatdecoder.cpp:3245 (ProcessVideoFrame) - AFD: video timecode 425052282 4722803 4722803 4722763
432012-06-04 15:58:57.329719 I [2992/3048] Decoder avformatdecoder.cpp:3245 (ProcessVideoFrame) - AFD: video timecode 425055882 4722843 4722843 4722803
442012-06-04 15:58:57.448526 I [2992/3048] Decoder avformatdecoder.cpp:3245 (ProcessVideoFrame) - AFD: video timecode 425059482 4722883 4722883 4722843
452012-06-04 15:58:57.568558 I [2992/3048] Decoder avformatdecoder.cpp:3245 (ProcessVideoFrame) - AFD: video timecode 425063082 4722923 4722923 4722883
462012-06-04 15:58:57.628348 I [2992/2992] CoreContext mythplayer.cpp:1836 (AVSync) - Player(0): Video is 6.32875 frames behind audio (too slow), dropping frame to catch up.
472012-06-04 15:58:57.628458 I [2992/2992] CoreContext mythplayer.cpp:1836 (AVSync) - Player(0): Video is 14.1028 frames behind audio (too slow), dropping frame to catch up.
482012-06-04 15:58:57.628559 I [2992/2992] CoreContext mythplayer.cpp:1836 (AVSync) - Player(0): Video is 19.6833 frames behind audio (too slow), dropping frame to catch up.
492012-06-04 15:58:57.628656 I [2992/2992] CoreContext mythplayer.cpp:1836 (AVSync) - Player(0): Video is 23.6187 frames behind audio (too slow), dropping frame to catch up.
50
51        ...? It seems like video has now fallen behind the audio. Odd. How did the timing for the audio and video pass each other without meeting?
52
53        A bit later on it looks like things have finally synced up.
54
552012-06-04 15:58:57.769470 I [2992/3048] Decoder avformatdecoder.cpp:3245 (ProcessVideoFrame) - AFD: video timecode 425145882 4723843 4723843 4723803
562012-06-04 15:58:57.772547 I [2992/2992] CoreContext mythplayer.cpp:1836 (AVSync) - Player(0): Video is 5.02182 frames behind audio (too slow), dropping frame to catch up.
572012-06-04 15:58:57.775589 I [2992/3048] Decoder avformatdecoder.cpp:3245 (ProcessVideoFrame) - AFD: video timecode 425149482 4723883 4723883 4723843
582012-06-04 15:58:57.782007 I [2992/3048] Decoder avformatdecoder.cpp:3245 (ProcessVideoFrame) - AFD: video timecode 425153082 4723923 4723923 4723883
592012-06-04 15:58:57.788879 I [2992/3048] Decoder avformatdecoder.cpp:3245 (ProcessVideoFrame) - AFD: video timecode 425156682 4723963 4723963 4723923
602012-06-04 15:58:57.795247 I [2992/3048] Decoder avformatdecoder.cpp:3245 (ProcessVideoFrame) - AFD: video timecode 425160282 4724003 4724003 4723963
612012-06-04 15:58:57.801223 I [2992/3048] Decoder avformatdecoder.cpp:3245 (ProcessVideoFrame) - AFD: video timecode 425163882 4724043 4724043 4724003
622012-06-04 15:58:57.807782 I [2992/3048] Decoder avformatdecoder.cpp:3245 (ProcessVideoFrame) - AFD: video timecode 425167482 4724083 4724083 4724043
632012-06-04 15:58:57.808250 I [2992/3048] Decoder avformatdecoder.cpp:4248 (ProcessAudioPacket) - AFD: audio timecode 425174228 425174228 4724158 4724200
642012-06-04 15:58:57.814357 I [2992/3048] Decoder avformatdecoder.cpp:3245 (ProcessVideoFrame) - AFD: video timecode 425171082 4724123 4724123 4724083
652012-06-04 15:58:57.814824 I [2992/3048] Decoder avformatdecoder.cpp:4248 (ProcessAudioPacket) - AFD: audio timecode 425178068 425178068 4724200 4724242
662012-06-04 15:58:57.820681 I [2992/3048] Decoder avformatdecoder.cpp:3245 (ProcessVideoFrame) - AFD: video timecode 425174682 4724163 4724163 4724123
672012-06-04 15:58:57.821130 I [2992/3048] Decoder avformatdecoder.cpp:4248 (ProcessAudioPacket) - AFD: audio timecode 425181908 425181908 4724243 4724285
68