[mythtv] Empty and missing recording files when making multiple simultaneous dvb recordings
Roger James
roger at beardandsandals.co.uk
Thu Jun 28 13:43:34 UTC 2012
On 27/06/12 13:52, Roger James wrote:
> Hi,
>
> I am trying to track down a problem with missing or empty recording
> files. These seem to occur when multiple DVB recordings are starting
> at the same time and may be related to recording different channels on
> the same multiplex. My backend is running a fairly recent version of
> 0.25-fixes (Sun May 27). It has two dvb-t cards and one dvb-s card
> each is which is set up to allow simultaneous recordings (3 on the
> dvb-t cards 2 on the dvb-s card). I have captured a log which shows
> the problem. This resulted in one recording with a no file (should be
> /myth2/1009_20120626210000.mpg) and one recording with a empty file
> (/myth4/1002_20120626210000.mpg 376 bytes). These recordings where on
> different channels on the same terrestrial multiplex. The channels
> also available via the DVB-S tuner. The only error message I see in
> the logs is
>
>
> 2012-06-26 21:00:02.655217 I [2501/2700] DVBRead
> dvbstreamhandler.cpp:114 (run) - DVBSH(/dev/dvb/adapter201/frontend0):
> run(): end
> 2012-06-26 21:00:02.655519 W [2501/2511] TVRecEvent
> streamhandler.cpp:186 (Stop) - SH(/dev/dvb/adapter201/frontend0):
> Programmer Error: Start called before Stop finished
> 2012-06-26 21:00:02.655697 I [2501/2707] DVBRead
> dvbstreamhandler.cpp:107 (run) - DVBSH(/dev/dvb/adapter201/frontend0):
> run(): begin
>
I have looked into this some more and think the problem is definitely
caused by the a race condition starting and stopping the stream handler
when recording multiple programs from the same DTV multiplex. After the
signal monitor has done its work both TVRec threads are in a position to
tear down the signal monitor and set up dtvrecoder threads. (N.B. The
server this is running on has a quad processor so up to four threads can
actually run simultaneously.)
2012-06-26 21:00:02.304078 I [2501/2508] TVRecEvent tv_rec.cpp:3779
(TuningSignalCheck) - TVRec(3): Got good signal
2012-06-26 21:00:02.304103 I [2501/2511] TVRecEvent tv_rec.cpp:3779
(TuningSignalCheck) - TVRec(4): Got good signal
2012-06-26 21:00:02.304281 I [2501/2508] TVRecEvent tv_rec.cpp:1989
(TeardownSignalMonitor) - TVRec(3): TeardownSignalMonitor() -- begin
2012-06-26 21:00:02.304330 I [2501/2511] TVRecEvent tv_rec.cpp:1989
(TeardownSignalMonitor) - TVRec(4): TeardownSignalMonitor() -- begin
2012-06-26 21:00:02.304535 I [2501/2501] CoreContext scheduler.cpp:635
(UpdateRecStatus) - Updating status for "Line of Duty" on cardid 3
(Tuning => Recording)
2012-06-26 21:00:02.306905 I [2501/2501] CoreContext scheduler.cpp:635
(UpdateRecStatus) - Updating status for "Ethan Hawke on Macbeth" on
cardid 4 (Tuning => Recording)
Thread 2508 enters RemoveListener and acquires _listener_lock.
2012-06-26 21:00:02.354325 I [2501/2508] TVRecEvent streamhandler.cpp:97
(RemoveListener) - SH(/dev/dvb/adapter201/frontend0):
RemoveListener(0x972e448) -- begin
2012-06-26 21:00:02.354357 I [2501/2508] TVRecEvent
streamhandler.cpp:109 (RemoveListener) -
SH(/dev/dvb/adapter201/frontend0): RemoveListener(0x972e448) -- locked
Thread 2511 enters RemoveListener and blocks on _listener_lock.
2012-06-26 21:00:02.354383 I [2501/2511] TVRecEvent streamhandler.cpp:97
(RemoveListener) - SH(/dev/dvb/adapter201/frontend0):
RemoveListener(0xffffffffa1031e80) -- begin
2508 removes its streams from the listener and because 2511 still has
streams open does not stop the listener but just returns releasing
_listener_lock. N.B. we never see RemoveListener -- end for 2511.
2012-06-26 21:00:02.354418 I [2501/2508] TVRecEvent
streamhandler.cpp:131 (RemoveListener) -
SH(/dev/dvb/adapter201/frontend0): RemoveListener(0x972e448) -- end
2511 is unblocked and acquires _listener_lock, ithen goes on the remove
its streams and because there iare no more streams active on the
listener it goes on to release _listener_lock BEFORE calling the routine
the stop the streamhandler.
2012-06-26 21:00:02.354429 I [2501/2511] TVRecEvent
streamhandler.cpp:109 (RemoveListener) -
SH(/dev/dvb/adapter201/frontend0): RemoveListener(0xffffffffa1031e80) --
locked
Whilst 2511 is still executing the routine to stop the streamhandler,
2508 exits the tear down code and proceeds to sxet up its Recorder.
2012-06-26 21:00:02.354518 I [2501/2508] TVRecEvent tv_rec.cpp:2008
(TeardownSignalMonitor) - TVRec(3): TeardownSignalMonitor() -- end
2012-06-26 21:00:02.354551 I [2501/2508] TVRecEvent tv_rec.cpp:4173
(ClearFlags) - TVRec(3): ClearFlags(SignalMonitorRunning,) ->
RunMainLoop,WaitingForSignal,NeedToStartRecorder,
2012-06-26 21:00:02.354583 I [2501/2508] TVRecEvent tv_rec.cpp:4173
(ClearFlags) - TVRec(3): ClearFlags(WaitingForSignal,) ->
RunMainLoop,NeedToStartRecorder,
2012-06-26 21:00:02.356980 I [2501/2508] TVRecEvent tv_rec.cpp:3929
(TuningNewRecorder) - TVRec(3): Starting Recorder
2012-06-26 21:00:02.363310 I [2501/2508] TVRecEvent tv_rec.cpp:3919
(load_profile) - Using profile 'Default' to record
2012-06-26 21:00:02.363339 I [2501/2508] TVRecEvent tv_rec.cpp:3968
(TuningNewRecorder) - TVRec(3): rec->GetPathname():
'/myth4/1002_20120626210000.mpg'
2012-06-26 21:00:02.363852 I [2501/2508] TVRecEvent dtvrecorder.cpp:167
(ResetForNewFile) - DTVRec(3): ResetForNewFile(void)
2012-06-26 21:00:02.365315 I [2501/2508] TVRecEvent recorderbase.cpp:77
(SetRingBuffer) - RecBase(3:/dev/dvb/adapter201/frontend0):
SetRingBuffer(0xffffffff9f11fa48) '/myth4/1002_20120626210000.mpg'
I have removed a lot of logging about 2508 setting up its recorder.
Stream #11 pid(0x1c24) type(0x0b dsmcc-b std data)
Stream Identifier Descriptor (0x52): ComponentTag=0x68
Stream #12 pid(0x1c25) type(0x0b dsmcc-b std data)
Stre
2012-06-26 21:00:02.367023 I [2501/2508] TVRecEvent recorderbase.cpp:87
(SetRecording) - RecBase(3:/dev/dvb/adapter201/frontend0):
SetRecording(0xffffffffa83d05b0) title(Line of Duty)
2012-06-26 21:00:02.368834 I [2501/2706] RecThread dtvrecorder.cpp:167
(ResetForNewFile) - DTVRec(3): ResetForNewFile(void)
2012-06-26 21:00:02.368881 I [2501/2706] RecThread dvbrecorder.cpp:56
(Open) - DVBRec(3:/dev/dvb/adapter201/frontend0): Card opened successfully
The new dtv recorder thread calls AddListener and is able to acquire
_listener_lock. It then starts the process to add its streams.
2012-06-26 21:00:02.369020 I [2501/2706] RecThread streamhandler.cpp:45
(AddListener) - SH(/dev/dvb/adapter201/frontend0):
AddListener(0x972e448) -- begin
2012-06-26 21:00:02.369076 I [2501/2706] RecThread streamhandler.cpp:57
(AddListener) - SH(/dev/dvb/adapter201/frontend0):
AddListener(0x972e448) -- locked
2012-06-26 21:00:02.373665 I [2501/2508] TVRecEvent tv_rec.cpp:4164
(SetFlags) - TVRec(3): SetFlags(RecorderRunning,RingBufferReady,) ->
RunMainLoop,NeedToStartRecorder,RecorderRunning,RingBufferReady,
2012-06-26 21:00:02.377221 I [2501/2508] TVRecEvent tv_rec.cpp:4173
(ClearFlags) - TVRec(3): ClearFlags(NeedToStartRecorder,) ->
RunMainLoop,RecorderRunning,RingBufferReady,
The Stop called by 2511 is actioned by the streamhandler thread (2700)
2012-06-26 21:00:02.399733 I [2501/2700] DVBRead
dvbstreamhandler.cpp:265 (RunTS) - DVBSH(/dev/dvb/adapter201/frontend0):
RunTS(): shutdown
2012-06-26 21:00:02.399772 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0x0
2012-06-26 21:00:02.399895 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0x1
2012-06-26 21:00:02.399964 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0x10
2012-06-26 21:00:02.400030 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0x11
2012-06-26 21:00:02.400089 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0x14
2012-06-26 21:00:02.400150 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0xc8
2012-06-26 21:00:02.400211 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0xc9
2012-06-26 21:00:02.400267 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0xca
2012-06-26 21:00:02.400326 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0xcd
2012-06-26 21:00:02.400380 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0xce
2012-06-26 21:00:02.400436 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0xd2
2012-06-26 21:00:02.400489 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0xd7
2012-06-26 21:00:02.400540 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0xfa
2012-06-26 21:00:02.400596 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0x190
2012-06-26 21:00:02.400647 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0x191
2012-06-26 21:00:02.400702 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0x192
2012-06-26 21:00:02.400755 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0x195
2012-06-26 21:00:02.400802 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0x196
2012-06-26 21:00:02.400849 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0x19a
2012-06-26 21:00:02.400900 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0x19b
2012-06-26 21:00:02.400946 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0x19f
2012-06-26 21:00:02.400991 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0x1c2
2012-06-26 21:00:02.401039 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0x1c21
2012-06-26 21:00:02.401082 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0x1c22
2012-06-26 21:00:02.401123 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0x1c23
2012-06-26 21:00:02.401197 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0x1c24
2012-06-26 21:00:02.401253 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0x1c25
2012-06-26 21:00:02.401291 I [2501/2700] DVBRead
dvbstreamhandler.cpp:695 (Close) -
PIDInfo(/dev/dvb/adapter201/frontend0): Closing filter for pid 0x1ce9
2012-06-26 21:00:02.655178 I [2501/2700] DVBRead
dvbstreamhandler.cpp:284 (RunTS) - DVBSH(/dev/dvb/adapter201/frontend0):
RunTS(): end
2012-06-26 21:00:02.655217 I [2501/2700] DVBRead
dvbstreamhandler.cpp:114 (run) - DVBSH(/dev/dvb/adapter201/frontend0):
run(): end
The Stop processing returns to 2511 which finds that 2508 has tried to
start the StreamHandler whilst it was stopping it. It never gets to exit
the Stop routine.
2012-06-26 21:00:02.655519 W [2501/2511] TVRecEvent
streamhandler.cpp:186 (Stop) - SH(/dev/dvb/adapter201/frontend0):
Programmer Error: Start called before Stop finished
At this point it looks like streamhandler is in some kind of deadlock.
We never see the RemoveListener -- end for the 2511 signal monitor
thread, and the new recorder thread never opens any pids.
2012-06-26 21:00:02.655697 I [2501/2707] DVBRead
dvbstreamhandler.cpp:107 (run) - DVBSH(/dev/dvb/adapter201/frontend0):
run(): begin
2012-06-26 21:00:02.680242 I [2501/2707] DVBRead
DeviceReadBuffer.cpp:121 (Setup) -
DevRdB(/dev/dvb/adapter201/frontend0): buffer size 9400 KB
2012-06-26 21:00:02.680278 I [2501/2707] DVBRead
DeviceReadBuffer.cpp:128 (Start) -
DevRdB(/dev/dvb/adapter201/frontend0): Start() -- begin
2012-06-26 21:00:02.680354 I [2501/2707] DVBRead
DeviceReadBuffer.cpp:146 (Start) -
DevRdB(/dev/dvb/adapter201/frontend0): Start() -- middle
2012-06-26 21:00:02.680373 I [2501/2707] DVBRead
DeviceReadBuffer.cpp:151 (Start) -
DevRdB(/dev/dvb/adapter201/frontend0): Start() -- end
2012-06-26 21:00:03.153121 I [2501/2530] HouseKeeping
housekeeper.cpp:225 (RunHouseKeeping) - Running housekeeping thread
2012-06-26 21:00:30.099797 I [2501/2517] TVRecEvent tv_rec.cpp:1483
(HandlePendingRecordings) - TVRec(10): Deleting stale pending recording
3 'Line of Duty'
2012-06-26 21:00:30.099867 I [2501/2517] TVRecEvent tv_rec.cpp:1483
(HandlePendingRecordings) - TVRec(10): Deleting stale pending recording
4 'Ethan Hawke on Macbeth'
2012-06-26 21:05:07.159247 I [2501/2530] HouseKeeping
housekeeper.cpp:225 (RunHouseKeeping) - Running housekeeping thread
2012-06-26 21:10:13.165433 I [2501/2530] HouseKeeping
housekeeper.cpp:225 (RunHouseKeeping) - Running housekeeping thread
2012-06-26 21:11:15.562175 N [2501/2531] Expire autoexpire.cpp:263
(CalcParams) - AutoExpire: CalcParams(): Max required Free Space: 3.0 GB
w/freq: 7 min
2012-06-26 21:15:17.171588 I [2501/2530] HouseKeeping
housekeeper.cpp:225 (RunHouseKeeping) - Running housekeeping thread
2012-06-26 21:19:15.591174 N [2501/2531] Expire autoexpire.cpp:263
(CalcParams) - AutoExpire: CalcParams(): Max required Free Space: 3.0 GB
w/freq: 7 min
2012-06-26 21:20:18.177224 I [2501/2530] HouseKeeping
housekeeper.cpp:225 (RunHouseKeeping) - Running housekeeping thread
2012-06-26 21:24:40.949475 I [2501] ProcessRequest mainserver.cpp:1361
(HandleAnnounce) - MainServer::ANN Playback
Does anyone know if this has been fixed. If not this looks like a bug
which is beyond my knowledge to fix. I cannot understand how the threads
are getting past the _start_stop_lock which is supposed to prevent this
sort of thing. I am suspicious of the interaction between
QMutexLocker locker(&_start_stop_lock);
and
_running_state_changed.wait(&_start_stop_lock, 100);
which is a construct used in a number of places.
In the meantime if have reduced all my capture cards to allowing only
one simultaneous recording, and I will live with any conflicts!
Roger
More information about the mythtv-dev
mailing list