[mythtv-commits] Ticket #12314: mythbackend deadlocked during record, EIT scan and reschedule. CPU goes to 100%.
MythTV
noreply at mythtv.org
Mon Nov 3 20:56:06 UTC 2014
#12314: mythbackend deadlocked during record, EIT scan and reschedule. CPU goes to
100%.
--------------------------------------------+------------------------------
Reporter: Paul Netherwood <paul@…> | Owner:
Type: Bug Report - Hang/Deadlock | Status: new
Priority: major | Milestone: 0.27.5
Component: MythTV - General | Version: 0.27.4
Severity: medium | Keywords: deadlock 100%
Ticket locked: 0 | CPU
--------------------------------------------+------------------------------
Mythbackend locks up during recording after a period of time of usage.
This does not happen immediately but after a day or so and often during
when 2 or more recordings are occurring simultaneously either on the DVB-T
cards, the DVB-S2 card or both. Frontend, mythweb (and mythbackend
--setloglevel debug) do not respond. Logs fill up with sockets errors as
frontend tries and fails to connect. Mythweb just hangs. CPU is at 100%
while deadlock occurs. Eventually after 5 to 15 minutes mythbackend
sometimes becomes responsive again. A restart of mythbackend removes the
problem temporarily. Disabling the EIT scanner reduces the frequency of
the problem and the deadlock only lasts a few minutes.
The log files do not show much since logging freezes during deadlock. All
that is shown is problems with the sockets. See example logs below.
I'm using the latest 0.27.4 fixes and Ubuntu 14.04 with the latest
updates. My hardware setup is:
4 x Haupauge Nova-T DVB-T PCI cards
1 x TBS 6920 DVB-S2 PCIe card
I am on the latest version of the TBS Drivers which are v141019. All cards
are set to record on two Mux's.
I am using remote frontend (Acer Revo) using the version of Mythtv and
Ubuntu.
This problem did not occur in releases prior to 0.27. The hardware setup
is unchanged.
I have attached a gdb stack dump (a short and a full one). Looking at the
thread trace it looks like the scheduler is waiting on a lock. This error
seems similar to ticket #9261 but that code has changed quite a bit in
scheduler.cpp. The fact that disabling the EIT scanner reduces the
frequency of the problem implies its something to do with locking during
DVB recording.
'''uname -a:'''
{{{
Linux mythbackend 3.13.0-37-generic #64-Ubuntu SMP Mon Sep 22 21:30:01 UTC
2014 i686 i686 i686 GNU/Linux
}}}
'''mythbackend --version:'''
{{{
MythTV Version : v0.27.4-6-ge0b0027
MythTV Branch : fixes/0.27
Network Protocol : 77
Library API : 0.27.20141016-1
QT Version : 4.8.6
Options compiled in:
linux profile use_hidesyms using_alsa using_oss using_pulse
using_pulseoutput using_backend using_bindings_perl using_bindings_python
using_bindings_php using_crystalhd using_dvb using_firewire using_frontend
using_hdhomerun using_ceton using_hdpvr using_ivtv using_joystick_menu
using_libcrypto using_libdns_sd using_libfftw3 using_libxml2 using_lirc
using_mheg using_opengl using_opengl_video using_qtwebkit using_qtscript
using_qtdbus using_sdl using_taglib using_v4l2 using_x11 using_xrandr
using_xv using_profiletype using_bindings_perl using_bindings_python
using_bindings_php using_mythtranscode using_opengl using_vaapi
using_vdpau using_ffmpeg_threads using_mheg using_libass using_libxml2
}}}
'''Frontend log:'''
{{{
Nov 2 13:26:50 mythrevo3 mythfrontend.real: mythfrontend[1454]: N
CoreContext mythmainwindow.cpp:2742 (PauseIdleTimer) Resuming idle timer
Nov 2 13:27:59 mythrevo3 mythfrontend.real: mythfrontend[1454]: E
MythSocketThread(-1) mythsocket.cpp:850 (ReadStringListReal)
MythSocket(ffffffffaad42fc8:49): ReadStringList: Error, timed out after
30000
ms.
Nov 2 13:27:59 mythrevo3 mythfrontend.real: mythfrontend[1454]: E
ProgramInfoLoader mythsocket.cpp:353 (SendReceiveStringList)
MythSocket(ffffffffaad42fc8:-1): No response.
Nov 2 13:27:59 mythrevo3 mythfrontend.real: mythfrontend[1454]: N
ProgramInfoLoader mythcorecontext.cpp:1264 (SendReceiveStringList)
Connection to backend server lost
Nov 2 13:27:59 mythrevo3 mythfrontend.real: mythfrontend[1454]: N
MythSocketThread(-1) mythcorecontext.cpp:1500 (connectionClosed) Event
socket closed. No connection to the backend.
Nov 2 13:27:59 mythrevo3 mythfrontend.real: mythfrontend[1454]: I
ProgramInfoLoader mythcorecontext.cpp:426 (ConnectCommandSocket)
MythCoreContext: Connecting to backend server: 192.168.1.3:6543 (try 1 of
1)
Nov 2 13:27:59 mythrevo3 mythfrontend.real: mythfrontend[1454]: E
MythSocketThread(-1) mythsocket.cpp:737 (WriteStringListReal)
MythSocket(ffffffff8d9ebe50:50): WriteStringList: Error, invalid string
list
.
Nov 2 13:27:59 mythrevo3 mythfrontend.real: mythfrontend[1454]: E
ProgramInfoLoader mythsocket.cpp:347 (SendReceiveStringList)
MythSocket(ffffffff8d9ebe50:50): Failed to send command.
Nov 2 13:27:59 mythrevo3 mythfrontend.real: mythfrontend[1454]: C
ProgramInfoLoader mythcorecontext.cpp:1307 (SendReceiveStringList)
Reconnection to backend server failed
Nov 2 13:27:59 mythrevo3 mythfrontend.real: mythfrontend[1454]: I
SendMessage mythcorecontext.cpp:426 (ConnectCommandSocket)
MythCoreContext: Connecting to backend server: 192.168.1.3:6543 (try 1 of
1)
Nov 2 13:28:00 mythrevo3 mythfrontend.real: mythfrontend[1454]: W
CoreContext playbackbox.cpp:1799 (UpdateUILists) PlaybackBox: SortedList
is Empty
Nov 2 13:28:30 mythrevo3 mythfrontend.real: mythfrontend[1454]: E
MythSocketThread(-1) mythsocket.cpp:850 (ReadStringListReal)
MythSocket(ffffffff8d984af0:71): ReadStringList: Error, timed out after
30000
ms.
Nov 2 13:28:30 mythrevo3 mythfrontend.real: mythfrontend[1454]: E
ProgramInfoLoader mythsocket.cpp:353 (SendReceiveStringList)
MythSocket(ffffffff8d984af0:-1): No response.
Nov 2 13:28:30 mythrevo3 mythfrontend.real: mythfrontend[1454]: N
ProgramInfoLoader mythcorecontext.cpp:1264 (SendReceiveStringList)
Connection to backend server lost
Nov 2 13:28:30 mythrevo3 mythfrontend.real: mythfrontend[1454]: N
MythSocketThread(-1) mythcorecontext.cpp:1500 (connectionClosed) Event
socket closed. No connection to the backend.
Nov 2 13:28:30 mythrevo3 mythfrontend.real: mythfrontend[1454]: I
ProgramInfoLoader mythcorecontext.cpp:426 (ConnectCommandSocket)
MythCoreContext: Connecting to backend server: 192.168.1.3:6543 (try 1 of
1)
Nov 2 13:28:30 mythrevo3 mythfrontend.real: mythfrontend[1454]: E
MythSocketThread(-1) mythsocket.cpp:737 (WriteStringListReal)
MythSocket(ffffffffa790d3b0:50): WriteStringList: Error, invalid string
list
.
Nov 2 13:28:30 mythrevo3 mythfrontend.real: mythfrontend[1454]: E
ProgramInfoLoader mythsocket.cpp:347 (SendReceiveStringList)
MythSocket(ffffffffa790d3b0:50): Failed to send command.
Nov 2 13:28:30 mythrevo3 mythfrontend.real: mythfrontend[1454]: C
ProgramInfoLoader mythcorecontext.cpp:1307 (SendReceiveStringList)
Reconnection to backend server failed
Nov 2 13:28:30 mythrevo3 mythfrontend.real: mythfrontend[1454]: I
SendMessage mythcorecontext.cpp:426 (ConnectCommandSocket)
MythCoreContext: Connecting to backend server: 192.168.1.3:6543 (try 1 of
1)
Nov 2 13:28:30 mythrevo3 mythfrontend.real: mythfrontend[1454]: W
CoreContext playbackbox.cpp:1799 (UpdateUILists) PlaybackBox: SortedList
is Empty
}}}
and also
{{{
Nov 3 08:17:15 mythrevo3 mythfrontend.real: mythfrontend[1439]: I
SendMessage mythcorecontext.cpp:426 (ConnectCommandSocket)
MythCoreContext: Connecting to backend server: 192.168.1.3:6543 (try 1 of
1)
Nov 3 08:17:16 mythrevo3 mythfrontend.real: mythfrontend[1439]: I
CoreContext mythtranslation.cpp:65 (load) Loading en_us translation for
module mythgallery
Nov 3 08:17:16 mythrevo3 mythfrontend.real: mythfrontend[1439]: I
CoreContext mythtranslation.cpp:65 (load) Loading en_us translation for
module mythgame
Nov 3 08:17:16 mythrevo3 mythfrontend.real: mythfrontend[1439]: I
CoreContext schemawizard.cpp:118 (Compare) Current MythMusic Schema
Version (MusicDBSchemaVer): 1020
Nov 3 08:17:16 mythrevo3 mythfrontend.real: mythfrontend[1439]: I
CoreContext mythtranslation.cpp:65 (load) Loading en_us translation for
module mythmusic
Nov 3 08:17:16 mythrevo3 mythfrontend.real: mythfrontend[1439]: I
CoreContext serverpool.cpp:404 (listen) Listening on TCP 127.0.0.1:6546
Nov 3 08:17:16 mythrevo3 mythfrontend.real: mythfrontend[1439]: I
CoreContext serverpool.cpp:404 (listen) Listening on TCP 192.168.1.63:6546
Nov 3 08:17:16 mythrevo3 mythfrontend.real: mythfrontend[1439]: I
CoreContext serverpool.cpp:404 (listen) Listening on TCP [::1]:6546
Nov 3 08:17:16 mythrevo3 mythfrontend.real: mythfrontend[1439]: I
CoreContext serverpool.cpp:404 (listen) Listening on TCP
[fe80::201:6cff:fe6c:caca%eth0]:6546
Nov 3 08:17:16 mythrevo3 mythfrontend.real: mythfrontend[1439]: N
CoreContext main.cpp:1062 (RunMenu) Found mainmenu.xml for theme
'Mythbuntu'
Nov 3 08:17:22 mythrevo3 mythfrontend.real: mythfrontend[1439]: E
MythSocketThread(-1) mythsocket.cpp:850 (ReadStringListReal)
MythSocket(ffffffffa7942570:49): ReadStringList: Error, timed out after
7000 ms.
Nov 3 08:17:22 mythrevo3 mythfrontend.real: mythfrontend[1439]: C
SendMessage mythcorecontext.cpp:1520 (CheckProtoVersion) Protocol version
check failure.#012#011#011#011The response to MYTH_PROTO_VERSION was
empty.#012#011#011#011This happens when the backend is too busy to
respond,#012#011#011#011or has deadlocked due to bugs or hardware failure.
Nov 3 08:17:22 mythrevo3 mythfrontend.real: mythfrontend[1439]: I
SendMessage mythcorecontext.cpp:426 (ConnectCommandSocket)
MythCoreContext: Connecting to backend server: 192.168.1.3:6543 (try 1 of
1)
Nov 3 08:17:29 mythrevo3 mythfrontend.real: mythfrontend[1439]: E
MythSocketThread(-1) mythsocket.cpp:850 (ReadStringListReal)
MythSocket(ffffffffa7942b78:49): ReadStringList: Error, timed out after
7000 ms.
}}}
'''Backend logs:'''
{{{
Oct 30 23:59:46 mythbackend mythbackend: mythbackend[2292]: I TVRecEvent
tv_rec.cpp:1567 (HandlePendingRecordings) TVRec[9]: ASK_RECORDING 9 75 0 0
Oct 31 00:00:14 mythbackend mythbackend: mythbackend[2292]: I TVRecEvent
tv_rec.cpp:1050 (HandleStateChange) TVRec[9]: Changing from None to
RecordingOnly
Oct 31 00:00:14 mythbackend mythbackend: mythbackend[2292]: I TVRecEvent
tv_rec.cpp:3603 (TuningCheckForHWChange) TVRec[9]: HW Tuner: 9->9
Oct 31 00:00:14 mythbackend mythbackend: mythbackend[2292]: N Scheduler
autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max required
Free Space: 3.0 GB w/freq: 7 min
Oct 31 00:00:14 mythbackend mythbackend: mythbackend[2292]: I Scheduler
scheduler.cpp:2689 (HandleRecordingStatusChange) Tuning recording: "CSI:
Crime Scene Investigation":Cockroaches: channel 11710 on car
did 9, sourceid 4
Oct 31 00:00:15 mythbackend mythbackend: mythbackend[2292]: I TVRecEvent
tv_rec.cpp:4130 (TuningNewRecorder) TVRec[9]: rec->GetPathname():
'/data1/recordings/11710_20141031000000.mpg'
Oct 31 00:03:39 mythbackend mythbackend: mythbackend[2292]: I CoreContext
scheduler.cpp:704 (UpdateRecStatus) Updating status for "CSI: Crime Scene
Investigation":Cockroaches on cardid 9 (Tuning => Recordi
ng)
Oct 31 00:04:29 mythbackend mythbackend: mythbackend[2292]: I TVRecEvent
tv_rec.cpp:1567 (HandlePendingRecordings) TVRec[1]: ASK_RECORDING 1 29 0 0
Oct 31 00:04:29 mythbackend mythbackend: mythbackend[2292]: I TVRecEvent
tv_rec.cpp:1567 (HandlePendingRecordings) TVRec[2]: ASK_RECORDING 2 29 0 0
Oct 31 00:04:59 mythbackend mythbackend: mythbackend[2292]: N Scheduler
autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max required
Free Space: 3.0 GB w/freq: 7 min
Oct 31 00:04:59 mythbackend mythbackend: mythbackend[2292]: I Scheduler
scheduler.cpp:2689 (HandleRecordingStatusChange) Started recording: "The
Big Bang Theory":"The Russian Rocket Reaction": channel 1028
on cardid 1, sourceid 1
Oct 31 00:05:00 mythbackend mythbackend: mythbackend[2292]: I DVBRead
tv_rec.cpp:3399 (RingBufferChanged) TVRec[1]: RingBufferChanged()
Oct 31 00:05:00 mythbackend mythbackend: mythbackend[2292]: I DVBRead
recordinginfo.cpp:1075 (FinishedRecording) Finished recording The Big Bang
Theory "The Wiggly Finger Catalyst": channel 1028
Oct 31 00:05:11 mythbackend mythbackend: mythbackend[2292]: I
Metadata_27770 jobqueue.cpp:2156 (DoMetadataLookupThread) JobQueue:
Metadata Lookup Starting for "The Big Bang Theory":"The Wiggly Finger
Catal
yst" recorded from channel 1028 at 2014-10-30T23:36:00Z
Oct 31 00:06:00 mythbackend mythbackend: mythbackend[2292]: I Scheduler
scheduler.cpp:2139 (HandleReschedule) Reschedule requested for PLACE
PrepareToRecord
Oct 31 00:06:00 mythbackend mythbackend: mythbackend[2292]: I Scheduler
scheduler.cpp:2139 (HandleReschedule) Reschedule requested for PLACE
PrepareToRecord
Oct 31 00:06:00 mythbackend mythbackend: mythbackend[2292]: E CoreContext
mainserver.cpp:970 (customEvent) MainServer: PREVIEW_SUCCESS but no
receivers.
Oct 31 00:06:00 mythbackend mythbackend: mythbackend[2292]: I CoreContext
scheduler.cpp:704 (UpdateRecStatus) Updating status for "The Big Bang
Theory":"The Wiggly Finger Catalyst" on cardid 1 (Recording =
> Recorded)
Oct 31 00:06:41 mythbackend mythbackend: mythbackend[2292]: E
MythSocketThread(173) mythsocket.cpp:745 (WriteStringListReal)
MythSocket(94131d8:-1): WriteStringList: Error, called with unconnected
socket.
Oct 31 00:06:41 mythbackend mythbackend: mythbackend[2292]: E
MythSocketThread(81) mythsocket.cpp:745 (WriteStringListReal)
MythSocket(93a63a0:-1): WriteStringList: Error, called with unconnected
socket.
Oct 31 00:06:41 mythbackend mythbackend: mythbackend[2292]: E
MythSocketThread(172) mythsocket.cpp:745 (WriteStringListReal)
MythSocket(940ca40:-1): WriteStringList: Error, called with unconnected
socket.
Oct 31 00:06:41 mythbackend mythbackend: mythbackend[2292]: E
MythSocketThread(79) mythsocket.cpp:745 (WriteStringListReal)
MythSocket(93ae388:-1): WriteStringList: Error, called with unconnected
socket.
Oct 31 00:06:41 mythbackend mythbackend: mythbackend[2292]: E
MythSocketThread(175) mythsocket.cpp:745 (WriteStringListReal)
MythSocket(940b3e0:-1): WriteStringList: Error, called with unconnected
socket.
Oct 31 00:06:41 mythbackend mythbackend: mythbackend[2292]: E
MythSocketThread(177) mythsocket.cpp:745 (WriteStringListReal)
MythSocket(940f6a8:-1): WriteStringList: Error, called with unconnected
socket.
Oct 31 00:06:42 mythbackend mythbackend: mythbackend[2292]: I Scheduler
scheduler.cpp:2243 (HandleReschedule) Reschedule interrupted, will retry
Oct 31 00:11:51 mythbackend mythbackend: mythbackend[2292]: N Expire
autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max required
Free Space: 3.0 GB w/freq: 7 min
Oct 31 00:18:51 mythbackend mythbackend: mythbackend[2292]: N Expire
autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max required
Free Space: 3.0 GB w/freq: 7 min
Oct 31 00:21:00 mythbackend mythbackend: mythbackend[2292]: I Scheduler
scheduler.cpp:2139 (HandleReschedule) Reschedule requested for CHECK -3
1627 0 UpdateRecStatus2 | The Big Bang Theory | The Wiggly Fi
nger Catalyst | Raj feels upset about not being in a relationship, so
Penny sets out to find a date and introduces him to a girl he can actually
talk to. They hit it off, but when it becomes apparent he ha
s been buying her expensive gifts, his friends suspect she is only
interested in his wealth. | EP10079709745
Oct 31 00:21:00 mythbackend mythbackend: mythbackend[2292]: I Scheduler
scheduler.cpp:2139 (HandleReschedule) Reschedule requested for PLACE
Interrupted
Oct 31 00:21:50 mythbackend mythbackend: mythbackend[2292]: I Scheduler
scheduler.cpp:2252 (HandleReschedule) Scheduled 923 items in 50.8 = 0.11
match + 0.09 check + 50.62 place
Oct 31 00:25:51 mythbackend mythbackend: mythbackend[2292]: N Expire
autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max required
Free Space: 3.0 GB w/freq: 7 min
Oct 31 00:32:51 mythbackend mythbackend: mythbackend[2292]: N Expire
autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max required
Free Space: 3.0 GB w/freq: 7 min
Oct 31 00:35:16 mythbackend mythbackend: mythbackend[2292]: I
Metadata_27772 jobqueue.cpp:2156 (DoMetadataLookupThread) JobQueue:
Metadata Lookup Starting for "The Big Bang Theory":"The Russian Rocket
Reac
tion" recorded from channel 1028 at 2014-10-31T00:05:00Z
Oct 31 00:36:00 mythbackend mythbackend: mythbackend[2292]: E
MythSocketThread(65) mythsocket.cpp:745 (WriteStringListReal)
MythSocket(940c250:-1): WriteStringList: Error, called with unconnected
socket.
Oct 31 00:36:00 mythbackend mythbackend: mythbackend[2292]: E
MythSocketThread(64) mythsocket.cpp:745 (WriteStringListReal)
MythSocket(9400490:-1): WriteStringList: Error, called with unconnected
socket.
Oct 31 00:36:00 mythbackend mythbackend: mythbackend[2292]: E
MythSocketThread(79) mythsocket.cpp:745 (WriteStringListReal)
MythSocket(93fa120:-1): WriteStringList: Error, called with unconnected
socket.
Oct 31 00:40:51 mythbackend mythbackend: mythbackend[2292]: N Expire
autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max required
Free Space: 3.0 GB w/freq: 7 min
Oct 31 00:41:01 mythbackend mythbackend: mythbackend[2292]: I TVRecEvent
tv_rec.cpp:1050 (HandleStateChange) TVRec[1]: Changing from RecordingOnly
to None
Oct 31 00:41:02 mythbackend mythbackend: mythbackend[2292]: I TVRecEvent
recordinginfo.cpp:1075 (FinishedRecording) Finished recording The Big Bang
Theory "The Russian Rocket Reaction": channel 1028
Oct 31 00:48:51 mythbackend mythbackend: mythbackend[2292]: N Expire
autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max required
Free Space: 3.0 GB w/freq: 14 min
Oct 31 00:51:00 mythbackend mythbackend: mythbackend[2292]: I CoreContext
scheduler.cpp:704 (UpdateRecStatus) Updating status for "The Big Bang
Theory":"The Russian Rocket Reaction" on cardid 1 (Recording
=> Recorded)
Oct 31 00:51:00 mythbackend mythbackend: mythbackend[2292]: I Scheduler
scheduler.cpp:2139 (HandleReschedule) Reschedule requested for CHECK -3
1627 0 UpdateRecStatus2 | The Big Bang Theory | The Russian R
ocket Reaction | Sheldon's old adversary Wil Wheaton returns and invites
everyone to a housewarming party. Leonard is eager to go, but Sheldon
threatens to shun him if he attends. However, he soon changes
his mind when he finds out that Star Trek: The Next Generation actor Brent
Spiner will also be there. | EP10079709755
Oct 31 00:51:00 mythbackend mythbackend: mythbackend[2292]: E
MythSocketThread(59) mythsocket.cpp:745 (WriteStringListReal)
MythSocket(92be3b8:-1): WriteStringList: Error, called with unconnected
socket.
Oct 31 00:51:00 mythbackend mythbackend: mythbackend[2292]: E
MythSocketThread(61) mythsocket.cpp:745 (WriteStringListReal)
MythSocket(93aaff8:-1): WriteStringList: Error, called with unconnected
socket.
Oct 31 00:51:00 mythbackend mythbackend: mythbackend[2292]: E
MythSocketThread(64) mythsocket.cpp:745 (WriteStringListReal)
MythSocket(93fac78:-1): WriteStringList: Error, called with unconnected
socket.
Oct 31 00:53:07 mythbackend mythbackend: mythbackend[2292]: I
ProcessRequest mainserver.cpp:1443 (HandleAnnounce) MainServer::ANN
Monitor
}}}
--
Ticket URL: <https://code.mythtv.org/trac/ticket/12314>
MythTV <http://www.mythtv.org>
MythTV Media Center
More information about the mythtv-commits
mailing list