[mythtv-users] Both In progress HD recordings and Live Tv dropping frames on frontend.

Thu May 15 19:10:33 UTC 2014

On 14/05/14 19:51, John wrote:
> On 14/05/14 10:46, Jean-Yves Avenard wrote:
>> On 14 May 2014 05:06, John <reidjr at lineone.net> wrote:
>>
>>> I am intrigued by what the difference is between the frontend being 
>>> in the
>>>
>>> kState_WatchingRecording rather than kState_WatchingPreRecorded, as 
>>> I assume
>>> it is the dBase activity of being in the former state that causes 
>>> the issue.
>>> As the backend shouldnt care if a frontend is watching somthing its
>>> recording, nulling out that activity seems to make sense.
>> as far as the FE is concerned, it makes no difference except that it
>> will know if it needs to query the database for seek tables.
>>
>> your BE is obviously too busy to properly serve files while also 
>> recording
>>
> Thanks for your reply.
>
> I think it is more subtle than that. I carried out some further tests 
> after reading your reply.
>
> I can record 4 simultaneous HD programmes on my backend and watch any 
> one of them on the frontend on the same physical machine (Core2duo 
> with intel graphics).
>
> The revo Atom/Ion frontend can also watch a PRE-recorded stream from 
> the backend while all 4 other programmes are being recorded.
>
> If I try to watch an in-progress recording I get visible judder and 
> dropped frames as per my initial post. This doese not apear to be 
> better or worse if I am recording 1 or 4 programmes.
>
> So there is something fundamentally different about playing an in 
> progress recording which is causing the dropped frames, it is not the 
> fact that the backend itself is busy with other tasks. It could be 
> some sort of blocking of serving and recording the same stream of 
> course, as suggested above, but mounting the backend root without 
> barriers made no difference. I have tried logging with playback and 
> database, but I cant diagnose the cause of the drops.
>
> [An odd discovery, and potential red herring  is that turning off 
> interlacing on the Atom frontend seems to stop the dropped frames for 
> the in-progress recordings. The same recording ( when complete) can be 
> watched with VDPAU Temporal 2x de-interlacing. ]
>
>
> John

Further followup. I repeated the test Angela tried in

https://code.mythtv.org/trac/ticket/12016

Created a donor recording, which was then stopped. Then removed the donor mpg file, and created a hard link to an in progress recording - I then had two entries in the recording screen one for the in progress recording (real) and one for the donor file, which is linked to the same (still recording) Fake file. The hard link recording uses the database entries and state of the donor recording that has been deleted.

Playing back the hard link, no drops.
Playing back the real in progress recording, drops.

Attached trace shows watching same recording for 30 secs or so as a "Fake" WatchingPreRecorded, and a similer length of time as the "Real" WatchingRecording
Same mpg file, diffrent behaviour.

May 15 19:37:08 revo mythfrontend.real: mythfrontend[4022]: I CoreContext tv_play.cpp:2201 (HandleStateChange) TV: Attempting to change from None to WatchingPreRecorded
May 15 19:37:08 revo mythfrontend.real: mythfrontend[4022]: I CoreContext tv_play.cpp:5558 (StartPlayer) TV: StartPlayer(0, WatchingPreRecorded, main) -- begin
May 15 19:37:09 revo mythfrontend.real: mythfrontend[4022]: I CoreContext decoderbase.cpp:348 (SyncPositionMap) Dec: Resyncing position map. posmapStarted = 0 livetv(0) watchingRec(0)
May 15 19:37:10 revo mythfrontend.real: mythfrontend[4022]: I CoreContext tv_play.cpp:5602 (StartPlayer) TV: StartPlayer(0, WatchingPreRecorded, main) -- end ok
May 15 19:37:10 revo mythfrontend.real: mythfrontend[4022]: I CoreContext tv_play.cpp:2459 (HandleStateChange) TV: Changing from None to WatchingPreRecorded
May 15 19:37:12 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(6): Video is 3.3698 frames behind audio (too slow), dropping frame to catch up.
May 15 19:37:12 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(6): Video is 3.5086 frames behind audio (too slow), dropping frame to catch up.
May 15 19:37:12 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(6): Video is 3.3877 frames behind audio (too slow), dropping frame to catch up.
May 15 19:37:12 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(6): Video is 3.05953 frames behind audio (too slow), dropping frame to catch up.
May 15 19:37:38 revo mythfrontend.real: mythfrontend[4022]: I CoreContext decoderbase.cpp:348 (SyncPositionMap) Dec: Resyncing position map. posmapStarted = 1 livetv(0) watchingRec(0)
May 15 19:39:55 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(6): Video is 3.1126 frames behind audio (too slow), dropping frame to catch up.
May 15 19:39:55 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(6): Video is 3.01958 frames behind audio (too slow), dropping frame to catch up.
May 15 19:40:26 revo mythfrontend.real: mythfrontend[4022]: I CoreContext tv_play.cpp:2201 (HandleStateChange) TV: Attempting to change from WatchingPreRecorded to None
May 15 19:40:27 revo mythfrontend.real: mythfrontend[4022]: I CoreContext tv_play.cpp:2459 (HandleStateChange) TV: Changing from WatchingPreRecorded to None
May 15 19:40:30 revo mythfrontend.real: mythfrontend[4022]: I CoreContext tv_play.cpp:2201 (HandleStateChange) TV: Attempting to change from None to WatchingPreRecorded
May 15 19:40:30 revo mythfrontend.real: mythfrontend[4022]: I CoreContext tv_play.cpp:5558 (StartPlayer) TV: StartPlayer(0, WatchingPreRecorded, main) -- begin
May 15 19:40:31 revo mythfrontend.real: mythfrontend[4022]: I CoreContext decoderbase.cpp:348 (SyncPositionMap) Dec: Resyncing position map. posmapStarted = 0 livetv(0) watchingRec(0)
May 15 19:40:32 revo mythfrontend.real: mythfrontend[4022]: I CoreContext tv_play.cpp:5602 (StartPlayer) TV: StartPlayer(0, WatchingPreRecorded, main) -- end ok
May 15 19:40:32 revo mythfrontend.real: mythfrontend[4022]: I CoreContext tv_play.cpp:2459 (HandleStateChange) TV: Changing from None to WatchingPreRecorded
May 15 19:41:49 revo mythfrontend.real: mythfrontend[4022]: I CoreContext tv_play.cpp:2201 (HandleStateChange) TV: Attempting to change from WatchingPreRecorded to None
May 15 19:41:49 revo mythfrontend.real: mythfrontend[4022]: I CoreContext tv_play.cpp:2459 (HandleStateChange) TV: Changing from WatchingPreRecorded to None
May 15 19:41:53 revo mythfrontend.real: mythfrontend[4022]: I CoreContext tv_play.cpp:2201 (HandleStateChange) TV: Attempting to change from None to WatchingRecording
May 15 19:41:53 revo mythfrontend.real: mythfrontend[4022]: I CoreContext tv_play.cpp:5558 (StartPlayer) TV: StartPlayer(0, WatchingRecording, main) -- begin
May 15 19:41:54 revo mythfrontend.real: mythfrontend[4022]: I CoreContext decoderbase.cpp:348 (SyncPositionMap) Dec: Resyncing position map. posmapStarted = 0 livetv(0) watchingRec(1)
May 15 19:41:54 revo mythfrontend.real: mythfrontend[4022]: I CoreContext decoderbase.cpp:365 (SyncPositionMap) Dec: SyncPositionMap watchingrecording, from DB: 426 entries
May 15 19:41:54 revo mythfrontend.real: mythfrontend[4022]: I CoreContext decoderbase.cpp:379 (SyncPositionMap) Dec: SyncPositionMap watchingrecording total: 431 entries
May 15 19:41:56 revo mythfrontend.real: mythfrontend[4022]: I CoreContext tv_play.cpp:5602 (StartPlayer) TV: StartPlayer(0, WatchingRecording, main) -- end ok
May 15 19:41:56 revo mythfrontend.real: mythfrontend[4022]: I CoreContext tv_play.cpp:2459 (HandleStateChange) TV: Changing from None to
WatchingPreRecorded
May 15 19:41:57 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 4.225 frames behind audio (too slow), dropping frame to catch up.
May 15 19:41:57 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 5.29375 frames behind audio (too slow), dropping frame to catch up.
May 15 19:41:57 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 5.86405 frames behind audio (too slow), dropping frame to catch up.
May 15 19:41:57 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 6.07303 frames behind audio (too slow), dropping frame to catch up.
May 15 19:41:57 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 5.51725 frames behind audio (too slow), dropping frame to catch up.
May 15 19:41:57 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 4.86293 frames behind audio (too slow), dropping frame to catch up.
May 15 19:41:57 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 4.12218 frames behind audio (too slow), dropping frame to catch up.
May 15 19:41:57 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.34788 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:04 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.05052 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:06 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.04888 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:10 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.7265 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:10 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 4.11363 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:10 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 4.16645 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:10 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.97482 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:10 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.56235 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:10 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.02175 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:13 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.15275 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:13 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.1708 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:14 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.40355 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:14 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 4.0714 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:14 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 4.3473 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:14 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 4.31047 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:14 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 4.04535 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:18 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.20445 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:18 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.57207 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:18 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.6103 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:18 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.40147 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:18 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.0136 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:22 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.11013 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:22 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.37632 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:22 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.36348 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:22 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.1351 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:23 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.27367 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:23 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.40525 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:23 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.25393 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:27 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.491 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:27 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.7745 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:27 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.74962 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:27 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.4997 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:27 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.07477 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:37 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.1616 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:37 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.3962 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:37 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.2909 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:43 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.15972 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:43 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.48228 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:43 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.4742 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:43 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.21815 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:48 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.16267 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:48 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.472 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:48 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.48525 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:48 revo mythfrontend.real: mythfrontend[4022]: I CoreContext mythplayer.cpp:1879 (AVSync) Player(5): Video is 3.25767 frames behind audio (too slow), dropping frame to catch up.
May 15 19:42:50 revo mythfrontend.real: mythfrontend[4022]: I CoreContext decoderbase.cpp:348 (SyncPositionMap) Dec: Resyncing position map. posmapStarted = 1 livetv(0) watchingRec(1)
May 15 19:42:50 revo mythfrontend.real: mythfrontend[4022]: I CoreContext decoderbase.cpp:379 (SyncPositionMap) Dec: SyncPositionMap watchingrecording total: 462 entries
May 15 19:42:51 revo mythfrontend.real: mythfrontend[4022]: I CoreContext tv_play.cpp:2201 (HandleStateChange) TV: Attempting to change from WatchingRecording to None
May 15 19:42:51 revo mythfrontend.real: mythfrontend[4022]: I CoreContext tv_play.cpp:2459 (HandleStateChange) TV: Changing from WatchingRecording to None
May 15 19:42:54 revo mythfrontend.real: mythfrontend[4022]: I CoreContext tv_play.cpp:2201 (HandleStateChange) TV: Attempting to change from None to WatchingPreRecorded
May 15 19:42:54 revo mythfrontend.real: mythfrontend[4022]: I CoreContext tv_play.cpp:5558 (StartPlayer) TV: StartPlayer(0, WatchingPreRecorded, main) -- begin
May 15 19:42:55 revo mythfrontend.real: mythfrontend[4022]: I CoreContext decoderbase.cpp:348 (SyncPositionMap) Dec: Resyncing position map. posmapStarted = 0 livetv(0) watchingRec(0)
May 15 19:42:56 revo mythfrontend.real: mythfrontend[4022]: I CoreContext tv_play.cpp:5602 (StartPlayer) TV: StartPlayer(0, WatchingPreRecorded, main) -- end ok
May 15 19:42:56 revo mythfrontend.real: mythfrontend[4022]: I CoreContext tv_play.cpp:2459 (HandleStateChange) TV: Changing from None to WatchingPreRecorded

Any ideas ?