Closed Bug 1302612 Opened 8 years ago Closed 8 years ago

Intermittent dom/media/test/test_new_audio.html | Test timed out.

Categories

(Core :: Audio/Video: MediaStreamGraph, defect, P2)

Product:
Core
Component:
Audio/Video: MediaStreamGraph
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla52
Tracking Flags:
Tracking Status
firefox49 --- wontfix
firefox50 --- wontfix
firefox51 --- fixed
firefox52 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: pehrsons)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Bug 1302612 - SourceMediaStream: Don't lock mMutex when disconnecting consumers.
58 bytes, text/x-review-board-request
jesup
: review+
gchang
: approval-mozilla-aurora+
Details
Component: Audio/Video → Audio/Video: Playback
See Also: → 1302613
https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=37973779#L5606
https://public-artifacts.taskcluster.net/cO3F4lrNTZWFAMcvOXs2IQ/0/public/logs/live_backing.log

[task 2016-10-20T13:42:44.676852Z] 13:42:44     INFO -  ###!!! ERROR: Potential deadlock detected:
[task 2016-10-20T13:42:44.677869Z] 13:42:44     INFO -  === Cyclical dependency starts at
[task 2016-10-20T13:42:44.679024Z] 13:42:44     INFO -  --- Mutex : mozilla::media::SourceMediaStream (currently acquired)
[task 2016-10-20T13:42:44.680267Z] 13:42:44     INFO -   calling context
[task 2016-10-20T13:42:44.681230Z] 13:42:44     INFO -    [stack trace unavailable]
[task 2016-10-20T13:42:44.682078Z] 13:42:44     INFO -  === Cycle completed at
[task 2016-10-20T13:42:44.682874Z] 13:42:44     INFO -  --- Mutex : mozilla::media::SourceMediaStream (currently acquired)
[task 2016-10-20T13:42:44.683669Z] 13:42:44     INFO -   calling context
[task 2016-10-20T13:42:44.684425Z] 13:42:44     INFO -    [stack trace unavailable]
[task 2016-10-20T13:42:44.685202Z] 13:42:44     INFO -  ###!!! Deadlock may happen NOW!
[task 2016-10-20T13:42:44.685845Z] 13:42:44     INFO -  [Child 1289] ###!!! ASSERTION: Potential deadlock detected:
[task 2016-10-20T13:42:44.686743Z] 13:42:44     INFO -  Cyclical dependency starts at
[task 2016-10-20T13:42:44.687529Z] 13:42:44     INFO -  Mutex : mozilla::media::SourceMediaStream (currently acquired)
[task 2016-10-20T13:42:44.688157Z] 13:42:44     INFO -  Cycle completed at
[task 2016-10-20T13:42:44.688940Z] 13:42:44     INFO -  Mutex : mozilla::media::SourceMediaStream (currently acquired)
[task 2016-10-20T13:42:44.689761Z] 13:42:44     INFO -  ###!!! Deadlock may happen NOW!
[task 2016-10-20T13:42:44.690558Z] 13:42:44     INFO -  : 'Error', file /home/worker/workspace/build/src/xpcom/glue/BlockingResourceBase.cpp, line 307
[task 2016-10-20T13:43:13.212535Z] 13:43:13     INFO -  #01: mozilla::OffTheBooksMutex::Lock [xpcom/glue/BlockingResourceBase.cpp:382]
[task 2016-10-20T13:43:13.214567Z] 13:43:13     INFO -  #02: mozilla::SourceMediaStream::RemoveDirectTrackListenerImpl [dom/media/MediaStreamGraph.cpp:2954]
[task 2016-10-20T13:43:13.215764Z] 13:43:13     INFO -  #03: mozilla::TrackUnionStream::RemoveInput [dom/media/TrackUnionStream.cpp:64]
[task 2016-10-20T13:43:13.217262Z] 13:43:13     INFO -  #04: mozilla::MediaInputPort::Disconnect [dom/media/MediaStreamGraph.cpp:3155]
[task 2016-10-20T13:43:13.218440Z] 13:43:13     INFO -  #05: mozilla::MediaStream::DestroyImpl [dom/media/MediaStreamGraph.cpp:2005]
[task 2016-10-20T13:43:13.219586Z] 13:43:13     INFO -  #06: mozilla::SourceMediaStream::DestroyImpl [dom/media/MediaStreamGraph.cpp:2657]
[task 2016-10-20T13:43:13.221117Z] 13:43:13     INFO -  #07: mozilla::MediaStream::Destroy()::Message::Run()
[task 2016-10-20T13:43:13.221811Z] 13:43:13     INFO -  #08: mozilla::MediaStreamGraphImpl::RunMessagesInQueue [dom/media/MediaStreamGraph.cpp:1243]
[task 2016-10-20T13:43:13.222449Z] 13:43:13     INFO -  #09: mozilla::MediaStreamGraphImpl::OneIteration [dom/media/MediaStreamGraph.cpp:1406]
[task 2016-10-20T13:43:13.223089Z] 13:43:13     INFO -  #10: mozilla::AudioCallbackDriver::DataCallback [dom/media/GraphDriver.cpp:989]
[task 2016-10-20T13:43:13.223749Z] 13:43:13     INFO -  #11: trigger_user_callback [media/libcubeb/src/cubeb_pulse.c:231]
[task 2016-10-20T13:43:13.224408Z] 13:43:13     INFO -  #12: libpulse.so.0 + 0x2ba7e
[task 2016-10-20T13:43:13.225074Z] 13:43:13     INFO -  #13: libpulsecommon-8.0.so + 0x39de2
[task 2016-10-20T13:43:13.225676Z] 13:43:13     INFO -  #14: libpulse.so.0 + 0xef2e
[task 2016-10-20T13:43:13.226307Z] 13:43:13     INFO -  #15: libpulsecommon-8.0.so + 0x3c6cf
[task 2016-10-20T13:43:13.226592Z] 13:43:13     INFO -  #16: libpulsecommon-8.0.so + 0x3eccb
[task 2016-10-20T13:43:13.227495Z] 13:43:13     INFO -  #17: libpulsecommon-8.0.so + 0x3f069
[task 2016-10-20T13:43:13.228788Z] 13:43:13     INFO -  #18: libpulsecommon-8.0.so + 0x3f8ea
[task 2016-10-20T13:43:13.228863Z] 13:43:13     INFO -  #19: libpulse.so.0 + 0x23cb0
[task 2016-10-20T13:43:13.228998Z] 13:43:13     INFO -  #20: libpulse.so.0 + 0x240bc
[task 2016-10-20T13:43:13.229070Z] 13:43:13     INFO -  #21: libpulse.so.0 + 0x24160
[task 2016-10-20T13:43:13.230049Z] 13:43:13     INFO -  #22: libpulse.so.0 + 0x32149
[task 2016-10-20T13:43:13.230658Z] 13:43:13     INFO -  #23: libpulsecommon-8.0.so + 0x4f678
[task 2016-10-20T13:43:13.230894Z] 13:43:13     INFO -  #24: libpthread.so.0 + 0x76fa
[task 2016-10-20T13:43:13.231485Z] 13:43:13     INFO -  #25: libc.so.6 + 0x106b5d
[task 2016-10-20T13:43:13.232302Z] 13:43:13     INFO -  #26: ??? (???:???)

