Watching in progress recording stutters

[angela.schmid@…]

Since upgrading from 0.26-fixes to 0.27-fixes/master watching in progress recordings stutters. This happens with all mediatypes (720p, 1080i, SD) and is 100% reproducible with all in progress recordings.

As soon as the scheduled recording is finished the stuttering finishes. Reusing and playing another finished recording where the file is linked to the in progress recording file there is no stuttering.

I made the following test and attached the frontend.log (--loglevel debug -v general,playback)

01:00 started a 15 minute recording 01:05 watch in progress recording, stuttering 01:15 recording finished, till the end no stuttering (Attempting to change from WatchingRecording? to WatchingPreRecorded?) 01:20 watching finished

01:30 watch finished (prerecorded) recording, no stuttering 01:45 watching finished

I tried to bisect the problem but had stack overflows and avfilter problems from 0.27-pre to 0.27-beta. 0.27-alpha is the first version not crashing, but has stutter, so I stopped to bisect the problem further.

The following dirty hack worked, although the recording only stops after finishing viewing. As it might produce other problems I don’t use it in production.

diff --git a/mythtv/libs/libmythtv/tv_play.cpp b/mythtv/libs/libmythtv/tv_play.cpp
index 77858d0..8ecd918 100644
--- a/mythtv/libs/libmythtv/tv_play.cpp
+++ b/mythtv/libs/libmythtv/tv_play.cpp
@@ -2210,6 +2210,10 @@ void TV::HandleStateChange(PlayerContext *mctx, PlayerContext *ctx)
     TVState ctxState = ctx->GetState();
     TVState desiredNextState = ctx->DequeueNextState();

+    if(desiredNextState == kState_WatchingRecording)
+       desiredNextState = kState_WatchingPreRecorded;
+
     LOG(VB_GENERAL, LOG_INFO, LOC +
         QString("Attempting to change from %1 to %2")
             .arg(StateToString(nextState))

[angela.schmid@…]

mythfrontend.20140114235857.13600.log

[Jim Stichnoth]

This sounds like it might be related to having barriers enabled in the file system that holds your mysql database. A recent thread in the mythtv-users list discusses this:

​http://www.gossamer-threads.com/lists/mythtv/users/561590

Can you check whether the solutions/workarounds in that thread apply to your case?

[angela.schmid@…]

The DB is on a ext3 filesystem to remedy barrier problems: /dev/sda3 on / type ext3 (rw,errors=remount-ro)

It happens on a SSD (prod) as also on a disk (dev).

Everything was fine in 0.26, also livetv worked perfectly. The problem started with 0.27.

It has something to do that for an in progress recording it uses the state WatchingRecording? vs. WatchingPreRecorded? for finished recordings.

[sphery]

ext3 enables barriers by default with some kernels. What is the output of:

cat /proc/mounts

That will show whether barriers are enabled.

[angela.schmid@…]

cat /proc/mounts

rootfs / rootfs rw 0 0
sysfs /sys sysfs rw,nosuid,nodev,noexec,relatime 0 0
proc /proc proc rw,nosuid,nodev,noexec,relatime 0 0
udev /dev tmpfs rw,relatime,mode=755 0 0
devpts /dev/pts devpts rw,nosuid,noexec,relatime,gid=5,mode=620 0 0
tmpfs /run tmpfs rw,nosuid,relatime,size=1602892k,mode=755 0 0
/dev/disk/by-uuid/dc239d71-ef55-4a90-a92e-ce7854347947 / ext3 rw,relatime,errors=remount-ro,data=ordered 0 0
none /proc/sys/fs/binfmt_misc binfmt_misc rw,nosuid,nodev,noexec,relatime 0 0
none /sys/kernel/debug debugfs rw,relatime 0 0
none /run/lock tmpfs rw,nosuid,nodev,noexec,relatime,size=5120k 0 0
none /run/shm tmpfs rw,nosuid,nodev,relatime 0 0
/dev/sda2 /boot ext4 rw,relatime,data=ordered 0 0
/dev/sda5 /home ext4 rw,noatime,data=ordered 0 0
rpc_pipefs /run/rpc_pipefs rpc_pipefs rw,relatime 0 0
/dev/disk/by-uuid/dc239d71-ef55-4a90-a92e-ce7854347947 /srv/share/vdr ext3 rw,relatime,errors=remount-ro,data=ordered 0 0   <--------
/dev/sdb2 /store/store11 ext4 rw,relatime,data=ordered 0 0
/dev/sdb3 /store/store12 ext4 rw,relatime,data=ordered 0 0
/dev/sdb4 /store/store13 ext4 rw,relatime,data=ordered 0 0
/dev/sdc2 /store/store2 ext4 rw,relatime,data=ordered 0 0
/dev/sdd2 /store/store3 ext4 rw,relatime,data=ordered 0 0
/dev/sde2 /store/store9 ext4 rw,relatime,data=ordered 0 0

[jonathan.oexner@…]

I've noticed the same thing since the upgrade to 0.27. It makes live TV or any recording before it's finished nearly unwatchable.

[angela.schmid@…]

Keeping on eye on the FPS displayed with menu->playback->playback data, I see that the stuttering happens exactly every 10 seconds, when the FPS drops (from 50 to around 30-40, 720p@50). Maybe for just about 25% of the occurrences the FPS drops (sometimes also raises) only a little bit, so that the stuttering is not that apparent.

@Jonathan, can you please check my observation.

[blm-ubunet@…]

Angela Your display is set to 60Hz refresh & the video reports as 50Hz. Could this be the cause or trigger?

2014-01-15 01:05:06.223191 I [13600/13600] CoreContext mythplayer.cpp:1790 (InitAVSync) - Player(0): Display Refresh Rate: 60.053 Video Frame Rate: 50.000

Is the log posted (comment #1) representative of the general problem?

Mythtv (from about 0.25) does not handle this situation very well & results in high fps jitter. Why is this worse when viewing in-progress recording? Don't know. Straw that breaks the camel's back?

Try allowing mythtv to change video mode to appropriate refresh rate or patch to fix ​http://code.mythtv.org/trac/ticket/11246

[angela.schmid@…]

This is on an interlaced television

1920x1080 25.0 + 30.0* 30.0

Tested on fresh master: Setting the refresh rate to 25 with xrandr didn't have a change in behaviour (also not with patch).

2014-02-04 02:16:45.810942 I [26853/26853] CoreContext mythplayer.cpp:1790 (InitAVSync) - Player(1): Display Refresh Rate: 50.045 Video Frame Rate: 50.000

With the normal refresh rate (30, 60i) and patch didn't have either a change in behaviour.

The patch applied or not behaves the same for finished and in-progress recordings.

[Steve Meyers <steve-mythtv@…>]

I have this same problem using MythTV 0.27-fixes on Mythbuntu 12.04 LTS. It has only occurred since I upgraded to 0.27, and I can't find any evidence in the log files that any problem has been noticed by the frontend. I tried using a hard link to fool it into thinking the recording was completed, and that made the stuttering stop.

It appears to be something it is doing while playing back a currently recording show. The frontend isn't extremely powerful -- it's an Atom 330 @ 1.6GHz with an Nvidia video card. It does not generally have problems playing back HD content, it only has these stutters when watching a show in 0.27 while the show is being recorded.

[Steve Meyers <steve-mythtv@…>]

I just checked, and I am also seeing this with an Atom D525 @ 1.8GHz that does not have any problems normally.

[Steve Meyers <steve-mythtv@…>]

Having looked into it a bit more, there's one other thing that happens about every 10 seconds -- the entry in the recorded table gets updated. I'm not sure if this is related.

[jonathan.oexner@…]

Replying to Steve Meyers <steve-mythtv@…>:

...I tried using a hard link to fool it into thinking the recording was completed, and that made the stuttering stop...

Steve, how did you use a hard link? Does the backend usually use a symlink?

[Raymond Wagner]

Replying to jonathan.oexner@…:

Replying to Steve Meyers <steve-mythtv@…>:

...I tried using a hard link to fool it into thinking the recording was completed, and that made the stuttering stop...

Steve, how did you use a hard link? Does the backend usually use a symlink?

Yeah, that does not make any sense. The backend does not use symlinks for anything, nor does it produce additional hardlinks to recordings beyond the original file location.

[angela.schmid@…]

From my original post

Reusing and playing another finished recording where the file is linked to the in progress recording file there is no stuttering.

Take another recording, delete its file and create a link to the in recording file. Play this recording and no stuttering will be seen.

[Steve Meyers <steve-mythtv@…>]

Replying to jonathan.oexner@…:

Steve, how did you use a hard link? Does the backend usually use a symlink?

I hard linked to the file that was being recorded, and then added an entry for it manually in the database. This eliminates the possibility that it has something to do with the streaming of the file that is being recorded. It has to be something else the frontend is doing when it is viewing a recording in progress.

I haven't watched a ton of live events since upgrading to 0.27, so it wasn't bothering me much. With the Olympics on now, I'm watching more live events, and so I created a script to do the hard link and create the entry in the database.

[Jonatan Lindblad]

As far as I can see the stutter occurs when the FE is waiting for a response to a GET_FRAMES_WRITTEN command while the BE is busy with updating the database in ProgramInfo::SavePositionMap().

Applying the ProgramInfo parts from the patch from the thread mentioned in #comment:1 reduced the response time by an order of magnitude. Playback is now smooth most of the time. I did have some problems with the patch in that it used double quotes instead of single quotes in the query strings. I've addressed that in the patch that I will submit.

Note: I'm not using EIT so I left out that part of the original patch.

Note: I kept INSERT instead of REPLACE which was used in the original patch.

[angela.schmid@…]

I identified/solved my problem. Starting with 0.27-pre, recordseek is written every 10 seconds, previously it was written at the end of the recording. I noticed that some tables were using the InnoDB engine. I changed them to MYISAM and afterwards everything is fine. Even changing the volume produced hick ups, as it writes the volume change immediately into the settings table. Pressing the remote constantly halted playback until released.

As MythTV only supports MYISAM, I still tried the following MySQL setting and everything was also OK: innodb_flush_log_at_trx_commit = 0

Performance information using the MySQL setting: ​http://stackoverflow.com/questions/14121464/mysql-is-slow-with-innodb-during-insert-compared-to-myisam

[jonathan.oexner@…]

Replying to angela.schmid@…:

I noticed that some tables were using the InnoDB engine. I changed them to MYISAM and afterwards everything is fine. ... As MythTV only supports MYISAM...

So, is the underlying bug that the MythTV installer created InnoDB tables instead of MyISAM?

Or is it that writing out position data to the database in a blocking thread every 10 seconds is a bad idea?

[Jim Stichnoth]

Replying to jonathan.oexner@…:

So, is the underlying bug that the MythTV installer created InnoDB tables instead of MyISAM?

Or is it that writing out position data to the database in a blocking thread every 10 seconds is a bad idea?

If the latter were true, recordings would be damaged and it wouldn't matter whether you play an in-progress recording or a fully recorded recording.

Most likely, the underlying problem is that the decoder thread on the frontend is blocking on a slow query to the backend. The decoder and UI threads should both not be blocking on DB or backend queries.

[angela.schmid@…]

So, is the underlying bug that the MythTV installer created InnoDB tables instead of MyISAM?

No, I used MySQL a couple of months for work and I had to make optimizations; I used some analyzing/update scripts which could have introduced the changes to use the InnoDB engine for all DBs. They are all dropped and mythconverg is using the MYISAM engine again.

The backend should write to the DB in a separate thread, similar how DB writes for passive EIT collection are implemented.

Writing volume changes immediately to the DB in the frontend makes no sense; writing the settings at the end of playback would be just fine.

[Steve Meyers <steve-mythtv@…>]

Replying to angela.schmid@…:

As MythTV only supports MYISAM, I still tried the following MySQL setting and everything was also OK: innodb_flush_log_at_trx_commit = 0

I tried this setting, and it worked for me, as well. Changing the recordedseek table to MyISAM worked also.

By default, InnoDB will flush transactions to disk when they are committed. I'm not sure if it just flushes its own data, or all data that needs to be written to disk. I believe it's the latter, since I don't believe Linux has a way to just flush your own data. If that's the case, then it could be that it's forcing the MythTV stream to be written to disk before continuing.

So in short, I don't believe MythTV is necessarily doing anything wrong, it's just a byproduct of how MySQL works. Since the recordedseek table is not critical, I don't see any reason to use InnoDB for it. It might make sense for MythTV to force that table to be MyISAM.

[reidjr@…]

If you have set AutoCommercialSkip? ( or notify) then GET_FRAMES_WRITTEN is called continuously for any still recording file.

On my setup that causes jitter and dropped frames. ( probably because of database blocking as described above ? )

Setting TV Settings --> Playback --> Advert Skip --> Automatically skip adverts = "none" is a workaround.

[reidjr@…]

having slowly trawled through the code on github;

mythtv/libs/libmythtv/mythplayer.cpp

Handle automatic commercial skipping

uint64_t jumpto = 0; if (deleteMap.IsEmpty?() && (ffrew_skip == 1) &&

(kCommSkipOff != commBreakMap.GetAutoCommercialSkip?()))

{

QString msg; uint64_t frameCount = GetCurrentFrameCount?(); XXX CommBreakMap? should use duration map not video_frame_rate bool jump = commBreakMap.AutoCommercialSkip?(jumpto, framesPlayed,

video_frame_rate, frameCount, msg)

will continually call GetCurrentFrameCount?() which calls GET_FRAMES_WRITTEN for in progress recordings.

Not sure best approach. As I never commflag before end of recording :

if (deleteMap.IsEmpty?() && (ffrew_skip == 1) && (commBreakMap.HasMap?()) &&

(kCommSkipOff != commBreakMap.GetAutoCommercialSkip?()))

might work for me, but would leave the issue for those that do commflag during recording.

[reidjr@…]

having slowly trawled through the code on github;

mythtv/libs/libmythtv/mythplayer.cpp

// Handle automatic commercial skipping
    uint64_t jumpto = 0;
    if (deleteMap.IsEmpty() && (ffrew_skip == 1) &&
       (kCommSkipOff != commBreakMap.GetAutoCommercialSkip()))
    {
        QString msg;
        uint64_t frameCount = GetCurrentFrameCount();
        // XXX CommBreakMap should use duration map not video_frame_rate
        bool jump = commBreakMap.AutoCommercialSkip(jumpto, framesPlayed,
                                                    video_frame_rate,
                                                    frameCount, msg)

will continually call GetCurrentFrameCount?() which calls GET_FRAMES_WRITTEN for in progress recordings.

Not sure best approach. As I never commflag before end of recording :

   if (deleteMap.IsEmpty() && (ffrew_skip == 1) && (commBreakMap.HasMap()) &&
       (kCommSkipOff != commBreakMap.GetAutoCommercialSkip()))

might work for me, but would leave the issue for those that do commflag during recording.

[reidjr@…]

patch for mythbuntu package

[Mike Thomas <pfw.demon.co.uk>]

In b4be8e24f9fab5b6a71f62df8e2c0403bedf4805/mythtv:

Speed up ProgramInfo::SavePositionMap?() database writes.

Use a single SQL query to save all new position map entries.
This speeds up SavePositionMap? by an order of magnitude.

Fixes #12016

Signed-off-by: Jean-Yves Avenard <jyavenard@…>

[Mike Thomas <pfw.demon.co.uk>]

In 8d06c76af49393bcaf86348eaca20ca125b153e1/mythtv:

Speed up ProgramInfo::SavePositionMap?() database writes.

Use a single SQL query to save all new position map entries.
This speeds up SavePositionMap? by an order of magnitude.

Fixes #12016

Signed-off-by: Jean-Yves Avenard <jyavenard@…>
(cherry picked from commit b4be8e24f9fab5b6a71f62df8e2c0403bedf4805)

[jonathan.oexner@…]

Call me a git noob, but did this change go into whatever branch the 0.27-fixes mythbuntu packages are built from, or just 0.28?

[Raymond Wagner]

0.28 only for now. Mythbuntu builds from the fixes/0.27 branch.

[JYA]

you can test with a 0.27 compatible system using the devel/027candidates branch or using mythbuntu compatible packages available with the repo: ​http://www.avenard.org/files/ubuntu-repos