Closed Bug 995690 Opened 11 years ago Closed 11 years ago

Intermittent test_getIdentityAssertion.html, test_setIdentityProvider.html | application crashed [@ mozilla::MediaStreamGraphImpl::PlayAudio()] after "Assertion failure: track->IsEnded() (Not enough data, and track not ended.)"

Categories

(Core :: Audio/Video, defect)

Product:
Core
Component:
Audio/Video
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla33
Tracking Flags:
Tracking Status
firefox30 --- unaffected
firefox31 --- fixed
firefox32 --- fixed
firefox33 --- fixed
firefox-esr24 --- unaffected
b2g-v1.4 --- unaffected
b2g-v2.0 --- fixed
b2g-v2.1 --- fixed

People

(Reporter: RyanVM, Assigned: karlt)

References

Details

(Keywords: assertion, crash, intermittent-failure, Whiteboard: [qa-])

Attachments

(2 files, 2 obsolete files)

correct mLastTickWritten to only advance when not blocked v2
4.50 KB, patch
roc
: review+
Details | Diff | Splinter Review
don't advance audio output stream position 1 tick beyond what has been produced v2
2.01 KB, patch
roc
: review+
padenot
: feedback+
Sylvestre
: approval-mozilla-aurora+
Sylvestre
: approval-mozilla-beta+
Details | Diff | Splinter Review
https://tbpl.mozilla.org/php/getParsedLog.php?id=37656318&tree=Mozilla-Central Windows XP 32-bit mozilla-central debug test mochitest-3 on 2014-04-11 15:03:08 PDT for push 71a02d5403f9 slave: t-xp32-ix-055 15:05:35 INFO - Assertion failure: track->IsEnded() (Not enough data, and track not ended.), at c:\builds\moz2_slave\m-cen-w32-d-000000000000000000\build\content\media\MediaStreamGraph.cpp:943 15:05:35 INFO - nsStringStats 15:05:35 INFO - => mAllocCount: 61430 15:05:35 INFO - => mReallocCount: 5583 15:05:35 INFO - => mFreeCount: 45055 -- LEAKED 16375 !!! 15:05:35 INFO - => mShareCount: 95267 15:05:35 INFO - => mAdoptCount: 3665 15:05:35 INFO - => mAdoptFreeCount: 3656 -- LEAKED 9 !!! 15:05:35 INFO - => Process ID: 3840, Thread ID: 1376 15:05:35 INFO - TEST-INFO | Main app process: exit status 80000003 15:05:35 WARNING - TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/identity/test_getIdentityAssertion.html | application terminated with exit code 2147483651 15:05:35 INFO - INFO | runtests.py | Application ran for: 0:00:16.891000 15:05:35 INFO - INFO | zombiecheck | Reading PID log: c:\docume~1\cltbld~1.t-x\locals~1\temp\tmptnxmnlpidlog 15:05:42 WARNING - PROCESS-CRASH | /tests/dom/media/tests/identity/test_getIdentityAssertion.html | application crashed [@ mozilla::MediaStreamGraphImpl::PlayAudio(mozilla::MediaStream *,__int64,__int64)] 15:05:42 INFO - Crash dump filename: c:\docume~1\cltbld~1.t-x\locals~1\temp\tmpirs7s4\minidumps\12bfd052-e036-4771-8a14-d105d54ba8af.dmp 15:05:42 INFO - Operating system: Windows NT 15:05:42 INFO - 5.1.2600 Service Pack 3 15:05:42 INFO - CPU: x86 15:05:42 INFO - GenuineIntel family 6 model 30 stepping 5 15:05:42 INFO - 8 CPUs 15:05:42 INFO - Crash reason: EXCEPTION_BREAKPOINT 15:05:42 INFO - Crash address: 0x2b55962 15:05:42 INFO - Thread 59 (crashed) 15:05:42 INFO - 0 xul.dll!mozilla::MediaStreamGraphImpl::PlayAudio(mozilla::MediaStream *,__int64,__int64) [MediaStreamGraph.cpp:71a02d5403f9 : 866 + 0x23] 15:05:42 INFO - eip = 0x02b55962 esp = 0x19a7fc6c ebp = 0x19a7fcfc ebx = 0x00000000 15:05:42 INFO - esi = 0x15481bd0 edi = 0x00000180 eax = 0x00000000 ecx = 0x7c1e46de 15:05:42 INFO - edx = 0x10361f48 efl = 0x00000206 15:05:42 INFO - Found by: given as instruction pointer in context 15:05:42 INFO - 1 xul.dll!mozilla::MediaStreamGraphImpl::RunThread() [MediaStreamGraph.cpp:71a02d5403f9 : 1343 + 0x13] 15:05:42 INFO - eip = 0x02b57297 esp = 0x19a7fd04 ebp = 0x19a7fdf8 15:05:42 INFO - Found by: call frame info 15:05:42 INFO - 2 xul.dll!mozilla::`anonymous namespace'::MediaStreamGraphInitThreadRunnable::Run() [MediaStreamGraph.cpp:71a02d5403f9 : 1483 + 0xc] 15:05:42 INFO - eip = 0x02b5763a esp = 0x19a7fe00 ebp = 0x19a7fe04 15:05:42 INFO - Found by: call frame info 15:05:42 INFO - 3 xul.dll!nsThread::ProcessNextEvent(bool,bool *) [nsThread.cpp:71a02d5403f9 : 699 + 0xd] 15:05:42 INFO - eip = 0x01a9d0eb esp = 0x19a7fe0c ebp = 0x19a7fe68 15:05:42 INFO - Found by: call frame info 15:05:42 INFO - 4 xul.dll!NS_ProcessNextEvent(nsIThread *,bool) [nsThreadUtils.cpp:71a02d5403f9 : 263 + 0xc] 15:05:42 INFO - eip = 0x01a2e987 esp = 0x19a7fe70 ebp = 0x19a7fe7c 15:05:42 INFO - Found by: call frame info 15:05:42 INFO - 5 xul.dll!mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate *) [MessagePump.cpp:71a02d5403f9 : 307 + 0x9] 15:05:42 INFO - eip = 0x01cefe1d esp = 0x19a7fe84 ebp = 0x19a7fea8 15:05:42 INFO - Found by: call frame info 15:05:42 INFO - 6 xul.dll!MessageLoop::RunInternal() [message_loop.cc:71a02d5403f9 : 226 + 0x8] 15:05:42 INFO - eip = 0x01cafef2 esp = 0x19a7feb0 ebp = 0x19a7fec8 15:05:42 INFO - Found by: call frame info 15:05:42 INFO - 7 xul.dll!MessageLoop::RunHandler() [message_loop.cc:71a02d5403f9 : 219 + 0x4] 15:05:42 INFO - eip = 0x01cb115d esp = 0x19a7fed0 ebp = 0x19a7fefc 15:05:42 INFO - Found by: call frame info 15:05:42 INFO - 8 xul.dll!MessageLoop::Run() [message_loop.cc:71a02d5403f9 : 193 + 0x6] 15:05:42 INFO - eip = 0x01cb224c esp = 0x19a7ff04 ebp = 0x19a7ff1c 15:05:42 INFO - Found by: call frame info
While line 866 appears to be a MOZ_ASSERT(mRealtime), I think this is likely coming from: TrackTicks ticksNeeded = TimeToTicksRoundDown(IdealAudioRate(), aTo) - TimeToTicksRoundDown(IdealAudioRate(), aFrom); if (aStream->mAudioOutputStreams.IsEmpty()) {
Fwiw, bug 931455 has a testcase that triggers the same fatal assertion reliably.
Depends on: 931455
https://tbpl.mozilla.org/php/getParsedLog.php?id=38726367&tree=Mozilla-Inbound
OS: Windows XP → All
Hardware: x86 → All
Summary: Intermittent test_getIdentityAssertion.html | application crashed [@ mozilla::MediaStreamGraphImpl::PlayAudio(mozilla::MediaStream *,__int64,__int64)] after "(Assertion failure: track->IsEnded() (Not enough data, and track not ended.)" → Intermittent test_getIdentityAssertion.html,test_setIdentityProvider.html | application crashed [@ mozilla::MediaStreamGraphImpl::PlayAudio()] after "(Assertion failure: track->IsEnded() (Not enough data, and track not ended.)"
Summary: Intermittent test_getIdentityAssertion.html,test_setIdentityProvider.html | application crashed [@ mozilla::MediaStreamGraphImpl::PlayAudio()] after "(Assertion failure: track->IsEnded() (Not enough data, and track not ended.)" → Intermittent test_getIdentityAssertion.html, test_setIdentityProvider.html | application crashed [@ mozilla::MediaStreamGraphImpl::PlayAudio()] after "Assertion failure: track->IsEnded() (Not enough data, and track not ended.)"
Some logging at https://tbpl.mozilla.org/?tree=Try&rev=5a8283d498b2 indicates that this happens when offset is advanced 1 tick beyond the expected position at https://hg.mozilla.org/mozilla-central/rev/2bf5b49d85e7#l6.134 Given that and the requirement to process the same number of ticks, it means that subsequent code needs to read a frame for 1 tick beyond what the track union stream has copied to its buffer. That situation is probably happening (more often than would be expected from rounding) due to incorrectly advancing mLastTickWritten with graph ticks rather than with stream ticks. https://tbpl.mozilla.org/?tree=Try&rev=4b87d30231a6 (These try runs also contain patches to run MediaTime at the graph's audio sample rate.)
Assignee: nobody → karlt
Blocks: 982490
Status: NEW → ASSIGNED
mLastTickWritten and offset are stream positions, which do not advance when the stream is blocked.
Attachment #8436742 - Flags: review?(paul)
This may result in repeating a sample sometimes due to rounding effects, but that should only happen once per unblocked sequence of track frames.
Attachment #8436743 - Flags: review?(paul)
Blocks: 1023697
This version removes some places where mLastTickWritten was set. These are now unnecessary because it is now set later.
Attachment #8436742 - Attachment is obsolete: true
Attachment #8436742 - Flags: review?(paul)
Attachment #8438860 - Flags: review?(paul)
This version updates the comment to be consistent with the new code.
Attachment #8436743 - Attachment is obsolete: true
Attachment #8436743 - Flags: review?(paul)
Attachment #8438861 - Flags: review?(paul)
https://hg.mozilla.org/mozilla-central/rev/2f5473458f0a https://hg.mozilla.org/mozilla-central/rev/698fae4afa72
Status: ASSIGNED → RESOLVED
Closed: 11 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla33
woowoo! Please request Aurora and Beta approval on this when you're confident enough that it's ready :)
status-b2g-v1.4: --- → unaffected
status-b2g-v2.0: --- → affected
status-b2g-v2.1: --- → fixed
status-firefox30: --- → unaffected
status-firefox31: --- → affected
status-firefox32: --- → affected
status-firefox33: --- → fixed
status-firefox-esr24: --- → unaffected
Comment on attachment 8438861 [details] [diff] [review] don't advance audio output stream position 1 tick beyond what has been produced v2 I'd like to check that Paul is happy with this part before uploading to Beta. Hitting the (offset - audioOutput.mLastTickWritten == -1) case was pretty bad (inserting zero samples) before this patch landed. I think the new behavior can only be an improvement. (The other part should be fine, and may be sufficient on its own for the tests, but I think this would be an improvement that we should take on beta)
Attachment #8438861 - Flags: feedback?(paul)
Comment on attachment 8438861 [details] [diff] [review] don't advance audio output stream position 1 tick beyond what has been produced v2 Review of attachment 8438861 [details] [diff] [review]: ----------------------------------------------------------------- That should be better indeed.
Attachment #8438861 - Flags: feedback?(paul) → feedback+
Comment on attachment 8438861 [details] [diff] [review] don't advance audio output stream position 1 tick beyond what has been produced v2 Requesting approval for both patches here. [Approval Request Comment] Bug caused by (feature/regressing bug #): bug 982490 User impact if declined: This mostly affects tests, where debug tests abort the test run when this happens. I'm guessing it is pretty much only happening in debug builds where things run slower and so the stream pauses waiting for new data, but we don't have the assertion in opt builds, so we don't really know whether it is happening there. If it is happening in opt builds, it could be happening in real life, and would present as a brief click in the audio output. There are other bugs causing worse clicks, so improvements here are most likely not audibly distinguishable. Testing completed (on m-c, etc.): on m-c, locally. Risk to taking this patch (and alternatives if risky): Some risk. Due to being at the output end of processing, this is not covered by automated tests. However, the success of the fix for the assertion failure (in m-c debug builds) gives us confidence in the patch. String or IDL/UUID changes made by this patch: none
Attachment #8438861 - Flags: approval-mozilla-beta?
Attachment #8438861 - Flags: approval-mozilla-aurora?
Comment on attachment 8438861 [details] [diff] [review] don't advance audio output stream position 1 tick beyond what has been produced v2 Accept for both aurora et beta to get maximum user coverage in beta 3.
Attachment #8438861 - Flags: approval-mozilla-beta?
Attachment #8438861 - Flags: approval-mozilla-beta+
Attachment #8438861 - Flags: approval-mozilla-aurora?
Attachment #8438861 - Flags: approval-mozilla-aurora+
Whiteboard: [qa-]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: