[FFmpeg-devel] [PATCH] pthread_frame: make accesses to debug field be protected by owner lock.

[wm4]

On Fri, 7 Apr 2017 08:30:00 -0400
"Ronald S. Bultje" <rsbultje at gmail.com> wrote:

> Hi,
> 
> On Fri, Apr 7, 2017 at 2:37 AM, wm4 <nfxjfg at googlemail.com> wrote:
> 
> > On Thu,  6 Apr 2017 13:48:41 -0400
> > "Ronald S. Bultje" <rsbultje at gmail.com> wrote:
> >  
> > > The av_log() is done outside the lock, but this way the accesses to the
> > > field (reads and writes) are always protected by a mutex. The av_log()
> > > is not run inside the lock context because it may involve user callbacks
> > > and doing that in performance-sensitive code is probably not a good idea.
> > >
> > > This should fix occasional tsan warnings when running fate-h264, like:
> > >
> > > WARNING: ThreadSanitizer: data race (pid=10916)
> > >   Write of size 4 at 0x7d64000174fc by main thread (mutexes: write  
> > M2313):  
> > >     #0 update_context_from_user src/libavcodec/pthread_frame.c:335  
> > (ffmpeg+0x000000df7b06)  
> > > [..]
> > >   Previous read of size 4 at 0x7d64000174fc by thread T1 (mutexes: write  
> > M2311):  
> > >     #0 ff_thread_await_progress src/libavcodec/pthread_frame.c:592  
> > (ffmpeg+0x000000df8b3e)  
> > > ---
> > >  libavcodec/pthread_frame.c | 20 ++++++++++++--------
> > >  1 file changed, 12 insertions(+), 8 deletions(-)
> > >
> > > diff --git a/libavcodec/pthread_frame.c b/libavcodec/pthread_frame.c
> > > index c246c2f..8857bfc 100644
> > > --- a/libavcodec/pthread_frame.c
> > > +++ b/libavcodec/pthread_frame.c
> > > @@ -559,6 +559,7 @@ void ff_thread_report_progress(ThreadFrame *f, int  
> > n, int field)  
> > >  {
> > >      PerThreadContext *p;
> > >      atomic_int *progress = f->progress ? (atomic_int*)f->progress->data  
> > : NULL;  
> > > +    int debug_mv;
> > >
> > >      if (!progress ||
> > >          atomic_load_explicit(&progress[field], memory_order_relaxed)
> > >= n)
> > > @@ -566,22 +567,24 @@ void ff_thread_report_progress(ThreadFrame *f,  
> > int n, int field)  
> > >
> > >      p = f->owner[field]->internal->thread_ctx;
> > >
> > > -    if (f->owner[field]->debug&FF_DEBUG_THREADS)
> > > -        av_log(f->owner[field], AV_LOG_DEBUG,
> > > -               "%p finished %d field %d\n", progress, n, field);
> > > -
> > >      pthread_mutex_lock(&p->progress_mutex);
> > > +    debug_mv = f->owner[field]->debug&FF_DEBUG_THREADS;
> > >
> > >      atomic_store_explicit(&progress[field], n, memory_order_release);
> > >
> > >      pthread_cond_broadcast(&p->progress_cond);
> > >      pthread_mutex_unlock(&p->progress_mutex);
> > > +
> > > +    if (debug_mv)
> > > +        av_log(f->owner[field], AV_LOG_DEBUG,
> > > +               "%p finished %d field %d\n", progress, n, field);
> > >  }
> > >
> > >  void ff_thread_await_progress(ThreadFrame *f, int n, int field)
> > >  {
> > >      PerThreadContext *p;
> > >      atomic_int *progress = f->progress ? (atomic_int*)f->progress->data  
> > : NULL;  
> > > +    int debug_mv;
> > >
> > >      if (!progress ||
> > >          atomic_load_explicit(&progress[field], memory_order_acquire)
> > >= n)
> > > @@ -589,14 +592,15 @@ void ff_thread_await_progress(ThreadFrame *f, int  
> > n, int field)  
> > >
> > >      p = f->owner[field]->internal->thread_ctx;
> > >
> > > -    if (f->owner[field]->debug&FF_DEBUG_THREADS)
> > > -        av_log(f->owner[field], AV_LOG_DEBUG,
> > > -               "thread awaiting %d field %d from %p\n", n, field,  
> > progress);  
> > > -
> > >      pthread_mutex_lock(&p->progress_mutex);
> > > +    debug_mv = f->owner[field]->debug&FF_DEBUG_THREADS;
> > >      while (atomic_load_explicit(&progress[field],  
> > memory_order_relaxed) < n)  
> > >          pthread_cond_wait(&p->progress_cond, &p->progress_mutex);
> > >      pthread_mutex_unlock(&p->progress_mutex);
> > > +
> > > +    if (debug_mv)
> > > +        av_log(f->owner[field], AV_LOG_DEBUG,
> > > +               "thread awaited %d field %d from %p\n", n, field,  
> > progress);  
> > >  }
> > >
> > >  void ff_thread_finish_setup(AVCodecContext *avctx) {  
> >
> > I'm not sure what "debug_mv" stands for, and I think this is a bit
> > overkill. It's run only when FF_DEBUG_THREADS is set (who even sets
> > that,  
> 
> 
> I actually occasionally use it.
> 
> and why does access to it need to be synchronized?),
> 
> 
> Now that's a really good question.
> 
> Let me give my explanation (which is probably similar to Clement's) and
> then we can see if others agree with it.
> 
> So first of all: is there a race condition here? Really, no. Sort of. A
> race condition is (for me) non-static behaviour in output in response to
> otherwise identical input. So imagine the following code fragment:
> 
> avctx = alloc(threads=2); open(avctx);
> for (i=0;i<5;i++)
>     decode(avctx, frame);
> close(avctx);
> 
> Is there a race condition (with my definition)? No. The code will always
> give the same return values. Now, let's look at this code fragment:
> 
> avctx = alloc(threads=2); open(avctx);
> for (i=0;i<5;i++) {
>     decode(avctx, frame);
>     if (i == 2) { avctx->debug |= THREADS; av_log_set_level(DEBUG); }
> }
> close(avctx);
> 
> Here, a week ago, you got a race condition because user threads would be
> synchronized with the next worker thread unlocked, thus allowing
> debug&THREADS to be updated mid-frame in an active thread. This was fixed
> in 1269cd5.
> 
> Is this a big deal? No, honestly. But it's sort-of a race. If you wanted to
> debug threading, at least it know always produces the same output.
> 
> This patch does not solve a race of that kind. It just removes a tsan
> warning about a protected write and an unprotected read in an unrelated
> thread that is waiting for the "owner" thread. So why would we do that? My
> answer is: primarily to make tsan less noisy. It found "fake" (like this)
> and "real" (some having real implications) races, and we will never find
> the real races unless we silence the fake ones also. As long as I can do
> that without affecting performance and code readability, I'm happy to do
> so. If it affects readability or performance, I will obviously leave it
> as-is.
> 
> so I see no big offense in calling av_log() inside of it.
> 
> 
> There's that also... I have no strong opinion on that.

In that case, maybe better to move the av_log into the block to reduce
the amount of code needed for it. But I have no strong opinion either,
just the ever-present feeling that debug logs should not take up too
much space in the source code.