[mythtv-commits] Ticket #9016: mythbackend hangs due to all DVB-devices becoming busy & unavailable
MythTV
mythtv at cvs.mythtv.org
Thu Oct 7 07:35:30 UTC 2010
#9016: mythbackend hangs due to all DVB-devices becoming busy & unavailable
--------------------------------------------------------+-------------------
Reporter: Tomi Orava <tomi.orava@…> | Owner:
Type: defect | Status: closed
Priority: minor | Milestone: unknown
Component: MythTV - General | Version: Trunk Head
Severity: medium | Resolution: Duplicate
Keywords: | Ticket locked: 0
--------------------------------------------------------+-------------------
Comment (by David Madsen <david.madsen@…>):
The past few days I have noticed a few lingering mythbackend processes
that have been forked off from the main process, but are locked on the
same mutex within libc. The problem doesn't appear to be with the
verbose_mutex itsef, but has to do with the tzset_lock within the tzset
function of glibc:
{{{
void
__tzset (void)
{
__libc_lock_lock (tzset_lock);
tzset_internal (1, 1);
if (!__use_tzfile)
{
/* Set `tzname'. */
__tzname[0] = (char *) tz_rules[0].name;
__tzname[1] = (char *) tz_rules[1].name;
}
__libc_lock_unlock (tzset_lock);
}
}}}
This tzset function is called by QTDateTime::currentDateTime which is used
in the VERBOSE macro. What looks to be happening is a thread is writing
out a verbose message when a context switch occurs while that thread has
locked the tzset_lock. Another thread in mythbackend then proceeds to
fork the mythbackend process to eventually exec it's command, but prior to
that, we execute this in myth_system_fork:
{{{
/* Child */
/* In case we forked WHILE it was locked */
bool unlocked = verbose_mutex.tryLock();
verbose_mutex.unlock();
if( !unlocked )
VERBOSE(VB_IMPORTANT, "Cleared parent's verbose lock");
/* Close all open file descriptors except stdout/stderr */
for (int i = sysconf(_SC_OPEN_MAX) - 1; i > 2; i--)
close(i);
}}}
This forcibly unlocks the verbose mutex which the parent process had
locked (within the tzset task call). We then proceed to execute a new
VERBOSE statement which will again call tzset in the child process. As
the process was copied with the tzset_lock locked form the parent, the
child will be deadlocked at this point.
Since the child process has not yet been able to close it's open file
descriptors, the parent process can later end up with the reported errors
since it appears the DVB devices are still open and in use by the child
process.
This is the limited backtrace I was able to generate.. not everything was
left with debug symbols enabled so it isn't great but at least shows the
trail through currentDateTime. Since this process was also just recently
forked and hasn't yet execed it's command there isn't much code the hung
process could be executing.
{{{
#0 0xb8062424 in __kernel_vsyscall ()
No symbol table info available.
#1 0xb4bd3fa3 in __lll_lock_wait_private () from /lib/libc.so.6
No symbol table info available.
#2 0xb4b8337c in _L_lock_1528 () from /lib/libc.so.6
No symbol table info available.
#3 0xb4b832af in tzset () from /lib/libc.so.6
No symbol table info available.
#4 0xb4ee3954 in QDateTime::currentDateTime() () from
/usr/lib/qt4/libQtCore.so.4
No symbol table info available.
#5 0x96bcfe90 in ?? ()
No symbol table info available.
#6 0x00000000 in ?? ()
No symbol table info available.
}}}
strace output:
{{{
Process 5257 attached - interrupt to quit
futex(0xb4c3da4c, FUTEX_WAIT_PRIVATE, 2, NULL
}}}
Relevant mythbackend log info:
{{{
2010-10-06 19:01:01.046 MPEGRec(/dev/v4l/video2): StartRecording finishing
up
2010-10-06 19:01:01.056 MPEGRec(/dev/v4l/video2): StopEncoding
2010-10-06 19:01:02.732 MPEGRec(/dev/v4l/video2): Encoding stopped
2010-10-06 19:01:02.791 TVRec(14): ClearFlags(RecorderRunning,) ->
RunMainLoop,RingBufferReady,
2010-10-06 19:01:02.792 RecBase(14:/dev/v4l/video2): SetRecording(0x0)
2010-10-06 19:01:02.860 Launching: /usr/bin/mythpreviewgen --size 0x0
--chanid 4723 --starttime 20101006175900 > /dev/null
2010-10-06 19:01:02.891 TVRec(14): FinishedRecording(MythBusters) in
recgroup: Default
2010-10-06 19:01:02.896 PID 5257: launched
2010-10-06 19:01:02.899 Finished recording MythBusters "Hair of the Dog":
channel 4723
2010-10-06 19:01:02.903 TVRec(14): ClearFlags(RecorderRunning,) ->
RunMainLoop,RingBufferReady,
2010-10-06 19:01:02.926 TVRec(14): Tearing down RingBuffer
2010-10-06 19:01:02.932 TVRec(14): ClearFlags(PENDINGACTIONS,) ->
RunMainLoop,RingBufferReady,
}}}
lsof showing the open file descriptors in the child process, showing that
it has not yet executed the loop to close all of it's open handles:
{{{
mythbacke 5257 mythtv 18u CHR 171,0 0t0
1966 /dev/raw1394
mythbacke 5257 mythtv 19u CHR 212,3 0t0
2054 /dev/dvb/adapter0/frontend0
mythbacke 5257 mythtv 68r CHR 212,5 0t0
2049 /dev/dvb/adapter0/dvr0
mythbacke 5257 mythtv 69u CHR 212,4 0t0
2050 /dev/dvb/adapter0/demux0
mythbacke 5257 mythtv 70u CHR 212,4 0t0
2050 /dev/dvb/adapter0/demux0
mythbacke 5257 mythtv 71u CHR 212,4 0t0
2050 /dev/dvb/adapter0/demux0
mythbacke 5257 mythtv 72u CHR 212,4 0t0
2050 /dev/dvb/adapter0/demux0
mythbacke 5257 mythtv 73u CHR 212,4 0t0
2050 /dev/dvb/adapter0/demux0
mythbacke 5257 mythtv 78u CHR 212,4 0t0
2050 /dev/dvb/adapter0/demux0
mythbacke 5257 mythtv 79u CHR 212,4 0t0
2050 /dev/dvb/adapter0/demux0
mythbacke 5257 mythtv 80u CHR 212,4 0t0
2050 /dev/dvb/adapter0/demux0
}}}
Please let me know if I can provide any more info.
It appears it may not be safe to use the VERBOSE macro in the child
process unless there is a way to forcibly unlock the tzset_lock within
glibc in the child as well.
--
Ticket URL: <http://svn.mythtv.org/trac/ticket/9016#comment:2>
MythTV <http://www.mythtv.org/>
MythTV Media Center
More information about the mythtv-commits
mailing list