Watching recorded TV (TS files) pauses/freezes mediaportal for exacly one minute. (1 Viewer)

[ferrocene]

MediaPortal Version: 1.1.3.0
MediaPortal Skin: StreamedMP 1.4.12
Windows Version: Windows Server 2008 R2
CPU Type: i7 @ 3.5GHz
HDD: 60GB SSD, 2TB HDD
Memory: 8GB
Motherboard: Gigabyte P55/LGA-1156
Video Card: NVidia 8800GT
Video Card Driver: 258.96
Sound Card: Onboard Realtek, also M-Audio Audiophile 2496 (not used)
Sound Card AC3:
Sound Card Driver:
1. TV Card: HDHomerun dual tuner (new model)
1. TV Card Type:
1. TV Card Driver:
2. TV Card:
2. TV Card Type:
2. TV Card Driver:
3. TV Card:
3. TV Card Type:
3. TV Card Driver:
4. TV Card:
4. TV Card Type:
4. TV Card Driver:
MPEG2 Video Codec: ffshow, MPC
MPEG2 Audio Codec:
h.264 Video Codec: CoreAVC
Satelite/CableTV Provider:
HTPC Case:
Cooling:
Power Supply:
Remote: Harmony One
TV: Samsung
TV - HTPC Connection: DVI to HDMI


First, I know I'm running 2008 Server - I get the prompt every time I enter Configuration. I'm fairly confident it's not a problem with the OS.

Basically, the HDHomerun records .TS files just fine. Everything works great, except when I play back certain recorded TV shows, such as a 1080i hour-long show, at certain points it will freeze for around 60 seconds. At the 60 second mark, the audio will continue playing as the video does this fast-forward catch-up, at which point it will play fine for awhile until it freezes up again.

I can play the TS files just fine in MPC-HC or VLC. In MediaPortal, I've tried both MPC and ffmpeg codecs, and in ffmpeg I've tried both MPEG2 decoders - libavcodec and libmpeg2. They both do the same thing, although ffmpeg seems to do it less, as odd as that sounds.

In the TsReader-*.log, after playback "resumes", the log file fills up with the following at at rate of 185 lines per second for a few seconds:

28-03-2011 22:36:40.846 [1110]Vid/Ref : 2272.388, Late B-frame(13), Compensated = 157.516 ( -1.982 A/V buffers=308/01), Clk : 159.498077, State 2
28-03-2011 22:36:40.852 [1110]Vid/Ref : 2272.522, Late I-frame(02), Compensated = 157.650 ( -1.833 A/V buffers=308/01), Clk : 159.483078, State 2
28-03-2011 22:36:40.860 [1110]Vid/Ref : 2272.455, Late B-frame(00), Compensated = 157.583 ( -1.900 A/V buffers=308/01), Clk : 159.483078, State 2
28-03-2011 22:36:40.865 [1110]Vid/Ref : 2272.488, Late B-frame(01), Compensated = 157.616 ( -1.883 A/V buffers=308/01), Clk : 159.499084, State 2
28-03-2011 22:36:40.865 [d64]Aud/Ref : 2222.613, Late              Compensated = 107.741 ( -51.758 A/V buffers=308/00), Clk : 159.499084, State 2
28-03-2011 22:36:40.869 [1110]Vid/Ref : 2272.622, Late P-frame(05), Compensated = 157.750 ( -1.733 A/V buffers=308/01), Clk : 159.483078, State 2
28-03-2011 22:36:40.876 [1110]Vid/Ref : 2272.555, Late B-frame(03), Compensated = 157.683 ( -1.800 A/V buffers=308/01), Clk : 159.483078, State 2
28-03-2011 22:36:40.880 [1110]Vid/Ref : 2272.588, Late B-frame(04), Compensated = 157.716 ( -1.782 A/V buffers=308/01), Clk : 159.498077, State 2
28-03-2011 22:36:40.884 [1110]Vid/Ref : 2272.722, Late P-frame(08), Compensated = 157.850 ( -1.648 A/V buffers=308/01), Clk : 159.498077, State 2
28-03-2011 22:36:40.891 [1110]Vid/Ref : 2272.655, Late B-frame(06), Compensated = 157.783 ( -1.700 A/V buffers=308/01), Clk : 159.483078, State 2

As I watch the CPU % and disk quotas, there is a huge spike, but that's while the video is in fast-forward mode and catching up to the audio.

my evr.log for the last 17 minutes has 11,000 lines, 99.99% of which read:

29-03-2011 03:09:06.233 [e28]Scheduling sample from the past (7339.29 ms, last call to NotifyWorker: 3.86 ms)
29-03-2011 03:09:06.233 [d5c]Dropping frame, behind 7339.29 ms, last sleep time 0.00 ms.
29-03-2011 03:09:06.235 [e28]Scheduling sample from the past (7322.61 ms, last call to NotifyWorker: 2.71 ms)
29-03-2011 03:09:06.235 [d5c]Dropping frame, behind 7322.61 ms, last sleep time 0.00 ms.
29-03-2011 03:09:06.237 [e28]Scheduling sample from the past (7305.92 ms, last call to NotifyWorker: 2.17 ms)
29-03-2011 03:09:06.238 [d5c]Dropping frame, behind 7305.92 ms, last sleep time 0.00 ms.
29-03-2011 03:09:06.242 [e28]Scheduling sample from the past (7289.24 ms, last call to NotifyWorker: 4.09 ms)
29-03-2011 03:09:06.242 [d5c]Dropping frame, behind 7289.24 ms, last sleep time 0.00 ms.
29-03-2011 03:09:06.246 [e28]Scheduling sample from the past (7272.56 ms, last call to NotifyWorker: 4.04 ms)
29-03-2011 03:09:06.246 [d5c]Dropping frame, behind 7272.56 ms, last sleep time 0.00 ms.
29-03-2011 03:09:06.249 [e28]Scheduling sample from the past (7255.87 ms, last call to NotifyWorker: 2.94 ms)
29-03-2011 03:09:06.249 [d5c]Dropping frame, behind 7255.87 ms, last sleep time 0.00 ms.

Again, this only happens inside mediaportal. The same codecs in VLC and media player classic don't exhibit this behavior.

This doesn't happen with H.264 or any other codec/video file, just .TS streams. In all cases the audio is being sent out the Realtek S/PDIF interface as Dolby Digital to my HT system.


I have to go to bed, it's 3am. Any help would be appreciated.

Quick update: this problem only seems to happen when mediaportal doesn't have focus. This is on a dual-monitor computer, and if i'm reading this forum on the other monitor, within a few minutes it will freeze up.

The file doesn't freeze up in the same spot, which indicates that the file is ok. I also tested the .TS file with mpeg2repair, and other than the beginning and end, it checks out ok.

I also uninstalled the KLITE codec pack, and I thought that fixed it until it freezed up 20 minutes later when the window didn't have focus.

 

[ferrocene]

The following attachment shows the Wait Chain and Disk I/O during the freezing. It looks like some threads under mediaportal freeze, which locks up the parent thread/process.

Normally the wait chain is always empty for every process. I'm still trying to find the network i/o that it is waiting on that is causing the lockup.

 

[ferrocene]

Ugh, this is so frustrating. It got to the point that I plugged in a mouse, shut down MediaPortal and just used VLC to play back the TS files.

VLC works perfectly, MediaPortal just chokes. I've gone back and changed every option I can find, changed all codec settings, changed decoders, re-installed, no change.

I got excited because a new version of CoreAVC came out, and one of its fixes was to reduce freezing in MediaPortal.

Alas, CoreAVC only does h.264, so it doesn't affect TS files at all which are MPEG2.

I'm at a loss. Everything else works perfectly.

 

[wonkyd]

Have you tried owlsroots directshow helper from the dev forums?

 

[ferrocene]

I haven't heard of it before, i'll do a search, thanks.

 

[Owlsroost]

I don't know if it will help, but you could try using the tsreader.ax from 1.2.0 beta - http://sources.team-mediaportal.com/websvn/filedetails.php?repname=MediaPortal&path=%2Ftrunk%2FDirectShowFilters%2FTsReader%2Fbin%2FRelease%2FTsReader.ax&sc=1 (you'll need VSC++2010 runtime installed). I'd also take a look at https://forum.team-mediaportal.com/submit-code-patches-mediaportal-tv-server-etc-325/fix-stuttering-corrupted-streaming-live-tv-91214/

Tony

 

[ferrocene]

Thanks, The funny thing is live TV is perfect, it's just the recorded TV. Which is weird because live TV saves temp data the same way for pausing, etc (i forget what that's called).

I tried the tsreader.ax from the above link. It still randomly locks up. :/

I'm still checking the log files for more info.

 

[wonkyd]

Thanks, The funny thing is live TV is perfect, it's just the recorded TV. Which is weird because live TV saves temp data the same way for pausing, etc (i forget what that's called).

I tried the tsreader.ax from the above link. It still randomly locks up. :/

I'm still checking the log files for more info.

Where your using 2008 R2 have you added the Desktop Experience feature, started the themes service and enabled Aero?

Quick update: this problem only seems to happen when mediaportal doesn't have focus. This is on a dual-monitor computer, and if i'm reading this forum on the other monitor, within a few minutes it will freeze up.

Ah, this may be your problem. MP slows the frame rate when it doesn't have focus and I'm not sure if you can disable that feature. Maybe try enabling "always on top" in the configuration tool? I know people on here use dual monitors all the time so it's definitely possible.

 

[ferrocene]

Thanks, The funny thing is live TV is perfect, it's just the recorded TV. Which is weird because live TV saves temp data the same way for pausing, etc (i forget what that's called).

I tried the tsreader.ax from the above link. It still randomly locks up. :/

I'm still checking the log files for more info.

Where your using 2008 R2 have you added the Desktop Experience feature, started the themes service and enabled Aero?

Yes. It looks exactly like Win7. All my games work on it, etc.

Quick update: this problem only seems to happen when mediaportal doesn't have focus. This is on a dual-monitor computer, and if i'm reading this forum on the other monitor, within a few minutes it will freeze up.

Ah, this may be your problem. MP slows the frame rate when it doesn't have focus and I'm not sure if you can disable that feature. Maybe try enabling "always on top" in the configuration tool? I know people on here use dual monitors all the time so it's definitely possible.

I should remove that update, because it is incorrect. After more extensive testing, it happens when it has focus as well. My girlfriend recently discovered that if we don't fast forward, the problem doesn't happen. I haven't confirmed this yet. I just need to watch an hour-long program from the beginning w/o skipping commercials, and if it never pauses then that's the trigger. I'll post back with an update.

58 second delays are a bit strange.

01-04-2011 20:05:31.934 [22a4]OnClockPause
01-04-2011 20:05:31.959 [22a4]ProcessMessage MFVP_MESSAGE_FLUSH
01-04-2011 20:05:31.959 [c90]Flushing: size=5
01-04-2011 20:05:32.090 [22a4]OnClockRestart
01-04-2011 20:06:37.558 [24c4]Scheduling sample from the past (58223.35 ms, last call to NotifyWorker: 58254.76 ms)
01-04-2011 20:06:37.558 [c90]Dropping frame, behind 58223.37 ms, last sleep time 0.00 ms.
01-04-2011 20:06:37.563 [24c4]Scheduling sample from the past (58210.92 ms, last call to NotifyWorker: 5.31 ms)
01-04-2011 20:06:37.563 [c90]Dropping frame, behind 58210.94 ms, last sleep time 0.00 ms.
01-04-2011 20:06:37.571 [24c4]Scheduling sample from the past (58165.94 ms, last call to NotifyWorker: 8.36 ms)
01-04-2011 20:06:37.571 [c90]Dropping frame, behind 58165.96 ms, last sleep time 0.00 ms.
01-04-2011 20:06:37.597 [24c4]Scheduling sample from the past (58133.76 ms, last call to NotifyWorker: 25.99 ms)
01-04-2011 20:06:37.597 [c90]Dropping frame, behind 58133.79 ms, last sleep time 0.00 ms.
01-04-2011 20:06:37.605 [24c4]Scheduling sample from the past (58058.29 ms, last call to NotifyWorker: 7.91 ms)
01-04-2011 20:06:37.605 [c90]Dropping frame, behind 58058.29 ms, last sleep time 0.00 ms.
01-04-2011 20:06:37.613 [24c4]Scheduling sample from the past (58008.29 ms, last call to NotifyWorker: 8.05 ms)
01-04-2011 20:06:37.613 [c90]Dropping frame, behind 58008.29 ms, last sleep time 0.00 ms.
01-04-2011 20:06:37.624 [24c4]Scheduling sample from the past (57958.32 ms, last call to NotifyWorker: 10.90 ms)
01-04-2011 20:06:37.624 [c90]Dropping frame, behind 57958.32 ms, last sleep time 0.00 ms.
01-04-2011 20:06:37.632 [24c4]Scheduling sample from the past (57908.31 ms, last call to NotifyWorker: 7.99 ms)
01-04-2011 20:06:37.632 [c90]Dropping frame, behind 57908.31 ms, last sleep time 0.00 ms.

And about 1000 lines later:

01-04-2011 20:06:42.580 [c90]Dropping frame, behind 28529.06 ms, last sleep time 0.00 ms.
01-04-2011 20:06:42.589 [24c4]Scheduling sample from the past (28479.06 ms, last call to NotifyWorker: 9.10 ms)
01-04-2011 20:06:42.589 [c90]Dropping frame, behind 28479.06 ms, last sleep time 0.00 ms.
01-04-2011 20:06:42.599 [24c4]Scheduling sample from the past (28429.06 ms, last call to NotifyWorker: 9.45 ms)
01-04-2011 20:06:42.599 [c90]Dropping frame, behind 28429.06 ms, last sleep time 0.00 ms.
01-04-2011 20:06:42.609 [24c4]Scheduling sample from the past (28379.06 ms, last call to NotifyWorker: 10.51 ms)
01-04-2011 20:06:42.609 [c90]Dropping frame, behind 28379.06 ms, last sleep time 0.00 ms.
01-04-2011 20:06:42.610 [22a4]OnClockPause
01-04-2011 20:06:42.618 [24c4]Should not be processing data in pause mode
01-04-2011 20:06:42.618 [1888]Should not be processing data in pause mode
01-04-2011 20:06:43.584 [22a4]OnClockRestart
01-04-2011 20:06:43.585 [1888]Scheduling sample from the past (28319.50 ms, last call to NotifyWorker: 0.43 ms)
01-04-2011 20:06:43.585 [c90]Dropping frame, behind 28319.53 ms, last sleep time 0.00 ms.
01-04-2011 20:06:43.585 [24c4]Scheduling sample from the past (28270.21 ms, last call to NotifyWorker: 1.14 ms)
01-04-2011 20:06:43.585 [c90]Dropping frame, behind 28270.23 ms, last sleep time 0.00 ms.
01-04-2011 20:06:43.588 [24c4]Scheduling sample from the past (28255.90 ms, last call to NotifyWorker: 2.66 ms)
01-04-2011 20:06:43.588 [c90]Dropping frame, behind 28255.92 ms, last sleep time 0.00 ms.
01-04-2011 20:06:43.593 [24c4]dangerous and unlikely time to schedule [11298BA0]: 247857266. scheduled time: 371368864, now: 123511598
01-04-2011 20:06:43.593 [c90]dangerous and unlikely time to schedule [11298BA0]: 247857085. scheduled time: 371368864, now: 123511779
01-04-2011 20:06:43.597 [24c4]dangerous and unlikely time to schedule [11299230]: 247996959. scheduled time: 371528864, now: 123531905
01-04-2011 20:06:43.597 [c90]dangerous and unlikely time to schedule [11298BA0]: 247836781. scheduled time: 371368864, now: 123532083
01-04-2011 20:06:43.599 [24c4]dangerous and unlikely time to schedule [11298CF0]: 248141825. scheduled time: 371698864, now: 123557039
01-04-2011 20:06:43.599 [c90]dangerous and unlikely time to schedule [11298BA0]: 247811614. scheduled time: 371368864, now: 123557250
01-04-2011 20:06:43.604 [24c4]dangerous and unlikely time to schedule [11298D98]: 248296977. scheduled time: 371868864, now: 123571887
01-04-2011 20:06:43.604 [c90]dangerous and unlikely time to schedule [11298BA0]: 247796796. scheduled time: 371368864, now: 123572068
01-04-2011 20:06:43.608 [24c4]dangerous and unlikely time to schedule [11298C48]: 248437765. scheduled time: 372028864, now: 123591099
01-04-2011 20:06:43.608 [c90]dangerous and unlikely time to schedule [11298BA0]: 247777547. scheduled time: 371368864, now: 123591317
01-04-2011 20:06:44.473 [22a4]OnClockPause
01-04-2011 20:06:44.496 [22a4]ProcessMessage MFVP_MESSAGE_FLUSH

 

[Owlsroost]

There are some known issues with FFWD/RWD - 1.2.0 beta will have some fixes for these.

Tony