Closed Bug 995690 Opened 10 years ago Closed 10 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: 10 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: