998168 - nsITimer shouldn't be used in multiple threads in MediaDecoderStateMachine

Status: RESOLVED FIXED

(Core :: Audio/Video, defect)

Description

[JW Wang [:jwwang] [:jw_wang]]

XPCOM document: http://lxr.mozilla.org/mozilla-central/source/xpcom/threads/nsITimer.idl#51

It is not safe to call nsITimer functions in decoding thread other than the event target thread of the timer.

Comment 1

[JW Wang [:jwwang] [:jw_wang]]

Attachment: part1_fixlog.patch

1. Add |this| pointer to the log message for debugging concurrently running MediaDecoderStateMachine.
2. Decrease log level of some verbose messages for less flooding.

Comment 2

[JW Wang [:jwwang] [:jw_wang]]

Attachment: part2_fixtimer.patch

1. Only call nsITimer functions in state machine thread for nsITimer not thread-safe.
2. Use generation numbers to ignore timer callbacks/runnables that should be canceled for there is no reliable way to do that on a thread other than state machine thread.

Comment 3

[JW Wang [:jwwang] [:jw_wang]]

try: https://tbpl.mozilla.org/?tree=Try&rev=70b007929e1b

Comment 4

[JW Wang [:jwwang] [:jw_wang]]

(In reply to JW Wang [:jwwang] from comment #3)
> try: https://tbpl.mozilla.org/?tree=Try&rev=70b007929e1b

No test_seek timeouts on OSX 10.6 debug over 80 runs.

Comment 5

[Chris Pearce [:cpearce (Not reading bugmail)]]

Comment on attachment 8409628 [details] [diff] [review]
part1_fixlog.patch

Review of attachment 8409628 [details] [diff] [review]:
-----------------------------------------------------------------

I don't think you should use PR_DEBUG_LOG+1. Check for the enviroment variable MOZ_QUIET, and only log if it's not present.

::: content/media/MediaDecoderStateMachine.cpp
@@ +48,4 @@
>  #ifdef PR_LOGGING
>  extern PRLogModuleInfo* gMediaDecoderLog;
> +#define DECODER_LOG(type, msg, ...) \
> +  PR_LOG(gMediaDecoderLog, type, ("DecoderStateMachine(%p)" msg, this, ##__VA_ARGS__))

Why do you need to print out the state machine's this pointer here? Most of the log messages log the value of mDecoder, the pointer to the MediaDecoder. Why can't you rely on that to disambiguate state machines?

Please add the mDecoder pointer to the DECODER_LOG instead of the state machine pointer, unless there's a good reason why not to.

The MediaDecoder pointer is also logged in other related log messages, so it makes it clear which decoder the message is associated with. You'll need to edit the existing log messages that already log mDecoder.

We already don't log some messages if the MOZ_QUIET environment variable is set, so I think we should just keep doing that.

So please add a macro VERBOSE_LOG, and use that where you were adding PR_DEBUG_LOG+1, something like:

#define VERBOSE_LOG(type, msg, ...) \
  if (!PR_GetEnv("MOZ_QUIET")) { \
    PR_LOG(gMediaDecoderLog, type, ("%p " msg, mDecoder.get(), ##__VA_ARGS__)); \
  }

@@ +1857,5 @@
>                !(mMediaSeekable && mTransportSeekable) || mEndTime != -1,
>                "Active seekable media should have end time");
>    MOZ_ASSERT(!(mMediaSeekable && mTransportSeekable) ||
>               GetDuration() != -1, "Seekable media should have duration");
> +  DECODER_LOG(PR_LOG_DEBUG+1, "%p Media goes from %lld to %lld (duration %lld) "

This should happen once per media load, so I don't think you need to silence this warning.

@@ +2324,5 @@
>      return;
>    }
>  
>    if (!PR_GetEnv("MOZ_QUIET")) {
> +    DECODER_LOG(PR_LOG_DEBUG+1, "%p Decoder playing video frame %lld",

Use VERBOSE_LOG.

@@ +2438,5 @@
>        mVideoFrameEndTime = frame->GetEndTime();
>        currentFrame = frame;
>  #ifdef PR_LOGGING
>        if (!PR_GetEnv("MOZ_QUIET")) {
> +        DECODER_LOG(PR_LOG_DEBUG, "%p Decoder discarding video frame %lld", mDecoder.get(), frame->mTime);

Use VERBOSE_LOG.

Comment 6

[Chris Pearce [:cpearce (Not reading bugmail)]]

Comment on attachment 8409630 [details] [diff] [review]
part2_fixtimer.patch

Review of attachment 8409630 [details] [diff] [review]:
-----------------------------------------------------------------

How about in ScheduleStateMachine() you do something like:

if (!OnStateMachineThread()) {
  nsCOMPtr<nsIRunnable> runnable =
      NS_NewRunnableMethodWithArg<uint32_t>(this,
          &MediaDecoderStateMachine::ScheduleStateMachine, ms);
  GetStateMachineThread()->Dispatch(runnable, NS_DISPATCH_NORMAL);
  return;
}

::: content/media/MediaDecoderStateMachine.cpp
@@ +2721,5 @@
> +    return mStateMachine->TimeoutExpired(mGeneration);
> +  }
> +private:
> +  nsRefPtr<MediaDecoderStateMachine> mStateMachine;
> +  int mGeneration;

const

@@ +2754,5 @@
> +
> +  nsresult rv = NS_ERROR_FAILURE;
> +  nsRefPtr<TimerEvent> event = new TimerEvent(this, mGeneration+1);
> +
> +  if (ms == 0) {

You need more comments here explaining why we need to do this.

::: content/media/MediaDecoderStateMachine.h
@@ +939,5 @@
>    MediaDecoderOwner::NextFrameStatus mLastFrameStatus;
> +
> +  // The generation number of timer tasks, used to ignore tasks that are
> +  // scheduled previously.
> +  mozilla::Atomic<int> mGeneration;

Note this doesn't need to be atomic, since mGeneration is only accessed while the decoder monitor is held.

In general, atomics are hard to use correctly, since there's no guarantee that something won't change the atomic value after your thread read the atomic value. Whereas monitor give some degree of certainty of that.

I think you should rename this to mTimerId, to make it clearer that this applies to the timer only, and is not the "generation number" of some other thing.

Comment 7

[JW Wang [:jwwang] [:jw_wang]]

(In reply to Chris Pearce (:cpearce) from comment #6)
> How about in ScheduleStateMachine() you do something like:
> 
> if (!OnStateMachineThread()) {
>   nsCOMPtr<nsIRunnable> runnable =
>       NS_NewRunnableMethodWithArg<uint32_t>(this,
>           &MediaDecoderStateMachine::ScheduleStateMachine, ms);
>   GetStateMachineThread()->Dispatch(runnable, NS_DISPATCH_NORMAL);
>   return;
> }

I tried that before this patch. I found out the decoding thread could call ScheduleStateMachine() several times in a short time resulting a burst of runnables sending to the state machine thread which didn't look very nice to me, and also a mysterious leak in MediaDecoderStateMachine ref count which I didn't dig into.

Comment 8

[JW Wang [:jwwang] [:jw_wang]]

Attachment: part1_fixlog-v2.patch

Comment 9

[JW Wang [:jwwang] [:jw_wang]]

Attachment: part2_fixtimer-v2.patch

Comment 10

[Chris Pearce [:cpearce (Not reading bugmail)]]

Comment on attachment 8410043 [details] [diff] [review]
part1_fixlog-v2.patch

Review of attachment 8410043 [details] [diff] [review]:
-----------------------------------------------------------------

Let's run with this for now. Hopefully in future we can get a new log level added for more verbose debug logging and and use that instead of VERBOSE_LOG.

Comment 11

[Randell Jesup [:jesup] (needinfo me)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/d97882e9c503
https://hg.mozilla.org/integration/mozilla-inbound/rev/243bf2777fa4

Comment 12

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/d97882e9c503
https://hg.mozilla.org/mozilla-central/rev/243bf2777fa4