[confirm] Dropped frames after watching Live TV for long period of time (1 Viewer)

[wonkyd]

MediaPortal Version: v1.1.0 RC6
MediaPortal Skin: Maya SVN
Windows Version: Windows 7 Home Premium
CPU Type: AMD X2 4200+
HDD: Hitachi 120Gb, Samsung 500Gb, Samsung 1Tb
Memory: 4GB OCZ DDR2 800Mhz
Motherboard: Abit A-N78HD
Video Card: nVidia Geforce GT220
Video Card Driver: nVidia Forceware 257.21
Sound Card: nVidia HDMI
Sound Card AC3:
Sound Card Driver: nVidia HDMI 1.00.00.59
1. TV Card: Hauppauge Nova TD-500
1. TV Card Type: DVB-T
1. TV Card Driver: BDA
2. TV Card: FloppyDTV S2
2. TV Card Type: DVB-S/S2
2. TV Card Driver: V5.7
MPEG2 Video Codec: MS DTV Codec
MPEG2 Audio Codec: FFDshow
h.264 Video Codec: MS DTV Codec / FFDshow
Satellite/CableTV Provider: Astra 28.2°E/28.5°E
HTPC Case: Antec Fusion v2
Cooling: Scythe Mini Ninja, 1x Noctua Cooling Fan & 2x Noctua 800RPM Case Fans
Power Supply: Antec 430W
Remote: Logitech Harmony 525 Universal Remote
TV: Sony KDL-32U3000
TV - HTPC Connection: HDMI @ 720p 50Hz

Hi,

I was watching TV last night, BBC THREE from around 00:00 to 01:40 and between 00:45 and 01:15 video started to drop frames heavily, becoming a slide show. This persisted for about 5 to 10 minutes until it managed to recover itself.

Something interesting to note from the Windows event log is that at 01:00 windows did an online time sync and adjusted the time (looks like less than 1 second adjustment).

Also at 01:00 an application (Windows Assessment Tool) made a request to disable the Desktop Window Manager but was unable to start as composition was disabled by a running application

I don't run any other programs on my HTPC other than MediaPortal, it's dedicated to the task.

Annoyingly the EVR.log seems to have been overwritten this morning, so there is no logs from that. It did show a lot of corrected/late frames between 01:00 and 01:15, significantly starting at 01:00. Please find remaining logs attached.

P.S not sure if this is related to https://forum.team-mediaportal.com/...-glitches-livetv-both-sd-hd-83762/index3.html

 

[elliottmc]

MediaPortal Version: v1.1.0 RC6
MediaPortal Skin: Maya SVN
Windows Version: Windows 7 Home Premium
CPU Type: AMD X2 4200+
HDD: Hitachi 120Gb, Samsung 500Gb, Samsung 1Tb
Memory: 4GB OCZ DDR2 800Mhz
Motherboard: Abit A-N78HD
Video Card: nVidia Geforce GT220
Video Card Driver: nVidia Forceware 257.21
Sound Card: nVidia HDMI
Sound Card AC3:
Sound Card Driver: nVidia HDMI 1.00.00.59
1. TV Card: Hauppauge Nova TD-500
1. TV Card Type: DVB-T
1. TV Card Driver: BDA
2. TV Card: FloppyDTV S2
2. TV Card Type: DVB-S/S2
2. TV Card Driver: V5.7
MPEG2 Video Codec: MS DTV Codec
MPEG2 Audio Codec: FFDshow
h.264 Video Codec: MS DTV Codec / FFDshow
Satellite/CableTV Provider: Astra 28.2°E/28.5°E
HTPC Case: Antec Fusion v2
Cooling: Scythe Mini Ninja, 1x Noctua Cooling Fan & 2x Noctua 800RPM Case Fans
Power Supply: Antec 430W
Remote: Logitech Harmony 525 Universal Remote
TV: Sony KDL-32U3000
TV - HTPC Connection: HDMI @ 720p 50Hz

Hi,

I was watching TV last night, BBC THREE from around 00:00 to 01:40 and between 00:45 and 01:15 video started to drop frames heavily, becoming a slide show. This persisted for about 5 to 10 minutes until it managed to recover itself.

Something interesting to note from the Windows event log is that at 01:00 windows did an online time sync and adjusted the time (looks like less than 1 second adjustment).

Also at 01:00 an application (Windows Assessment Tool) made a request to disable the Desktop Window Manager but was unable to start as composition was disabled by a running application

I don't run any other programs on my HTPC other than MediaPortal, it's dedicated to the task.

Annoyingly the EVR.log seems to have been overwritten this morning, so there is now logs from that. It did show a lot of corrected/late frames between 01:00 and 01:15, significantly starting at 01:00. Please find remaining logs attached.

P.S not sure if this is related to https://forum.team-mediaportal.com/...-glitches-livetv-both-sd-hd-83762/index3.html

When this happens, try skipping back 15 seconds and then forward and see if this help.

Good reporting about the online time sync. Does it happen any other time?

Mark

 

[Owlsroost]

Does it stop if you pause TV briefly (so that there is more data in the timeshift buffer) ?

I sometimes get this problem after changing channels - pausing for a second fixes it - when it happens to me the dshowhelper.dll is just running out of data, so I suspect it's a timeshift buffer management problem.

Tony

 

[wonkyd]

When this happens, try skipping back 15 seconds and then forward and see if this help.

Good reporting about the online time sync. Does it happen any other time?

Mark

Usually that is what I would do, I was curious to see if it would recover. It did after around 5-10 minutes. Can't say it's ever happened before, I'll post back if it does. I just thought the time sync was an interesting coincidence, especially after reading that other thread.

Does it stop if you pause TV briefly (so that there is more data in the timeshift buffer) ?

I sometimes get this problem after changing channels - pausing for a second fixes it - when it happens to me the dshowhelper.dll is just running out of data, so I suspect it's a timeshift buffer management problem.

Tony

I've not experienced it after changing channels, will see if pausing it or jumping back 15 seconds fixes it if it happens again.

 

[snoekieboe]

Multiple people are experiencing the same issues ( with the same lines in the logs ) but so for no one from the MP team explained what the following lines in our logs mean, and what they could be caused by:

See the "Continous glitches in LiveTV (both SD & HD)" topic.

The following lines are copied from the TSreader logfile.

11-07-2010 19:16:23.865 [fc0]Audio Samples : 7, First : 0.088, Last : 0.728
11-07-2010 19:16:23.866 [fc0]Video Samples : 6, First : 1.614, Last : 1.794
11-07-2010 19:16:23.866 [fc0]Compensation : ( Rnd : 0 mS ) Audio pts greatly ahead Video pts . Add 1.086 sec of extra video comp to start now !...( real time TV )
11-07-2010 19:16:23.866 [fc0]aud:Compensation:0.528, Clock on start 0.000 m_rtStart:0
11-07-2010 19:16:23.871 [fc0]aud:set discontinuity
11-07-2010 19:16:23.871 [fc0]Aud/Ref : 0.536, Late Compensated = 0.008 ( 0.008 A/V buffers=03/06), Clk : 0.000000, State 1
11-07-2010 19:16:23.877 [fc0]Aud/Ref : 0.632, Late Compensated = 0.104 ( 0.104 A/V buffers=03/10), Clk : 0.000000, State 1
11-07-2010 19:16:23.884 [fc0]Aud/Ref : 0.728, Late Compensated = 0.200 ( 0.200 A/V buffers=04/22), Clk : 0.000000, State 1
11-07-2010 19:16:23.889 [fbc]Demux : Video to render 1.846 Sec
11-07-2010 19:16:23.890 [fbc]vid:set discontinuity
11-07-2010 19:16:23.890 [fc0]Aud/Ref : 0.824, Late Compensated = 0.296 ( 0.296 A/V buffers=04/34), Clk : 0.000000, State 1
11-07-2010 19:16:23.890 [fbc]Vid/Ref : 1.614, Late I-frame(00), Compensated = 0.000 ( 0.000 A/V buffers=04/41), Clk : 0.000000, State 1
11-07-2010 19:16:23.898 [fc0]Aud/Ref : 0.952, Late Compensated = 0.424 ( 0.424 A/V buffers=04/40), Clk : 0.000000, State 1
11-07-2010 19:16:23.904 [fc0]Aud/Ref : 1.048, Late Compensated = 0.520 ( 0.520 A/V buffers=03/40), Clk : 0.000000, State 1
11-07-2010 19:16:23.919 [fc0]Aud/Ref : 1.144, Late Compensated = 0.616 ( 0.616 A/V buffers=02/40), Clk : 0.000000, State 1
11-07-2010 19:16:23.925 [fc0]Aud/Ref : 1.240, Late Compensated = 0.712 ( 0.712 A/V buffers=01/40), Clk : 0.000000, State 1
11-07-2010 19:16:23.943 [fbc]Demux : Audio to render 0.840 Sec
11-07-2010 19:16:23.945 [fbc]Vid/Ref : 1.634, Late ?-frame(00), Compensated = 0.060 ( 0.060 A/V buffers=01/41), Clk : 0.000000, State 1
11-07-2010 19:16:23.951 [fbc]Vid/Ref : 1.774, Late ?-frame(00), Compensated = 0.480 ( 0.480 A/V buffers=01/41), Clk : 0.000000, State 1
11-07-2010 19:16:23.953 [fbc]Vid/Ref : 1.794, Late ?-frame(00), Compensated = 0.540 ( 0.540 A/V buffers=01/40), Clk : 0.000000, State 1
11-07-2010 19:16:23.955 [fbc]Vid/Ref : 1.694, Late ?-frame(00), Compensated = 0.240 ( 0.240 A/V buffers=01/39), Clk : 0.000000, State 1
11-07-2010 19:16:23.957 [fbc]Vid/Ref : 1.714, Late ?-frame(00), Compensated = 0.300 ( 0.300 A/V buffers=01/38), Clk : 0.000000, State 1
11-07-2010 19:16:23.959 [fbc]Vid/Ref : 1.654, Late ?-frame(00), Compensated = 0.120 ( 0.120 A/V buffers=01/37), Clk : 0.000000, State 1
11-07-2010 19:16:23.961 [fbc]Vid/Ref : 1.674, Late ?-frame(00), Compensated = 0.180 ( 0.180 A/V buffers=00/36), Clk : 0.000000, State 1
11-07-2010 19:16:23.964 [fc0]Aud/Ref : 1.368, Late Compensated = 0.840 ( 0.840 A/V buffers=01/36), Clk : 0.000000, State 1
11-07-2010 19:16:23.965 [fbc]Vid/Ref : 1.734, Late ?-frame(00), Compensated = 0.360 ( 0.360 A/V buffers=00/35), Clk : 0.000000, State 1
11-07-2010 19:16:23.967 [fbc]Vid/Ref : 1.754, Late ?-frame(00), Compensated = 0.420 ( 0.420 A/V buffers=00/34), Clk : 0.000000, State 1
11-07-2010 19:16:23.968 [b2c]CTsReaderFilter::Run(98565.16) state 1 seeking 0
11-07-2010 19:16:23.968 [b2c]Elapsed time from pause to Audio/Video ( total zapping time ) : 98565144 mS
11-07-2010 19:16:23.969 [b2c]CTsReaderFilter::Run(98565.16) state 2 -->done
11-07-2010 19:16:23.969 [fbc]Vid/Ref : 1.934, Late ?-frame(00), Compensated = 0.960 ( 0.960 A/V buffers=00/33), Clk : 0.000000, State 2
11-07-2010 19:16:24.012 [fc0]audDVBSubtitleFilter->SetTimeCompensation
11-07-2010 19:16:24.018 [fc0]Aud/Ref : 1.464, Late Compensated = 0.936 ( 0.889 A/V buffers=01/38), Clk : 0.047000, State 2
11-07-2010 19:16:24.106 [fbc]Vid/Ref : 1.954, Late ?-frame(00), Compensated = 1.020 ( 0.916 A/V buffers=00/40), Clk : 0.104000, State 2
11-07-2010 19:16:24.108 [fbc]Vid/Ref : 1.854, Late ?-frame(00), Compensated = 0.720 ( 0.616 A/V buffers=00/39), Clk : 0.104000, State 2
11-07-2010 19:16:24.109 [fbc]Vid/Ref : 1.874, Late ?-frame(00), Compensated = 0.780 ( 0.676 A/V buffers=00/38), Clk : 0.104000, State 2
11-07-2010 19:16:24.114 [fbc]Vid/Ref : 1.814, Late ?-frame(00), Compensated = 0.600 ( 0.496 A/V buffers=00/37), Clk : 0.104000, State 2
11-07-2010 19:16:24.120 [fbc]Vid/Ref : 1.834, Late ?-frame(00), Compensated = 0.660 ( 0.552 A/V buffers=00/38), Clk : 0.108000, State 2
11-07-2010 19:16:24.123 [fbc]Vid/Ref : 1.894, Late ?-frame(00), Compensated = 0.840 ( 0.732 A/V buffers=00/37), Clk : 0.108000, State 2
11-07-2010 19:16:24.124 [fc0]Aud/Ref : 1.560, Late Compensated = 1.032 ( 0.924 A/V buffers=01/38), Clk : 0.108000, State 2
11-07-2010 19:16:24.126 [fbc]Vid/Ref : 1.914, Late ?-frame(00), Compensated = 0.900 ( 0.792 A/V buffers=00/36), Clk : 0.108000, State 2
11-07-2010 19:16:24.128 [fbc]Vid/Ref : 2.094, Late ?-frame(00), Compensated = 1.440 ( 1.332 A/V buffers=00/35), Clk : 0.108000, State 2
11-07-2010 19:16:24.131 [fbc]Vid/Ref : 2.114, Late ?-frame(00), Compensated = 1.500 ( 1.392 A/V buffers=00/34), Clk : 0.108000, State 2
11-07-2010 19:16:24.135 [fbc]Vid/Ref : 2.014, Late ?-frame(00), Compensated = 1.200 ( 1.076 A/V buffers=00/33), Clk : 0.124000, State 2
11-07-2010 19:16:24.139 [fbc]Vid/Ref : 2.034, Late ?-frame(00), Compensated = 1.260 ( 1.146 A/V buffers=00/32), Clk : 0.114000, State 2
11-07-2010 19:16:24.255 [fc0]Aud/Ref : 1.688, Late Compensated = 1.160 ( 0.976 A/V buffers=01/37), Clk : 0.184208, State 2
11-07-2010 19:16:24.323 [fbc]Vid/Ref : 1.974, Late ?-frame(00), Compensated = 1.080 ( 0.823 A/V buffers=00/43), Clk : 0.257000, State 2
11-07-2010 19:16:24.325 [fbc]Vid/Ref : 1.994, Late ?-frame(00), Compensated = 1.140 ( 0.883 A/V buffers=00/42), Clk : 0.257000, State 2
11-07-2010 19:16:24.327 [fbc]Vid/Ref : 2.054, Late ?-frame(00), Compensated = 1.320 ( 1.063 A/V buffers=00/41), Clk : 0.257000, State 2
11-07-2010 19:16:24.329 [fbc]Vid/Ref : 2.074, Late ?-frame(00), Compensated = 1.380 ( 1.120 A/V buffers=00/40), Clk : 0.260000, State 2
11-07-2010 19:16:24.330 [fbc]Vid/Ref : 2.254, Late ?-frame(00), Compensated = 1.726 ( 1.466 A/V buffers=00/39), Clk : 0.260000, State 2
11-07-2010 19:16:24.331 [fbc]Vid/Ref : 2.274, Late ?-frame(00), Compensated = 1.746 ( 1.486 A/V buffers=00/38), Clk : 0.260000, State 2
11-07-2010 19:16:24.332 [fbc]Vid/Ref : 2.174, Late ?-frame(00), Compensated = 1.646 ( 1.386 A/V buffers=00/37), Clk : 0.260000, State 2
11-07-2010 19:16:24.333 [fbc]Vid/Ref : 2.194, Late ?-frame(00), Compensated = 1.666 ( 1.406 A/V buffers=00/36), Clk : 0.260000, State 2
11-07-2010 19:16:24.334 [fbc]Vid/Ref : 2.134, Late ?-frame(00), Compensated = 1.560 ( 1.285 A/V buffers=00/35), Clk : 0.275000, State 2
11-07-2010 19:16:24.335 [fbc]Vid/Ref : 2.154, Late ?-frame(00), Compensated = 1.620 ( 1.345 A/V buffers=00/34), Clk : 0.275000, State 2
11-07-2010 19:16:24.336 [fbc]Vid/Ref : 2.214, Late ?-frame(00), Compensated = 1.686 ( 1.411 A/V buffers=00/33), Clk : 0.275000, State 2
11-07-2010 19:16:24.337 [fbc]Vid/Ref : 2.234, Late ?-frame(00), Compensated = 1.706 ( 1.431 A/V buffers=00/32), Clk : 0.275000, State 2
11-07-2010 19:16:24.338 [fbc]Vid/Ref : 2.414, Late ?-frame(00), Compensated = 1.886 ( 1.611 A/V buffers=00/31), Clk : 0.275000, State 2
11-07-2010 19:16:24.339 [fbc]Vid/Ref : 2.434, Late ?-frame(00), Compensated = 1.906 ( 1.631 A/V buffers=00/30), Clk : 0.275000, State 2
11-07-2010 19:16:24.340 [fbc]Vid/Ref : 2.334, Late ?-frame(00), Compensated = 1.806 ( 1.531 A/V buffers=00/29), Clk : 0.275000, State 2
11-07-2010 19:16:24.353 [fc0]Aud/Ref : 1.784, Late Compensated = 1.256 ( 0.961 A/V buffers=01/29), Clk : 0.295000, State 2
11-07-2010 19:16:24.380 [fbc]Vid/Ref : 2.354, Late ?-frame(00), Compensated = 1.826 ( 1.512 A/V buffers=00/29), Clk : 0.313896, State 2
11-07-2010 19:16:24.381 [fbc]Vid/Ref : 2.294, Late ?-frame(00), Compensated = 1.766 ( 1.437 A/V buffers=00/28), Clk : 0.328896, State 2
11-07-2010 19:16:24.460 [fc0]Aud/Ref : 1.880, Late Compensated = 1.352 ( 0.947 A/V buffers=01/27), Clk : 0.404896, State 2
11-07-2010 19:16:24.500 [fbc]Vid/Ref : 2.314, Late ?-frame(00), Compensated = 1.786 ( 1.354 A/V buffers=00/27), Clk : 0.432312, State 2
11-07-2010 19:16:24.501 [fbc]Vid/Ref : 2.374, Late ?-frame(00), Compensated = 1.846 ( 1.414 A/V buffers=00/26), Clk : 0.432312, State 2
11-07-2010 19:16:24.558 [fc0]Aud/Ref : 1.976, Late Compensated = 1.448 ( 0.959 A/V buffers=01/26), Clk : 0.489312, State 2
11-07-2010 19:16:24.654 [fc0]Aud/Ref : 2.104, Late Compensated = 1.576 ( 0.992 A/V buffers=01/30), Clk : 0.583917, State 2
11-07-2010 19:16:24.664 [fbc]Vid/Ref : 2.394, Late ?-frame(00), Compensated = 1.866 ( 1.266 A/V buffers=00/32), Clk : 0.599917, State 2
11-07-2010 19:16:24.665 [fbc]Vid/Ref : 2.574, Late ?-frame(00), Compensated = 2.046 ( 1.446 A/V buffers=00/31), Clk : 0.599917, State 2
11-07-2010 19:17:24.082 [fc0]Demux : Video to render 1.835 Sec
11-07-2010 19:17:54.445 [fc0]Demux : Video to render 1.820 Sec
11-07-2010 19:18:49.440 [fc0]Demux : Video to render 1.751 Sec
11-07-2010 19:18:49.643 [fc0]Demux : Video to render 1.714 Sec
11-07-2010 19:18:49.674 [fc0]Demux : Video to render 1.699 Sec
11-07-2010 19:18:50.042 [fc0]Demux : Video to render 1.660 Sec
11-07-2010 19:22:23.405 [fc0]Demux : Video to render 1.618 Sec
11-07-2010 19:22:23.445 [fc0]Demux : Video to render 1.616 Sec

 

[tourettes]

Multiple people are experiencing the same issues ( with the same lines in the logs ) but so for no one from the MP team explained what the following lines in our logs mean, and what they could be caused by:

Only Ambass can give the 100% correct answer to that question. Unfortunately I haven't seen him in few months...

 

[torbjorns]

30-06-2010 19:15:59.917 [5f4]CTsReaderFilter::ThreadProc start()
30-06-2010 19:15:59.963 [f64] MPEG I-FRAME found 0.638000
30-06-2010 19:15:59.964 [f64] MPEG First '0' frame found. 0.558000
30-06-2010 19:16:00.006 [f64]Audio Samples : 3, First : 0.146, Last : 0.386
30-06-2010 19:16:00.007 [f64]Video Samples : 9, First : 0.558, Last : 0.878
30-06-2010 19:16:00.007 [f64]Compensation : ( Rnd : 0 mS ) Audio pts greatly ahead Video pts . Add 0.372 sec of extra video comp to start now !...( real time TV )
30-06-2010 19:16:00.007 [f64]aud:Compensation:0.186, Clock on start 0.000 m_rtStart:0
30-06-2010 19:16:00.012 [f64]aud:set discontinuity
30-06-2010 19:16:00.012 [f64]Aud/Ref : 0.266, Late Compensated = 0.080 ( 0.080 A/V buffers=02/09), Clk : 0.000000, State 1
30-06-2010 19:16:00.021 [3e8]vid:set discontinuity
30-06-2010 19:16:00.021 [3e8]Vid/Ref : 0.638, Late I-frame(02), Compensated = 0.240 ( 0.240 A/V buffers=03/15), Clk : 0.000000, State 1

I found this in my own TsReader log. So is the dropping frame an audio<-> video sync issue?

 

[god_md5]

maybe the hardisk write and read to hard,you can try other harddisk.
maybe tv signal not good,you can use TSReader to test it,or other check the signal have packet loss or not
if the system time sync ,you can try to stop the internet time sysn.
is gemx tools TsPacketChecker is not have download now?

 

[torbjorns]

maybe the hardisk write and read to hard,you can try other harddisk.
maybe tv signal not good,you can use TSReader to test it,or other check the signal have packet loss or not
if the system time sync ,you can try to stop the internet time sysn.
is gemx tools TsPacketChecker is not have download now?

Thanks for your answer. Is there any way of downloading "gemx tools TsPacketChecker"?
(Im not trying to hijack this thread)

 

[wonkyd]

maybe the hardisk write and read to hard,you can try other harddisk.
maybe tv signal not good,you can use TSReader to test it,or other check the signal have packet loss or not
if the system time sync ,you can try to stop the internet time sysn.
is gemx tools TsPacketChecker is not have download now?

No problems with HDD, manages to keep up with HD H.264 no issues. The machine wasn't doing anything other that time shifting at the time. Auto updates and auto defrag are disabled. TV signal was OK at the time the problem happened, logs show now discontinuity errors.

Could disable Time Sync but not sure if it is the cause or just a coincidence. Still disabling it would be a work around rather that a real solution.

Not seen the TsPacketChecker guessing it would tell me if there were errors in the TSbuffer rather then a problem rendering. The EVR log suggested it was a rendering problem rather than an issue in the TSbuffer though, just wish it hadn't over written it! It did look very much like the log snippets posted above.

Only Ambass can give the 100% correct answer to that question. Unfortunately I haven't seen him in few months...

He has been lurking, his status says he visited about a week ago. Think he last said he was busy with real life...