mythbackend deadlocked during record, EIT scan and reschedule. CPU goes to 100%.

[Paul Netherwood <paul@…>]

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

[Paul Netherwood <paul@…>]

Immediately after deadlock released

[Paul Netherwood <paul@…>]

I've just added two more stack traces, gdb.deadlocked.3.txt while mythbackend was locked and gdb.deadlocked.3.after.txt immediately after after it unlocked itself about 5 minutes later. You can see in the deadlocked file that there are 7 threads all waiting on the same QMutex. They have gone in the second file. It looks like thet are all waiting on a lock in the same place. I suspect there is some locking issue in the scheduler. Note that these stacktraces are with the EIT scanner turned off and during one recording.

[Paul Netherwood <paul@…>]

I think I may have a potential resolution to this problem. Since reverting to an older version of the TBS drivers (v140113) the problem seems to have gone away. I'll keep monitoring but it looks promising. Since the TBS drivers are a closed source version of the whole v4l repository there may be a compatibility issue with their newer drivers potentially conflicting with my old Nova-T cards. Since it only occurs while recording there must be a problem when the scheduler queries the recording status of the card(s).

I'll update this bug and potentially close it if the problem stays resolved.

[Paul Netherwood <paul@…>]

Ok. Problem not solved. It still locks up with multiple scheduler threads all waiting on QMutex.

[Paul Netherwood <paul@…>]

I've managed to reduce the length of the deadlocks further by reducing the number of multirec channels on my DVB-S2 card. I've reduced it from 5 to 2. Now I don't see long duration lockouts but only much shorter ones around the time recordings start and end. In my 0.26 setup I had multirec set to 5 for the DVB-S2 card so maybe the problem is to do with some multrec changes in 0.27.4

My setup is 4x Nova-T cards each with multirec set to two and one TBS 6920 now with multirec set to 2 (previously 5).

[Paul Netherwood <paul@…>]

I've reduced the number of multirec's on all cards to one. The back end still locks up but for a shorter amount of time. Rather than it being an issue with multirec I think reducing the number of encoders from 13 to 5 is more likely to be the reason for the reduce lock up time.

[Paul Netherwood <paul@…>]

Graph of scheduler place time

[Paul Netherwood <paul@…>]

I've added a graph showing the time spent in "place" by the scheduler. Since the upgrade to version v0.27.3-164-g629f711 on Sep 25th, the place time goes up significantly. Prior to that the place time was consistently below 20 seconds. This was on version v0.27.3-5-gdbb4ef3. After that the place time has some very high number including up to 800 seconds. So I suspect a change between version v0.27.3-5-gdbb4ef3 and version v0.27.3-164-g629f711 has caused the problem.

Logs for Scheduler prior on version v0.27.3-5-gdbb4ef3:

Aug  2 06:25:41 mythbackend mythbackend: mythbackend[2575]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1423 items in 19.9 = 0.58 match + 0.05 check + 19.26 place
Aug  2 06:31:27 mythbackend mythbackend: mythbackend[2575]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1423 items in 19.9 = 0.59 match + 0.06 check + 19.23 place
Aug  2 06:33:34 mythbackend mythbackend: mythbackend[2575]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1423 items in 19.3 = 0.00 match + 0.00 check + 19.31 place
Aug  2 06:35:21 mythbackend mythbackend: mythbackend[2575]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1421 items in 21.0 = 0.04 match + 0.01 check + 20.93 place
Aug  2 06:41:39 mythbackend mythbackend: mythbackend[2575]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1420 items in 21.3 = 0.05 match + 0.17 check + 21.07 place
Aug  2 06:49:18 mythbackend mythbackend: mythbackend[2575]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1420 items in 21.3 = 0.01 match + 0.01 check + 21.31 place
Aug  2 06:49:39 mythbackend mythbackend: mythbackend[2575]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1420 items in 21.1 = 0.03 match + 0.01 check + 21.10 place
Aug  2 06:56:23 mythbackend mythbackend: mythbackend[2575]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1417 items in 21.4 = 0.02 match + 0.01 check + 21.40 place
Aug  2 07:04:18 mythbackend mythbackend: mythbackend[2575]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1414 items in 20.9 = 0.02 match + 0.01 check + 20.82 place
Aug  2 07:04:39 mythbackend mythbackend: mythbackend[2575]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1414 items in 21.2 = 0.03 match + 0.01 check + 21.17 place

Recent logs for schedule place time:

Nov 25 21:08:58 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1093 items in 225.0 = 0.00 match + 0.00 check + 224.98 place
Nov 25 21:12:26 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1092 items in 203.6 = 0.01 match + 0.10 check + 203.49 place
Nov 25 22:06:39 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1089 items in 215.2 = 0.00 match + 0.00 check + 215.22 place
Nov 25 22:14:20 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1086 items in 196.1 = 0.01 match + 0.04 check + 196.05 place
Nov 25 22:44:46 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1085 items in 206.0 = 0.00 match + 0.02 check + 206.02 place
Nov 25 22:52:13 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1085 items in 211.7 = 0.00 match + 0.01 check + 211.69 place
Nov 25 22:56:03 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1085 items in 227.7 = 0.00 match + 0.02 check + 227.72 place
Nov 25 23:09:01 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1084 items in 214.8 = 0.00 match + 0.00 check + 214.83 place
Nov 25 23:38:18 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1082 items in 165.4 = 0.00 match + 0.00 check + 165.45 place
Nov 25 23:51:32 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1079 items in 223.3 = 0.00 match + 0.00 check + 223.33 place
Nov 26 00:14:51 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1075 items in 227.0 = 0.22 match + 0.12 check + 226.67 place
Nov 26 00:24:14 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1072 items in 192.4 = 0.02 match + 0.08 check + 192.29 place
Nov 26 00:30:44 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1071 items in 164.9 = 0.03 match + 0.04 check + 164.87 place
Nov 26 02:28:36 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1157 items in 263.1 = 3.33 match + 18.19 check + 241.55 place

[Paul Netherwood <paul@…>]

I think I have successfully traced the problem. The time spent in place in the scheduler was down to a sql statement that was creating a temporary table. My sql database had grown significantly since I first setup the database in 2006 and a retuning of mysql was necessary. After running mysqltuner.pl and a few other tweaks I was able to bring the place time down from 200+ seconds to 1-2 seconds. Since then there have been no occurrences of the lockup.

Please close the ticket.

Thanks

[gigem]

Thanks for the update.