559793 - possible race on nsTimerImpl::mTimeout

Status: NEW

(Core :: XPCOM, defect)

Description

[Julian Seward [:jseward]]

NOTE, this bug is currently unconfirmed.  See
https://bugzilla.mozilla.org/show_bug.cgi?id=551155#c12
for background and rationale.


HOWTO REPRO: any Fx startup running on Helgrind


One thread reads nsTimerImpl::mTimeout whilst holding
TimerThread::mLock (line 262)

xpcom/threads/TimerThread.cpp:

244 NS_IMETHODIMP TimerThread::Run()
245 {
246   nsAutoLock lock(mLock);
...
262        if (!TIMER_LESS_THAN(now, timer->mTimeout + mTimeoutAdjustment)) {


A second thread later writes it, whilst not obviously holding the lock
(line 572)

xpcom/threads/nsTimerImpl.cpp:

560 void nsTimerImpl::SetDelayInternal(PRUint32 aDelay)
561 {
...
571  if (mTimeout == 0 || mType != TYPE_REPEATING_PRECISE)
572    mTimeout = now;


Is there some synch mechanism here, that I missed?  There are a
couple of other TimerThread-related races, but I'll hold off 
filing them until light is cast on this one.

Comment 1

[Julian Seward [:jseward]]

Raw report is:

Possible data race during write of size 4 at 0xe0d2b44 by thread #1
   at 0x587CED2: nsTimerImpl::SetDelayInternal(unsigned int)
                 (nsTimerImpl.cpp:572)
   by 0x587D401: nsTimerImpl::Setelay(unsigned int) (nsTimerImpl.cpp:307)
   by 0x14125EE5: mozJSComponentLoader::StartFastLoad(nsIFastLoadService*)
                  (mozJSComponentLoader.cpp:1036)
   by 0x14126393: mozJSComponentLoader::GlobalForLocation(nsILocalFile*,
                  JSObject**, char**, long*) (mozJSComponentLoader.cpp:1192)
   by 0x14127CF1: mozJSComponentLoader::LoadModule(nsILocalFile*, nsIModule**)
                  (mozJSComponentLoader.cpp:708)
   by 0x58758D3: nsFactoryEntry::GetFactory(nsIFactory**)
                 (nsComponentManager.cpp:3676)
   by 0x5875A1B: nsComponentManagerImpl::CreateInstanceByContractID(char
                 const*, nsISupports*, nsID const&, void**)
                 (nsComponentManager.cpp:1680)
   by 0x5874D2D: nsComponentManagerImpl::GetServiceByContractID(char const*,
                 nsID const&, void**) (nsComponentManager.cpp:2252)
   by 0x583CCE9: CallGetService(char const*, nsID const&, void**)
                 (nsComponentManagerUtils.cpp:94)
   by 0x583CD0B: nsGetServiceByContractIDWithError::operator()(nsID const&,
                 void**) const (nsComponentManagerUtils.cpp:288)
   by 0x583C119: nsCOMPtr_base::assign_from_gs_contractid_with_error(
                 nsGetServiceByContractIDWithError const&, nsID const&)
                 (nsCOMPtr.cpp:141)
   by 0x174B197D: nsAppStartupNotifier::Observe(nsISupports*, char const*,
                  unsigned short const*) (nsCOMPtr.h:1031)

 This conflicts with a previous read of size 4 by thread #5
   at 0x587DE33: TimerThread::Run() (TimerThread.cpp:262)
   by 0x5879C2C: nsThread::ProcessNextEvent(int, int*) (nsThread.cpp:527)
   by 0x5841B16: NS_ProcessNextEvent_P(nsIThread*, int) (nsThreadUtils.cpp:250)
   by 0x587A0A1: nsThread::ThreadFunc(void*) (nsThread.cpp:254)
   by 0x61018EA: _pt_root (ptthread.c:230)
   by 0x4C2A687: mythread_wrapper (hg_intercepts.c:221)
   by 0x4E34A03: start_thread (pthread_create.c:300)
   by 0x974680C: clone (clone.S:112)

 Address 0xe0d2b44 is 68 bytes inside a block of size 72 alloc'd
   at 0x4C25B08: malloc (vg_replace_malloc.c:236)
   by 0x5AD1F75: moz_xmalloc (mozalloc.cpp:75)
   by 0x5846C14: nsTimerImplConstructor(nsISupports*, nsID const&, void**)
                 (mozalloc.h:222)
   by 0x58428A0: nsGenericFactory::CreateInstance(nsISupports*, nsID const&,
                 void**) (nsGenericFactory.cpp:80)
   by 0x5875A33: nsComponentManagerImpl::CreateInstanceByContractID(char
                 const*, nsISupports*, nsID const&, void**)
                 (nsComponentManager.cpp:1685)
   by 0x583CBEF: CallCreateInstance(char const*, nsISupports*, nsID const&,
                 void**) (nsComponentManagerUtils.cpp:170)
   by 0x583CC1F: nsCreateInstanceByContractID::operator()(nsID const&, void**)
                 const (nsComponentManagerUtils.cpp:210)
   by 0x583C0CD: nsCOMPtr_base::assign_from_helper(nsCOMPtr_helper const&, nsID
                 const&) (nsCOMPtr.cpp:150)
   by 0x14125EAD: mozJSComponentLoader::StartFastLoad(nsIFastLoadService*)
                  (nsCOMPtr.h:707)
   by 0x14126393: mozJSComponentLoader::GlobalForLocation(nsILocalFile*,
                  JSObject**, char**, long*) (mozJSComponentLoader.cpp:1192)
   by 0x14127CF1: mozJSComponentLoader::LoadModule(nsILocalFile*, nsIModule**)
                  (mozJSComponentLoader.cpp:708)
   by 0x58758D3: nsFactoryEntry::GetFactory(nsIFactory**)
                 (nsComponentManager.cpp:3676)

Comment 2

[Boris Zbarsky [:bzbarsky]]

This looks like a bug to me, pure and simple...  ccing likely culprit and component owner.

Comment 3

[Brendan Eich [:brendan]]

Don't forget to cc: culprit numero uno. :-)

It looks like it's "just a bug". Is it a situation where the calls to SetDelayInternal that are operating on a timeout not yet queued to the timer thread don't need to lock, and this case trumped the racing case when we were thinking about this all those years ago? I forget.

/be

Comment 4

[Julian Seward [:jseward]]

(In reply to comment #0)
> There are a couple of other TimerThread-related races, but I'll hold
> off filing them until light is cast on this one.

viz, a similar race occurs on nsTimerImpl::mTimeoutAdjustment:

in TimerThread.cpp:
(W)    TimerThread::UpdateFilter
233    mTimeoutAdjustment = (PRInt32) (smoothSlack * 1.5);
not obviously holding mLock
then
(R)    TimerThread::Run
262        if (!TIMER_LESS_THAN(now, timer->mTimeout + mTimeoutAdjustment)) {
whilst holding mLock


also
(W)    TimerThread::UpdateFilter
233    mTimeoutAdjustment = (PRInt32) (smoothSlack * 1.5);
not obviously holding mLock
then
(R)    TimerThread::Run
322        PRIntervalTime timeout = timer->mTimeout + mTimeoutAdjustment;
whilst holding mLock


In this case it's because TimerThread::UpdateFilter doesn't
take mLock.

Comment 5

[Julian Seward [:jseward]]

> viz, a similar race occurs on nsTimerImpl::mTimeoutAdjustment:

correction: on TimerThread::mTimeoutAdjustment

Comment 6

[Julian Seward [:jseward]]

A slightly bigger picture:

classes TimerThread and nsTimerImpl both have thread-shared
state, at a minumum:

  nsTimerImpl::mTimeout

  TimerThread::mTimeoutAdjustment

TimerThread has a lock to protect its shared state

  TimerThread::mLock

nsTimerImpl doesn't have a lock.

nsTimerImpl befriends itself to TimerThread, so TimerThread can access
nsTimerImpl's shared state.  It uses its lock (TimerThread::mLock) to
make that safe.

nsTimerImpl has no way to make its accesses to its own shared state
safe.  It has no lock of its own and can't use the one in TimerThread
because that's private.

------

Consequently it's easy to get rid of any race of the form
TimerThread::Foo vs TimerThread::Bar, by acquiring mLock as necessary.

But it's not obvious what to do about races between nsTimerImpl::Foo
and TimerThread::Bar.

Comment 7

[Julian Seward [:jseward]]

Attachment: ugly patch that gets rid of the races listed in comments 0 and 4

Comment 8

[Julian Seward [:jseward]]

> nsTimerImpl has no way to make its accesses to its own shared state
> safe.  It has no lock of its own and can't use the one in TimerThread
> because that's private.

> ugly patch that gets rid of the races listed in comments 0 and 4

Ugly because it adds TimerThread::{lock,unlock}(), so that 
nsTimerImpl can use TimerThread::mLock.  Feels like some 
refactoring might be a cleaner solution.

Comment 9

[Julian Seward [:jseward]]

The timer machinery seems to have a bunch of races.  I see them on
the following fields:

  TimerThread::mTimeoutAdjustment
  TimerThread::mDelayLineCounter
  TimerThread::mDelayLine

  nsTimerImpl::mArmed
  nsTimerImpl::mGeneration
  nsTimerImpl::mType
  nsTimerImpl::mTimeout

In all cases, the races involves one thread that holds TimerThread::mLock
racing against one that doesn't hold any locks.

I don't have a way to figure out if these are worth chasing.  After all,
this code has been in the tree for a long time, and so (presumably) it's
not obviously borked.

Comment 10

[Honza Bambas (:mayhemer)]

Just want to know the opinion: what about to write the timer again from scratch or some of the problematic parts?  I would also like to optimize usage of TimeStamp::Now() to TimeStamp::NowLoRes() under some conditions.  It doesn't seem that simple to do with the current code.