[mythtv-users] Help Mythbackend deadlocks.

John Drescher drescherjm at gmail.com
Sun Jan 8 16:58:43 UTC 2012


After the recording process has been working flawlessly for years (and
on 0.24 fixes for over a year) recently updated a little less
frequently I updated it a few times in the last few weeks / months and
only now I have a serious problem that I have never seen before. It
seems that if I record 2 programs back to back it is now very likely
that the second program deadlocks mythbackend. I originally thought
this was a kernel issue but I have reverted back to the kernel (3.1.4
gentoo-sources) I had used for the last few weeks that did not have
this issue.

jmd0 mythtv # mythbackend --version
Please attach all output as a file in bug reports.
MythTV Version   : v0.24.1-120-g294968b-dirty
MythTV Branch    : branch-fixes/0.24
Network Protocol : 63
Library API      : 0.24.20110804-1
QT Version       : 4.7.4
Options compiled in:
 linux release using_alsa using_oss using_pulse using_pulseoutput
using_backend using_bindings_perl using_bindings_python using_dvb
using_firewire using_frontend using_hdpvr using_ivtv using_mheg
using_opengl_video using_opengl_vsync using_qtdbus using_qtwebkit
using_v4l using_x11 using_xrandr using_xv using_xvmc using_xvmc_vld
using_xvmcw using_bindings_perl using_bindings_python
using_mythtranscode using_opengl using_vdpau using_ffmpeg_threads
using_mheg


2012-01-08 03:16:04.269 [mpeg2video @ 0x3ecc8f4780]warning: first
frame is no keyframe
2012-01-08 03:16:04.291 [mpeg2video @ 0x3ecc8f4780]warning: first
frame is no keyframe
2012-01-08 03:16:04.312 [mpeg2video @ 0x3ecc8f4780]warning: first
frame is no keyframe
2012-01-08 03:16:04.536 [mpeg2video @ 0x3ecc8f4780]warning: first
frame is no keyframe
2012-01-08 03:16:04.759 [mpeg2video @ 0x3ecc8f4780]warning: first
frame is no keyframe
2012-01-08 03:16:04.760 [mpeg2video @ 0x3ecc8f4780]warning: first
frame is no keyframe
2012-01-08 03:16:04.778 [mpeg2video @ 0x3ecc8f4780]warning: first
frame is no keyframe
2012-01-08 03:16:04.798 [mpeg2video @ 0x3ecc8f4780]warning: first
frame is no keyframe
2012-01-08 03:16:05.019 [mpeg2video @ 0x3ecc8f4780]warning: first
frame is no keyframe
2012-01-08 03:16:05.020 [mpeg2video @ 0x3ecc8f4780]warning: first
frame is no keyframe
2012-01-08 03:16:05.028 [mpeg2video @ 0x3ecc8f4780]warning: first
frame is no keyframe
2012-01-08 03:16:05.265 [mpeg2video @ 0x3ecc8f4780]warning: first
frame is no keyframe
2012-01-08 03:16:32.053 AutoExpire: CalcParams(): Max required Free
Space: 2.0 GB w/freq: 15 min
2012-01-08 03:31:32.086 AutoExpire: CalcParams(): Max required Free
Space: 2.0 GB w/freq: 15 min
2012-01-08 03:45:21.591 UPnpMedia: BuildMediaMap VIDEO scan starting
in :/share/Movies/dvd:
2012-01-08 03:45:21.593 UPnpMedia: BuildMediaMap Done. Found 0 objects
2012-01-08 03:46:33.316 AutoExpire: CalcParams(): Max required Free
Space: 2.0 GB w/freq: 15 min
2012-01-08 04:00:00.994 TVRec(21): Changing from RecordingOnly to None
2012-01-08 04:00:00.995 Updating status for "NFL PrimeTime" on cardid
21 (Recording => Recorded)
2012-01-08 04:00:00.995 Finished recording NFL PrimeTime: channel 1014
2012-01-08 04:00:01.002 Reschedule requested for id 0.
2012-01-08 04:00:01.114 Scheduled 90 items in 0.1 = 0.00 match + 0.11 place
2012-01-08 04:00:01.168 Finished recording NFL PrimeTime: channel 1014
2012-01-08 04:00:05.714
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited 2.0
seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:07.715
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited 4.0
seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:11.716
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited 8.0
seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:12.717
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited 9.0
seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:12.967
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited 9.2
seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:13.468
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited 9.8
seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:13.718
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
10.0 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:13.968
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
10.2 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:14.219
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
10.5 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:14.469
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
10.8 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:14.719
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
11.0 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:14.970
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
11.2 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:15.220
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
11.5 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:15.470
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
11.8 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:15.721
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
12.0 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:15.971
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
12.2 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:16.221
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
12.5 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:16.472
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
12.8 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:16.722
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
13.0 seconds for data

2012-01-08 04:00:16.972
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
13.2 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:17.223
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
13.5 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:17.473
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
13.8 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:17.723
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
14.0 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:17.973
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
14.2 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:18.224
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
14.5 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:18.225 MythSocket(119f570:7): readStringList: Error,
timed out after 7000 ms.
2012-01-08 04:00:18.226 RemoteFile::Read(): No response from control socket.
2012-01-08 04:00:18.226
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg) Error:
RingBuffer::safe_read(RemoteFile* ...): read failed
2012-01-08 04:00:18.226
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
14.5 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:18.476
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
14.8 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:18.727
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
15.0 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:18.977
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
15.2 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:19.228
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
15.5 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:19.478
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
15.8 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:19.728
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg): Waited
16.0 seconds for data
                        to become available... 0 < 32768
2012-01-08 04:00:19.728
RingBuf(myth://192.168.1.110:6543/1014_20120108030000.mpg) Error:
Waited 16 seconds for data, aborting.
2012-01-08 04:02:19.960 New DB connection, total: 4
2012-01-08 04:15:21.594 New DB connection, total: 5
2012-01-08 09:49:40.048 Event socket closed. No connection to the backend.


2012-01-08 10:21:58.666 mythbackend version: branch-fixes/0.24
[v0.24.1-120-g294968b-dirty] www.mythtv.org
2012-01-08 10:21:58.669 Using runtime prefix = /usr
2012-01-08 10:21:58.669 Using configuration directory = /home/mythtv/.mythtv
2012-01-08 10:21:58.680 Using localhost value of jmd0
2012-01-08 10:21:58.694 New DB connection, total: 1
2012-01-08 10:21:58.696 Connected to database 'mythconverg' at host: jmd0
2012-01-08 10:21:58.699 Closing DB connection named 'DBManager0'
2012-01-08 10:21:58.700 Connected to database 'mythconverg' at host: jmd0
2012-01-08 10:21:58.701 Current locale EN_US
2012-01-08 10:21:58.702 Reading locale defaults from
/usr/share/mythtv//locales/en_us.xml
2012-01-08 10:21:58.708 Current MythTV Schema Version (DBSchemaVer): 1264
2012-01-08 10:21:58.710 ThreadPool:HTTP: Initial 1, Max 25, Timeout 60000
2012-01-08 10:21:58.716 Enabling Upnpmedia rebuild thread.
2012-01-08 10:21:59.917 MythBackend: Starting up as the master server.
2012-01-08 10:21:59.920 New DB connection, total: 2
2012-01-08 10:21:59.920 Connected to database 'mythconverg' at host: jmd0
2012-01-08 10:21:59.923 New DB connection, total: 3
2012-01-08 10:21:59.923 Connected to database 'mythconverg' at host: jmd0
irsend: command failed: SEND_ONCE DTA Key_Enter
irsend: unknown command: "Key_Enter"
2012-01-08 10:22:02.877 New DB scheduler connection
2012-01-08 10:22:02.878 Connected to database 'mythconverg' at host: jmd0
2012-01-08 10:22:02.880 Main::Registering HttpStatus Extension
2012-01-08 10:22:02.880 Enabled verbose msgs: important general
2012-01-08 10:22:02.885 AutoExpire: CalcParams(): Max required Free
Space: 1.0 GB w/freq: 15 min
2012-01-08 10:22:05.882 Reschedule requested for id -1.
2012-01-08 10:22:05.993 Scheduled 90 items in 0.1 = 0.00 match + 0.10 place
2012-01-08 10:22:05.995 Seem to be woken up by USER
2012-01-08 10:22:08.717 UPnpMedia: BuildMediaMap VIDEO scan starting
in :/share/Movies/dvd:
2012-01-08 10:22:08.718 UPnpMedia: BuildMediaMap Done. Found 0 objects
2012-01-08 10:22:22.881 Expiring 3 MB for 1010 at 2012-01-06T20:45:04
=> Chuck:"Chuck Versus the Kept Man"
2012-01-08 10:22:48.215 MainServer::ANN Monitor
2012-01-08 10:22:48.216 adding: jmd0.comcast.net as a client (events: 2)
2012-01-08 10:22:50.798 MainServer::ANN Monitor
2012-01-08 10:22:50.798 adding: jmd0.comcast.net as a client (events: 2)
2012-01-08 10:22:52.513 MainServer::ANN Monitor
2012-01-08 10:22:52.514 adding: jmd0.comcast.net as a client (events: 2)
2012-01-08 10:22:52.518 MainServer::ANN Monitor
2012-01-08 10:22:52.519 adding: jmd0.comcast.net as a client (events: 2)
2012-01-08 10:22:56.139 MainServer::ANN Monitor
2012-01-08 10:22:56.140 adding: jmd0.comcast.net as a client (events: 2)
2012-01-08 10:22:56.144 MainServer::ANN Monitor
2012-01-08 10:22:56.144 adding: jmd0.comcast.net as a client (events: 2)
2012-01-08 10:22:56.182 MainServer::ANN Monitor
2012-01-08 10:22:56.182 adding: jmd0.comcast.net as a client (events: 2)
2012-01-08 10:22:56.183 Reschedule requested for id 693.
2012-01-08 10:22:56.284 Scheduled 91 items in 0.1 = 0.00 match + 0.10 place
2012-01-08 10:22:56.309 TVRec(21): Changing from None to RecordingOnly
2012-01-08 10:22:56.310 TVRec(21): HW Tuner: 21->21
2012-01-08 10:22:56.335 AutoExpire: CalcParams(): Max required Free
Space: 2.0 GB w/freq: 15 min
2012-01-08 10:22:56.336 Started recording: "CBS News Sunday Morning":
channel 1003 on cardid 21, sourceid 1
2012-01-08 10:22:56.411 MainServer::ANN Monitor
2012-01-08 10:22:56.411 adding: jmd0.comcast.net as a client (events: 2)
2012-01-08 10:22:56.415 MainServer::ANN Monitor
2012-01-08 10:22:56.415 adding: jmd0.comcast.net as a client (events: 2)
2012-01-08 10:22:57.026 ProgramInfo(1003_20120108102300.mpg), Error:
GetPlaybackURL: '1003_20120108102300.mpg' should be local, but it can
not be found.
irsend: command failed: SEND_ONCE DTA Key_Enter
irsend: unknown command: "Key_Enter"
2012-01-08 10:22:57.533 Updating status for "CBS News Sunday Morning"
on cardid 21 (Tuning => Recording)
2012-01-08 10:22:57.596 TVRec(21): rec->GetPathname():
'/mnt/mythtv/jmd0_vg_2t0_1/videos/1003_20120108102300.mpg'
2012-01-08 10:23:00.402 MainServer::ANN Monitor
2012-01-08 10:23:00.403 adding: jmd0.comcast.net as a client (events: 2)
2012-01-08 10:23:06.848 MainServer::ANN Monitor
2012-01-08 10:23:06.848 adding: jmd0.comcast.net as a client (events: 2)
2012-01-08 10:23:11.466 MainServer::ANN Monitor
2012-01-08 10:23:11.467 adding: jmd0.comcast.net as a client (events: 2)
2012-01-08 10:23:12.887 JobQueue: Commercial Detection Starting for
"CBS News Sunday Morning" recorded from channel 1003 at
2012-01-08T10:23:00
2012-01-08 10:23:12.994 Using runtime prefix = /usr
2012-01-08 10:23:12.994 Using configuration directory = /home/mythtv/.mythtv
2012-01-08 10:23:12.995 Using localhost value of jmd0
2012-01-08 10:23:13.004 New DB connection, total: 1
2012-01-08 10:23:13.007 Connected to database 'mythconverg' at host: jmd0
2012-01-08 10:23:13.008 Closing DB connection named 'DBManager0'
2012-01-08 10:23:13.009 Connected to database 'mythconverg' at host: jmd0
2012-01-08 10:23:13.010 Current locale EN_US
2012-01-08 10:23:13.010 Reading locale defaults from
/usr/share/mythtv//locales/en_us.xml
2012-01-08 10:23:13.015 Loading en_us translation for module mythfrontend
2012-01-08 10:23:13.019 MainServer::ANN Playback
2012-01-08 10:23:13.019 adding: jmd0 as a client (events: 0)
2012-01-08 10:23:13.020 MainServer::HandleAnnounce FileTransfer
2012-01-08 10:23:13.020 adding: jmd0 as a remote file transfer
2012-01-08 10:23:13.601 MythCoreContext: Connecting to backend server:
192.168.1.110:6543 (try 1 of 1)
2012-01-08 10:23:13.602 Using protocol version 63
2012-01-08 10:23:13.602 MainServer::ANN Playback
2012-01-08 10:23:13.603 adding: jmd0 as a client (events: 0)
2012-01-08 10:23:13.603 MainServer::ANN Monitor
2012-01-08 10:23:13.604 adding: jmd0 as a client (events: 1)
2012-01-08 10:23:18.405 MainServer::ANN Monitor
2012-01-08 10:23:18.406 adding: jmd0.comcast.net as a client (events: 2)
2012-01-08 10:23:20.818 MainServer::ANN Monitor
2012-01-08 10:23:20.818 adding: jmd0.comcast.net as a client (events: 2)
2012-01-08 10:23:22.885 AutoExpire: CalcParams(): Max required Free
Space: 2.0 GB w/freq: 15 min
2012-01-08 10:23:22.887 Expiring 483 MB for 3184 at 2011-03-12T01:49:16 => Extra
2012-01-08 10:23:25.692 MainServer::ANN Monitor
2012-01-08 10:23:25.693 adding: jmd0.comcast.net as a client (events: 2)
2012-01-08 10:23:25.730 MainServer::ANN Monitor
2012-01-08 10:23:25.731 adding: jmd0.comcast.net as a client (events: 2)
2012-01-08 10:23:25.731 Reschedule requested for id 694.
2012-01-08 10:23:25.834 Scheduled 92 items in 0.1 = 0.00 match + 0.10 place
2012-01-08 10:23:25.905 MainServer::ANN Monitor
2012-01-08 10:23:25.906 adding: jmd0.comcast.net as a client (events: 2)
2012-01-08 10:23:28.300 MainServer::ANN Monitor
2012-01-08 10:23:28.301 adding: jmd0.comcast.net as a client (events: 2)
2012-01-08 10:23:31.653 AFD Warning: ScanATSCCaptionStreams() called with no PMT
2012-01-08 10:23:31.654 AFD: Opened codec 0x7fbef800fa20,
id(MPEG2VIDEO) type(Video)
2012-01-08 10:23:31.654 AFD: codec MP2 has 2 channels
2012-01-08 10:23:31.654 AFD: Opened codec 0x7fbef80151a0, id(MP2) type(Audio)
2012-01-08 10:23:31.655 MythCoreContext: Connecting to backend server:
192.168.1.110:6543 (try 1 of 1)
2012-01-08 10:23:31.656 Using protocol version 63
2012-01-08 10:23:31.656 MainServer::ANN Playback
2012-01-08 10:23:31.656 adding: jmd0 as a client (events: 0)
2012-01-08 10:23:31.657 RecBase(21:/dev/v4l/video0):
GetKeyframePositions(691,9223372036854775807,#20) out of 66
2012-01-08 10:28:55.509 MainServer::ANN Monitor
2012-01-08 10:28:55.510 adding: jmd0.comcast.net as a client (events: 2)
2012-01-08 10:29:00.871 Reschedule requested for id 0.
2012-01-08 10:29:00.972 Scheduled 92 items in 0.1 = 0.00 match + 0.10 place
2012-01-08 10:29:08.040 MainServer::ANN Monitor
2012-01-08 10:29:08.040 adding: jmd0.comcast.net as a client (events: 2)
2012-01-08 10:29:12.131 MainServer::ANN Monitor
2012-01-08 10:29:12.132 adding: jmd0.comcast.net as a client (events: 2)
2012-01-08 10:29:12.170 MainServer::ANN Monitor
2012-01-08 10:29:12.170 adding: jmd0.comcast.net as a client (events: 2)
2012-01-08 10:29:12.170 Reschedule requested for id 695.
2012-01-08 10:29:12.274 Scheduled 93 items in 0.1 = 0.00 match + 0.10 place
2012-01-08 10:29:12.379 MainServer::ANN Monitor
2012-01-08 10:29:12.379 adding: jmd0.comcast.net as a client (events: 2)
2012-01-08 10:29:29.800 TVRec(21): ASK_RECORDING 21 29 0 0
2012-01-08 10:30:00.810 TVRec(21): Changing from RecordingOnly to None
2012-01-08 10:30:00.812 Updating status for "CBS News Sunday Morning"
on cardid 21 (Recording => Recorded)
2012-01-08 10:30:00.812 Finished recording CBS News Sunday Morning: channel 1003
2012-01-08 10:30:01.042 Finished recording CBS News Sunday Morning: channel 1003
2012-01-08 10:30:11.757 MythSocket(24144b0:7): readStringList: Error,
timed out after 7000 ms.
2012-01-08 10:30:11.758 Remote file timeout.
2012-01-08 10:30:33.796 MythSocket(7fbef800cf00:10): readStringList:
Error, timed out after 30000 ms.
2012-01-08 10:30:33.797 Connection to backend server lost
2012-01-08 10:30:33.797 New DB connection, total: 2
2012-01-08 10:30:33.798 Connected to database 'mythconverg' at host: jmd0
2012-01-08 10:30:33.799 MythCoreContext: Connecting to backend server:
192.168.1.110:6543 (try 1 of 1)
2012-01-08 10:30:40.799 MythSocket(2465860:8): readStringList: Error,
timed out after 7000 ms.
2012-01-08 10:30:40.799 Protocol version check failure.
                        The response to MYTH_PROTO_VERSION was empty.
                        This happens when the backend is too busy to respond,
                        or has deadlocked in due to bugs or hardware failure.
2012-01-08 10:30:40.799 Reconnection to backend server failed
2012-01-08 10:30:40.800 ~MythContext waiting for threads to exit.
2012-01-08 10:30:40.850 MythCoreContext: Connecting to backend server:
192.168.1.110:6543 (try 1 of 1)
2012-01-08 10:30:47.850 MythSocket(2413f10:8): readStringList: Error,
timed out after 7000 ms.
2012-01-08 10:30:47.850 Protocol version check failure.
                        The response to MYTH_PROTO_VERSION was empty.
                        This happens when the backend is too busy to respond,
                        or has deadlocked in due to bugs or hardware failure.


I believe this is ticket 9704

http://code.mythtv.org/trac/ticket/9704

I have this morning applied the patch
mythtv-0.24-backport_reconnect_fixes.patch but that has not helped at
all. After a restart of the backend I can record again.


-- 
John M. Drescher


More information about the mythtv-users mailing list