help with a suspected race condition in video_out.c

[Roger Scott-2]

Some parts of this message have been removed. Learn more about Nabble's security policy.

Hi xine developers,

I've been banging my head against a brick wall for a while now and don't seem any closer in finding a solution to a problem so I'm hoping someone here can help or at least point me in the right direction.

What I'm getting is frozen video when playing from a new position after opening the stream.  (eg xine_open(s,m); xine_play(s,0,0); some_stuff(); xine_play(s,0,pos )).  I suspect it's some kind of race condition because sometimes it works and sometimes it doesn't.  I can pause the stream and restart it and it's still frozen.  The audio still works, as does SPU/OSD output although the timing for the latter seems somewhat off (sped up).

From what I can figure it's a bug somewhere in video_out.c but I don't know enough of the internals to be able to track it down.  Frames are being appended to the display buffer but there never seems to be anything available (ie get_next_frame always returns 0).  There's no deadlock as all the loops keep going and I can stop and restart the stream and sometimes the video then works.  It's independent of the video output plugin as it's occurring with xv, vdpau, xshm and DFB drivers.  My suspicion is that part of the engine is waiting for the first frame whilst another part thinks it's already been done but I'm not sure.  It might be a frame expiry problem but I'm not getting continuous discarded or skipped messages.

Unfortunately the attach for hotmail doesn't seem to work so I've appended a few lines from turning on the logging in video_out.c below.  Although the numbers vary it's essentially the same continuing output.

Help please.

Roger.

--------------------------------------------------------------

video_out: (video_out_loop:1159) loop iteration at 455657
video_out: (get_next_frame:919) no frame
video_out: (get_next_frame:942) no frame, but no backup frame
video_out: (video_out_loop:1219) next_frame_vpts is 0
video_out: (video_out_loop:1239) 1000 usec to sleep at master vpts 455659
video_out: (vo_frame_draw:463) got image oat master vpts 455849. vpts for pictur
e is 3623016 (pts was 1477219824)
video_out: (vo_frame_draw:517) delivery diff : 3167167, current vpts is 455849,
0 frames to skip
video_out: (vo_frame_draw:568) frame is ok => appending to display buffer
video_out: (vo_get_frame:384) get_frame (720 x 576)
video_out: (vo_remove_from_img_buf_queue_int:236) frame format hit (4/10)
video_out: (vo_get_frame:391) got a frame -> pthread_mutex_lock (&img->mutex)
video_out: (vo_get_frame:426) get_frame (720 x 576) done
video_out: (vo_frame_draw:463) got image oat master vpts 456381. vpts for picture is 3626619 (pts was 1477223424)
video_out: (vo_frame_draw:517) delivery diff : 3170238, current vpts is 456381,
0 frames to skip
video_out: (vo_frame_draw:568) frame is ok => appending to display buffer
video_out: (vo_get_frame:384) get_frame (720 x 576)
video_out: (vo_remove_from_img_buf_queue_int:236) frame format hit (4/10)
video_out: (vo_get_frame:391) got a frame -> pthread_mutex_lock (&img->mutex)
video_out: (vo_get_frame:426) get_frame (720 x 576) done

---

Click Here View photos of singles in your area
------------------------------------------------------------------------------
Let Crystal Reports handle the reporting - Free Crystal Reports 2008 30-Day
trial. Simplify your report design, integration and deployment - and focus on
what you do best, core application coding. Discover what's new with
Crystal Reports now.  http://p.sf.net/sfu/bobj-july
_______________________________________________
xine-devel mailing list
xine-devel@...
https://lists.sourceforge.net/lists/listinfo/xine-devel

[Ian Rae-3]

Roger,

This sounds a lot like a deadlock I have encountered during stress
testing of an abandoned project. In my case the deadlock was caused by
the unprotected use of stream->demux_action_pending internal variable
from play_internal() and from within the demuxer loop.

I've attached a patch that fixed it for me. Basically direct access to
demux_action_pending is replaced with _x_action_raise() and
_x_action_lower() which use a mutex for thread safety.

If this resolves your bug then I'll submit the patch for inclusion in
Xine.

Thanks,
Ian.



On Sun, 2009-09-13 at 12:45 +1030, Roger Scott wrote:

> Hi xine developers,
>
> I've been banging my head against a brick wall for a while now and
> don't seem any closer in finding a solution to a problem so I'm hoping
> someone here can help or at least point me in the right direction.
>
> What I'm getting is frozen video when playing from a new position
> after opening the stream.  (eg xine_open(s,m); xine_play(s,0,0);
> some_stuff(); xine_play(s,0,pos )).  I suspect it's some kind of race
> condition because sometimes it works and sometimes it doesn't.  I can
> pause the stream and restart it and it's still frozen.  The audio
> still works, as does SPU/OSD output although the timing for the latter
> seems somewhat off (sped up).
>
> From what I can figure it's a bug somewhere in video_out.c but I don't
> know enough of the internals to be able to track it down.  Frames are
> being appended to the display buffer but there never seems to be
> anything available (ie get_next_frame always returns 0).  There's no
> deadlock as all the loops keep going and I can stop and restart the
> stream and sometimes the video then works.  It's independent of the
> video output plugin as it's occurring with xv, vdpau, xshm and DFB
> drivers.  My suspicion is that part of the engine is waiting for the
> first frame whilst another part thinks it's already been done but I'm
> not sure.  It might be a frame expiry problem but I'm not getting
> continuous discarded or skipped messages.
>
> Unfortunately the attach for hotmail doesn't seem to work so I've
> appended a few lines from turning on the logging in video_out.c below.
> Although the numbers vary it's essentially the same continuing output.
>
> Help please.
>
> Roger.
>
> --------------------------------------------------------------
>
> video_out: (video_out_loop:1159) loop iteration at 455657
> video_out: (get_next_frame:919) no frame
> video_out: (get_next_frame:942) no frame, but no backup frame
> video_out: (video_out_loop:1219) next_frame_vpts is 0
> video_out: (video_out_loop:1239) 1000 usec to sleep at master vpts
> 455659
> video_out: (vo_frame_draw:463) got image oat master vpts 455849. vpts
> for pictur
> e is 3623016 (pts was 1477219824)
> video_out: (vo_frame_draw:517) delivery diff : 3167167, current vpts
> is 455849,
> 0 frames to skip
> video_out: (vo_frame_draw:568) frame is ok => appending to display
> buffer
> video_out: (vo_get_frame:384) get_frame (720 x 576)
> video_out: (vo_remove_from_img_buf_queue_int:236) frame format hit
> (4/10)
> video_out: (vo_get_frame:391) got a frame -> pthread_mutex_lock
> (&img->mutex)
> video_out: (vo_get_frame:426) get_frame (720 x 576) done
> video_out: (vo_frame_draw:463) got image oat master vpts 456381. vpts
> for picture is 3626619 (pts was 1477223424)
> video_out: (vo_frame_draw:517) delivery diff : 3170238, current vpts
> is 456381,
> 0 frames to skip
> video_out: (vo_frame_draw:568) frame is ok => appending to display
> buffer
> video_out: (vo_get_frame:384) get_frame (720 x 576)
> video_out: (vo_remove_from_img_buf_queue_int:236) frame format hit
> (4/10)
> video_out: (vo_get_frame:391) got a frame -> pthread_mutex_lock
> (&img->mutex)
> video_out: (vo_get_frame:426) get_frame (720 x 576) done
>
>
>
> ______________________________________________________________________
> Click Here View photos of singles in your area
> ------------------------------------------------------------------------------
> Let Crystal Reports handle the reporting - Free Crystal Reports 2008 30-Day
> trial. Simplify your report design, integration and deployment - and focus on
> what you do best, core application coding. Discover what's new with
> Crystal Reports now.  http://p.sf.net/sfu/bobj-july
> _______________________________________________ xine-devel mailing list xine-devel@... https://lists.sourceforge.net/lists/listinfo/xine-devel

[video_out_deadlock.patch]

---

diff --git a/src/xine-lib/src/xine-engine/demux.c b/src/xine-lib/src/xine-engine/demux.c
index 4957841..e52ce96 100644
--- a/src/xine-lib/src/xine-engine/demux.c
+++ b/src/xine-lib/src/xine-engine/demux.c
@@ -149,7 +149,7 @@ void _x_demux_control_headers_done (xine_stream_t *stream) {
   buf_element_t *buf_video, *buf_audio;
 
   /* we use demux_action_pending to wake up sleeping spu decoders */
-  stream->demux_action_pending = 1;
+  _x_action_raise(stream);
   
   /* allocate the buffers before grabbing the lock to prevent cyclic wait situations */
   buf_video = stream->video_fifo->buffer_pool_alloc (stream->video_fifo);
@@ -195,7 +195,7 @@ void _x_demux_control_headers_done (xine_stream_t *stream) {
     pthread_cond_timedwait (&stream->counter_changed, &stream->counter_lock, &ts);
   }
 
-  stream->demux_action_pending = 0;
+  _x_action_lower(stream);
   pthread_cond_signal(&stream->demux_resume);
   
   lprintf ("headers processed.\n");
@@ -282,7 +282,7 @@ static void *demux_loop (void *stream_gen) {
       status = stream->demux_plugin->send_chunk(stream->demux_plugin);
 
       /* someone may want to interrupt us */
-      if( stream->demux_action_pending ) {
+      if (_x_action_pending(stream)) {
         struct timeval tv;
         struct timespec ts;
 
@@ -363,9 +363,9 @@ int _x_demux_start_thread (xine_stream_t *stream) {
   
   lprintf ("start thread called\n");
   
-  stream->demux_action_pending = 1;
+  _x_action_raise(stream);
   pthread_mutex_lock( &stream->demux_lock );
-  stream->demux_action_pending = 0;
+  _x_action_lower(stream);
   pthread_cond_signal(&stream->demux_resume);
   
   if( !stream->demux_thread_running ) {
@@ -394,10 +394,10 @@ int _x_demux_stop_thread (xine_stream_t *stream) {
   
   lprintf ("stop thread called\n");
   
-  stream->demux_action_pending = 1;
+  _x_action_raise(stream);
   pthread_mutex_lock( &stream->demux_lock );
   stream->demux_thread_running = 0;
-  stream->demux_action_pending = 0;
+  _x_action_lower(stream);
   pthread_cond_signal(&stream->demux_resume);
 
   /* At that point, the demuxer has sent the last audio/video buffer,
@@ -501,7 +501,7 @@ off_t _x_read_abort (xine_stream_t *stream, int fd, char *buf, off_t todo) {
         /* aborts current read if action pending. otherwise xine
          * cannot be stopped when no more data is available.
          */
-        if( stream->demux_action_pending )
+        if (_x_action_pending(stream))
           return total;
       } else {
         break;
@@ -542,6 +542,22 @@ int _x_action_pending (xine_stream_t *stream) {
   return stream->demux_action_pending;
 }
 
+/* set demux_action_pending in a thread safe way */
+void _x_action_raise (xine_stream_t *stream)
+{
+  pthread_mutex_lock(&stream->demux_action_lock);
+  stream->demux_action_pending++;
+  pthread_mutex_unlock(&stream->demux_action_lock);
+}
+
+/* reset demux_action_pending in a thread safe way */
+void _x_action_lower (xine_stream_t *stream)
+{
+  pthread_mutex_lock(&stream->demux_action_lock);
+  stream->demux_action_pending--;
+  pthread_mutex_unlock(&stream->demux_action_lock);
+}
+
 /*
  * demuxer helper function to send data to fifo, breaking into smaller
  * pieces (bufs) as needed.
diff --git a/src/xine-lib/src/xine-engine/io_helper.c b/src/xine-lib/src/xine-engine/io_helper.c
index c3654c7..a05dab5 100644
--- a/src/xine-lib/src/xine-engine/io_helper.c
+++ b/src/xine-lib/src/xine-engine/io_helper.c
@@ -244,7 +244,7 @@ int _x_io_select (xine_stream_t *stream, int fd, int state, int timeout_msec) {
            *   aborts current read if action pending. otherwise xine
            *   cannot be stopped when no more data is available.
            */
-          if (stream && stream->demux_action_pending)
+          if (stream && _x_action_pending(stream))
             return XIO_ABORTED;
           break;
         case WAIT_ABANDONED:
@@ -288,7 +288,7 @@ int _x_io_select (xine_stream_t *stream, int fd, int state, int timeout_msec) {
      *   aborts current read if action pending. otherwise xine
      *   cannot be stopped when no more data is available.
      */
-    if (stream && stream->demux_action_pending)
+    if (stream && _x_action_pending(stream))
       return XIO_ABORTED;
 
     total_time_usec += XIO_POLLING_INTERVAL;
diff --git a/src/xine-lib/src/xine-engine/video_decoder.c b/src/xine-lib/src/xine-engine/video_decoder.c
index c88e017..b99f8ab 100644
--- a/src/xine-lib/src/xine-engine/video_decoder.c
+++ b/src/xine-lib/src/xine-engine/video_decoder.c
@@ -91,7 +91,7 @@ int _x_spu_decoder_sleep(xine_stream_t *stream, int64_t next_spu_vpts)
       thread_vacant = (stream->video_fifo->first->type != BUF_CONTROL_FLUSH_DECODER);
     /* we have to return if the demuxer needs us to release a buffer */
     if (thread_vacant)
-      thread_vacant = !stream->demux_action_pending;
+      thread_vacant = !_x_action_pending(stream);
     
   } while (wait == SPU_SLEEP_INTERVAL && thread_vacant);
   
diff --git a/src/xine-lib/src/xine-engine/xine.c b/src/xine-lib/src/xine-engine/xine.c
index 39f2f2d..bc6ed6a 100644
--- a/src/xine-lib/src/xine-engine/xine.c
+++ b/src/xine-lib/src/xine-engine/xine.c
@@ -629,6 +629,7 @@ xine_stream_t *xine_stream_new (xine_t *this,
   pthread_mutex_init (&stream->info_mutex, NULL);
   pthread_mutex_init (&stream->meta_mutex, NULL);
   pthread_mutex_init (&stream->demux_lock, NULL);
+  pthread_mutex_init (&stream->demux_action_lock, NULL);
   pthread_mutex_init (&stream->demux_mutex, NULL);
   pthread_cond_init  (&stream->demux_resume, NULL);
   pthread_mutex_init (&stream->event_queues_lock, NULL);
@@ -1325,7 +1326,7 @@ static int play_internal (xine_stream_t *stream, int start_pos, int start_time)
   }
 
   /* hint demuxer thread we want to interrupt it */
-  stream->demux_action_pending = 1;
+  _x_action_raise(stream);
 
   /* set normal speed */
   if (_x_get_speed(stream) != XINE_SPEED_NORMAL)
@@ -1344,7 +1345,7 @@ static int play_internal (xine_stream_t *stream, int start_pos, int start_time)
   
   pthread_mutex_lock( &stream->demux_lock );
   /* demux_lock taken. now demuxer is suspended */
-  stream->demux_action_pending = 0;
+  _x_action_lower(stream);
   pthread_cond_signal(&stream->demux_resume);
 
   /* set normal speed again (now that demuxer/input pair is suspended)
@@ -1473,6 +1474,7 @@ static void xine_dispose_internal (xine_stream_t *stream) {
   pthread_cond_destroy  (&stream->counter_changed);
   pthread_mutex_destroy (&stream->demux_mutex);
   pthread_cond_destroy  (&stream->demux_resume);
+  pthread_mutex_destroy (&stream->demux_action_lock);
   pthread_mutex_destroy (&stream->demux_lock);
   pthread_mutex_destroy (&stream->first_frame_lock);
   pthread_cond_destroy  (&stream->first_frame_reached);
diff --git a/src/xine-lib/src/xine-engine/xine_internal.h b/src/xine-lib/src/xine-engine/xine_internal.h
index f97ca0b..580821d 100644
--- a/src/xine-lib/src/xine-engine/xine_internal.h
+++ b/src/xine-lib/src/xine-engine/xine_internal.h
@@ -336,6 +336,7 @@ struct xine_stream_s {
   int                        demux_thread_running;
   pthread_mutex_t            demux_lock;
   int                        demux_action_pending;
+  pthread_mutex_t            demux_action_lock;
   pthread_cond_t             demux_resume;
   pthread_mutex_t            demux_mutex; /* used in _x_demux_... functions to synchronize order of pairwise A/V buffer operations */
 
@@ -440,6 +441,9 @@ off_t _x_read_abort (xine_stream_t *stream, int fd, char *buf, off_t todo) XINE_
 
 int _x_action_pending (xine_stream_t *stream) XINE_PROTECTED;
 
+void _x_action_raise (xine_stream_t *stream) XINE_PROTECTED;
+void _x_action_lower (xine_stream_t *stream) XINE_PROTECTED;
+
 void _x_demux_send_data(fifo_buffer_t *fifo, uint8_t *data, int size,
                         int64_t pts, uint32_t type, uint32_t decoder_flags,
                         int input_normpos, int input_time, int total_time,

---

------------------------------------------------------------------------------
Let Crystal Reports handle the reporting - Free Crystal Reports 2008 30-Day
trial. Simplify your report design, integration and deployment - and focus on
what you do best, core application coding. Discover what's new with
Crystal Reports now.  http://p.sf.net/sfu/bobj-july
_______________________________________________
xine-devel mailing list
xine-devel@...
https://lists.sourceforge.net/lists/listinfo/xine-devel

[Roger Scott-2]

Some parts of this message have been removed. Learn more about Nabble's security policy.

> Roger,
 
Hi Ian (and xine-devel list),
 
> This sounds a lot like a deadlock I have encountered during stress

> testing of an abandoned project. In my case the deadlock was caused by
> the unprotected use of stream->demux_action_pending internal variable
> from play_internal() and from within the demuxer loop.
>
> I've attached a patch that fixed it for me. Basically direct access to
> demux_action_pending is replaced with _x_action_raise() and
> _x_action_lower() which use a mutex for thread safety.
>
> If this resolves your bug then I'll submit the patch for inclusion in
> Xine.

 
Unfortunately your patch didn't fix this particular problem but I'd like to test it further as I think it may address some deadlock issues I had to work around by using mutexes and delays around xine calls in my user code.
 
I think I have now resolved my original problem and it was indeed a race condition.  When doing a seek immediately after the first play the code was trying to complete a flush of the buffers by decrementing a discard counter (possibly assuming it had been incremented somewhere else first).  This was causing the counter to go negative and hence all checks against "this->discard_buffer" were evaluating to true and it was never recovering.  I have attached a patch (had to fire up IE in VirtualBox to get hotmail attaches to work properly) which disallows negative values.
 
I also note that there appears to be a similar issue in the audio_out.c file as well as a lack of mutex locking around the increment/decrement.  A patch is also attached for this.  I think this may address similar symptoms I have had with the audio where it would go quiet after a stop/close/open/play sequence.
 
The patches are against an older snapshot but they should go into the newer versions without difficulty.  Could someone please check these patches (they're quite small) and push them into the queue if they are okay?
 
Regards,
Roger.
 

---

Click Here View photos of singles in your area
--- b/src/xine-engine/video_out.c 2008-12-07 10:32:45.000000000 +1100
+++ /home/roger/xine-lib-e9b57f7f5399/src/xine-engine/video_out.c 2009-09-15 09:07:53.000000000 +1000
@@ -1469,10 +1469,11 @@
     pthread_mutex_lock(&this->display_img_buf_queue->mutex);
     if(value)
       this->discard_frames++;
     else
       this->discard_frames--;
+    if (this->discard_frames < 0) this->discard_frames = 0;
     pthread_mutex_unlock(&this->display_img_buf_queue->mutex);
     ret = this->discard_frames;
     
     /* discard buffers here because we have no output thread */
     if (this->grab_only && this->discard_frames) {

--- b/src/xine-engine/audio_out.c 2008-12-07 10:32:45.000000000 +1100
+++ /home/roger/xine-lib-e9b57f7f5399/src/xine-engine/audio_out.c 2009-09-15 09:09:00.000000000 +1000
@@ -1868,14 +1868,17 @@
     }
     break;
   
   case AO_PROP_DISCARD_BUFFERS:
     /* recursive discard buffers setting */
+    pthread_mutex_lock(&this->flush_audio_driver_lock);
     if(value)
       this->discard_buffers++;
     else
       this->discard_buffers--;
+    if (this->discard_buffers < 0) this->discard_buffers = 0;
+    pthread_mutex_unlock(&this->flush_audio_driver_lock);
   
     ret = this->discard_buffers;
     
     /* discard buffers here because we have no output thread */
     if (this->grab_only && this->discard_buffers) {

------------------------------------------------------------------------------
Come build with us! The BlackBerry® Developer Conference in SF, CA
is the only developer event you need to attend this year. Jumpstart your
developing skills, take BlackBerry mobile applications to market and stay
ahead of the curve. Join us from November 9-12, 2009. Register now!
http://p.sf.net/sfu/devconf
_______________________________________________
xine-devel mailing list
xine-devel@...
https://lists.sourceforge.net/lists/listinfo/xine-devel