It looks like the timeout is caused by deadlock involving media stream.
Component: Audio/Video: Playback → Audio/Video: MediaStreamGraph
Andreas - any thoughts?  (This is in code from bug 1208371).  Perhaps something else landed in the meantime; it has spiked recently.

Note that this is the only Debug timeout; the deadlock detector only runs in Debug, so it may well have been deadlocking all along.
Flags: needinfo?(pehrson)
This happens when we Destroy() a SourceMediaStream before all direct track listeners have been removed from it. It's mostly a fallback path, which probably explains why it's been quite rare so far.
Assignee: nobody → pehrson
Status: NEW → ASSIGNED
Rank: 25
status-firefox49: --- → affected
status-firefox50: --- → affected
status-firefox51: --- → affected
status-firefox52: --- → affected
Flags: needinfo?(pehrson)
Priority: P5 → P2
Comment on attachment 8803773 [details]
Bug 1302612 - SourceMediaStream: Don't lock mMutex when disconnecting consumers.

https://reviewboard.mozilla.org/r/87922/#review86990

::: dom/media/MediaStreamGraph.cpp:2655
(Diff revision 1)
>  SourceMediaStream::DestroyImpl()
>  {
>    CloseAudioInput();
>  
> +  GraphImpl()->AssertOnGraphThreadOrNotRunning();
> +  for (int32_t i = mConsumers.Length() - 1; i >= 0; --i) {

Normally I'd say to use 'auto', but in this case that'd be bad
Attachment #8803773 - Flags: review?(rjesup) → review+
Pushed by pehrsons@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/f7ffbce9fd97
SourceMediaStream: Don't lock mMutex when disconnecting consumers. r=jesup
https://hg.mozilla.org/mozilla-central/rev/f7ffbce9fd97
Status: ASSIGNED → RESOLVED
Closed: 8 years ago
status-firefox52: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla52
Too late for Beta, but please request Aurora approval on this when you get a chance.
status-firefox49: affected → wontfix
status-firefox50: affected → wontfix
Flags: needinfo?(pehrson)
Comment on attachment 8803773 [details]
Bug 1302612 - SourceMediaStream: Don't lock mMutex when disconnecting consumers.

Approval Request Comment
[Feature/regressing bug #]: bug 1208371
[User impact if declined]: The realtime media thread might hang, making future media captures impossible
[Describe test coverage new/current, TreeHerder]: tests in automation caught it, but only gave clues on debug
[Risks and why]: low risk; test coverage, patch is simple and easy to reason about
[String/UUID change made/needed]: none
Flags: needinfo?(pehrson)
Attachment #8803773 - Flags: approval-mozilla-aurora?
Comment on attachment 8803773 [details]
Bug 1302612 - SourceMediaStream: Don't lock mMutex when disconnecting consumers.

Fix an intermittent test failure. Take it in 51 aurora.
Attachment #8803773 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: