[mythtv-users] 0.27: Stalls and other niggles
Mike Thomas
mt3 at pfw.demon.co.uk
Thu Jan 16 16:32:27 UTC 2014
Dear Gurus,
I installed MythTV 0.22 on a computer some years back and it's been
working on this hardware without any major issues:
Dual Celeron 2.5GHz, 4GB 800MHz RAM, 2 x 7200rpm 1.5TB HDDs, 2 x RV710
graphics cards, 3 x HVR2200 tuners.
The disk configuration is as follows:
Disk 1: OS on ext4 with default settings
Swap (unused)
Videos on XFS with default settings
Disk 2: Mysql 5.1 database files & logs with default settings on ext4
Videos on XFS with default settings
The discs are encrypted with dmcrypt.
I am able to record digital broadcasts on 6 channels, play different
recordings on both graphics cards and play recordings on two other
computers simultaneously without any problems. This was also the case
when I used a dual 2.2GHz Celeron with 2GB RAM.
In short, MythTV knocked the socks off any DVR in the shops at the time.
I am writing today firstly to say thank you for writing such a damned
good piece of software and to ask for your advice about version 0.27.
I have configured a (headless) test box with a 2GHz i7 with 3GB of much
faster RAM, one of the above tuners, and a single 7200rpm 2TB HDD with a
similar disk layout. Installing 0.27 was straight-forward and it works
very well in most respects. However, I have encountered some problems
which prevent me from upgrading.
The first problem is that when I opt to watch live TV it displays
'Please Wait', hangs around for a minute or so (I suppose) and then
returns to the menu.
The second problem is that I see repeated video stalls during playback
of programs which are still being recorded. The video stalls occur
every 10 seconds and last for about half a second each time. The audio
does not stall and the front-end logs this at the time of the stall:
2014-01-15 15:09:52.701832 I [19666/19732] RingBuffer
ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 10223616, 32768) -> 32768, took 1 ms (262.144Mbps)
2014-01-15 15:09:52.830666 I [19666/19732] RingBuffer
ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 10256384, 32768) -> 32768, took 1 ms (262.144Mbps)
2014-01-15 15:09:52.832111 I [19666/19732] RingBuffer
ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 10289152, 32768) -> 32768, took 1 ms (262.144Mbps)
2014-01-15 15:09:52.951373 I [19666/19732] RingBuffer
ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 10321920, 32768) -> 32768, took 1 ms (262.144Mbps)
2014-01-15 15:09:53.068233 I [19666/19732] RingBuffer
ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 10354688, 32768) -> 32768, took 1 ms (262.144Mbps)
2014-01-15 15:09:53.184998 I [19666/19732] RingBuffer
ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 10387456, 32768) -> 32768, took 1 ms (262.144Mbps)
2014-01-15 15:09:53.236447 I [19666/19732] RingBuffer
ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 10420224, 32768) -> 32768, took 1 ms (262.144Mbps)
2014-01-15 15:09:53.302011 I [19666/19732] RingBuffer
ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 10452992, 32768) -> 32768, took 1 ms (262.144Mbps)
2014-01-15 15:09:53.431598 I [19666/19732] RingBuffer
ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 10485760, 32768) -> 32768, took 1 ms (262.144Mbps)
2014-01-15 15:09:53.465927 I [19666/19666] CoreContext
jitterometer.cpp:119 (RecordEndTime) - Player(0): FPS: 25.38 Mean:
39399 Std.Dev: 6154 CPUs: 100% 100% 100% 2% 2014-01-15 15:09:53.483105
I [19666/19732] RingBuffer ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 10518528, 32768) -> 32768, took 1 ms (262.144Mbps)
2014-01-15 15:09:54.267104 I [19666/19666] CoreContext
mythplayer.cpp:1877 (AVSync) - Player(0): Video is 4.85367 frames
behind audio (too slow), dropping frame to catch up. 2014-01-15
15:09:54.270992 I [19666/19732] RingBuffer ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 10551296, 32768) -> 32768, took 1 ms (262.144Mbps)
2014-01-15 15:09:54.272233 I [19666/19666] CoreContext
mythplayer.cpp:1877 (AVSync) - Player(0): Video is 8.32775 frames
behind audio (too slow), dropping frame to catch up. 2014-01-15
15:09:54.277182 I [19666/19666] CoreContext mythplayer.cpp:1877
(AVSync) - Player(0): Video is 10.7208 frames behind audio (too slow),
dropping frame to catch up. 2014-01-15 15:09:54.282340 I [19666/19666]
CoreContext mythplayer.cpp:1877 (AVSync) - Player(0): Video is 12.2906
frames behind audio (too slow), dropping frame to catch up. 2014-01-15
15:09:54.286484 I [19666/19732] RingBuffer ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 10584064, 65536) -> 65536, took 1 ms (524.288Mbps)
2014-01-15 15:09:54.298075 I [19666/19666] CoreContext
mythplayer.cpp:1877 (AVSync) - Player(0): Video is 13.1554 frames
behind audio (too slow), dropping frame to catch up. 2014-01-15
15:09:54.303849 I [19666/19666] CoreContext mythplayer.cpp:1877
(AVSync) - Player(0): Video is 13.6478 frames behind audio (too slow),
dropping frame to catch up. 2014-01-15 15:09:54.310869 I [19666/19666]
CoreContext mythplayer.cpp:1877 (AVSync) - Player(0): Video is 13.6546
frames behind audio (too slow), dropping frame to catch up. 2014-01-15
15:09:54.313971 I [19666/19732] RingBuffer ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 10649600, 32768) -> 32768, took 1 ms (262.144Mbps)
2014-01-15 15:09:54.316111 I [19666/19666] CoreContext
mythplayer.cpp:1877 (AVSync) - Player(0): Video is 13.4535 frames
behind audio (too slow), dropping frame to catch up. 2014-01-15
15:09:54.321138 I [19666/19666] CoreContext mythplayer.cpp:1877
(AVSync) - Player(0): Video is 13.0838 frames behind audio (too slow),
dropping frame to catch up. 2014-01-15 15:09:54.325979 I [19666/19666]
CoreContext mythplayer.cpp:1877 (AVSync) - Player(0): Video is 12.4879
frames behind audio (too slow), dropping frame to catch up. 2014-01-15
15:09:54.330448 I [19666/19732] RingBuffer ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 10682368, 65536) -> 65536, took 1 ms (524.288Mbps)
2014-01-15 15:09:54.331050 I [19666/19666] CoreContext
mythplayer.cpp:1877 (AVSync) - Player(0): Video is 11.8221 frames
behind audio (too slow), dropping frame to catch up. 2014-01-15
15:09:54.336008 I [19666/19666] CoreContext mythplayer.cpp:1877
(AVSync) - Player(0): Video is 11.1041 frames behind audio (too slow),
dropping frame to catch up. 2014-01-15 15:09:54.340893 I [19666/19666]
CoreContext mythplayer.cpp:1877 (AVSync) - Player(0): Video is 10.3468
frames behind audio (too slow), dropping frame to catch up. 2014-01-15
15:09:54.344070 I [19666/19732] RingBuffer ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 10747904, 65536) -> 65536, took 1 ms (524.288Mbps)
2014-01-15 15:09:54.345934 I [19666/19666] CoreContext
mythplayer.cpp:1877 (AVSync) - Player(0): Video is 9.5601 frames behind
audio (too slow), dropping frame to catch up. 2014-01-15
15:09:54.351160 I [19666/19666] CoreContext mythplayer.cpp:1877
(AVSync) - Player(0): Video is 8.60133 frames behind audio (too slow),
dropping frame to catch up. 2014-01-15 15:09:54.356067 I [19666/19666]
CoreContext mythplayer.cpp:1877 (AVSync) - Player(0): Video is 7.66348
frames behind audio (too slow), dropping frame to catch up. 2014-01-15
15:09:54.359103 I [19666/19732] RingBuffer ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 10813440, 65536) -> 65536, took 1 ms (524.288Mbps)
2014-01-15 15:09:54.361566 I [19666/19666] CoreContext
mythplayer.cpp:1877 (AVSync) - Player(0): Video is 6.74135 frames
behind audio (too slow), dropping frame to catch up. 2014-01-15
15:09:54.366542 I [19666/19666] CoreContext mythplayer.cpp:1877
(AVSync) - Player(0): Video is 5.83725 frames behind audio (too slow),
dropping frame to catch up. 2014-01-15 15:09:54.371486 I [19666/19666]
CoreContext mythplayer.cpp:1877 (AVSync) - Player(0): Video is 4.79042
frames behind audio (too slow), dropping frame to catch up. 2014-01-15
15:09:54.375035 I [19666/19732] RingBuffer ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 10878976, 65536) -> 65536, took 1 ms (524.288Mbps)
2014-01-15 15:09:54.376511 I [19666/19666] CoreContext
mythplayer.cpp:1877 (AVSync) - Player(0): Video is 3.78655 frames
behind audio (too slow), dropping frame to catch up. 2014-01-15
15:09:54.466773 I [19666/19732] RingBuffer ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 10944512, 32768) -> 32768, took 1 ms (262.144Mbps)
2014-01-15 15:09:54.518286 I [19666/19732] RingBuffer
ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 10977280, 32768) -> 32768, took 1 ms (262.144Mbps)
2014-01-15 15:09:54.587161 I [19666/19732] RingBuffer
ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 11010048, 32768) -> 32768, took 1 ms (262.144Mbps)
2014-01-15 15:09:54.638759 I [19666/19732] RingBuffer
ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 11042816, 32768) -> 32768, took 1 ms (262.144Mbps)
2014-01-15 15:09:54.709244 I [19666/19732] RingBuffer
ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 11075584, 32768) -> 32768, took 1 ms (262.144Mbps)
2014-01-15 15:09:54.760635 I [19666/19732] RingBuffer
ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 11108352, 32768) -> 32768, took 1 ms (262.144Mbps)
2014-01-15 15:09:54.834400 I [19666/19732] RingBuffer
ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 11141120, 32768) -> 32768, took 1 ms (262.144Mbps)
2014-01-15 15:09:54.885948 I [19666/19732] RingBuffer
ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 11173888, 32768) -> 32768, took 1 ms (262.144Mbps)
2014-01-15 15:09:54.954808 I [19666/19732] RingBuffer
ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 11206656, 32768) -> 32768, took 1 ms (262.144Mbps)
2014-01-15 15:09:55.072544 I [19666/19732] RingBuffer
ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 11239424, 32768) -> 32768, took 1 ms (262.144Mbps)
2014-01-15 15:09:55.124029 I [19666/19732] RingBuffer
ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 11272192, 32768) -> 32768, took 1 ms (262.144Mbps)
2014-01-15 15:09:55.189606 I [19666/19732] RingBuffer
ringbuffer.cpp:884 (run) -
RingBuf(myth://10.1.1.100:6543/1001_20140115150200.mpg):
safe_read(... at 11304960, 32768) -> 32768, took 1 ms (262.144Mbps)
The 100% CPU readings occur only on the first stall after starting
playback. The CPU readings on subsequent stalls hover below 5%. The
recordings made under these circumstances are perfect, and can be
played without any stalling once the recording has finished.
In terms of frequency of the stalls, recording a single programme and
watching it whilst it records produces stalls at precisely 10 second
intervals in wall clock time (ie. every 04, 14, 24... seconds on my
clock). It does not matter when I start a recording or a playback, or
whether I pause and play a programme, the stalls remain
synchronized to the wall clock. Starting mythfrontend and mythbackend
at different times makes no difference, but restarting mysqld does, at
least for a while. When I record two programmes simultaneously, I
observe stalls at the times described above and extra stalls at about 7
second intervals.
The third problem is that the moment a recording finishes, a live
playback of that recording stalls and dies.
Addressing the stalling problem first, my first thought was it could be
something to do with the audio drivers or video decoding, but I
discounted this by setting the audio device to NULL and changing the
decoding profile to slim. The only other problem source I've seen so far
on the mailing list is disk performance. Accordingly I examined the
following:
- Changing the buffer size of the video capture device
- Commenting-out fdatasync() and fsync() in mythbackend
- Moving the database to a third computer
- Killing everything on the computer but the mythtv components.
None of these things make any difference, and frankly, I'm not
surprised. The head-room of the disk system is amply demonstrated by
the performance of my live system. I use the Balanced I/O scheduler.
What I have noticed is mysqld almost always seems to be the process
doing the most I/O at the moment of the stall, but is rarely doing any
I/O at other times. It is almost as if mysqld is batching updates to
its tables and logs. Given that MythTV used to perform single row
updates of MyISAM tables, any batching is bound to have a deleterious
effect on performance. Is this the case in 0.27?
Does anyone have any suggestions on how to track down the problem?
Yours,
Mike
More information about the mythtv-users
mailing list