Closed Bug 998168 Opened 10 years ago Closed 10 years ago

nsITimer shouldn't be used in multiple threads in MediaDecoderStateMachine

Categories

(Core :: Audio/Video, defect)

defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla31
Tracking Status
firefox29 --- wontfix
firefox30 --- affected
firefox31 --- affected

People

(Reporter: jwwang, Assigned: jwwang)

References

Details

Attachments

(2 files, 2 obsolete files)

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.
Assignee: nobody → jwwang
Status: NEW → ASSIGNED
Blocks: 994877
Blocks: 981153
Attached patch part1_fixlog.patch (obsolete) — Splinter Review
1. Add |this| pointer to the log message for debugging concurrently running MediaDecoderStateMachine.
2. Decrease log level of some verbose messages for less flooding.
Attachment #8409628 - Flags: review?(cpearce)
Attached patch part2_fixtimer.patch (obsolete) — Splinter Review
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.
Attachment #8409630 - Flags: review?(cpearce)
(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 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.
Attachment #8409628 - Flags: review?(cpearce) → review-
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.
Attachment #8409630 - Flags: review?(cpearce) → review+
(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.
Attachment #8409628 - Attachment is obsolete: true
Attachment #8410043 - Flags: review?(cpearce)
Attachment #8409630 - Attachment is obsolete: true
Attachment #8410044 - Flags: review+
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.
Attachment #8410043 - Flags: review?(cpearce) → review+
Keywords: checkin-needed
You need to log in before you can comment on or make changes to this bug.