Closed Bug 989047 Opened 11 years ago Closed 11 years ago

Intermittent test_getUserMedia_playVideoTwice.html,test_getUserMedia_stopVideoAudioStreamWithFollowupVideoAudio.html,test_getUserMedia_gumWithinGum.html | Unexpected callback with = 'canplaythrough event never fired'

Categories

(Core :: WebRTC, defect)

Product:
Core
Component:
WebRTC
Platform:
ARM
Gonk (Firefox OS)
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla31
Tracking Flags:
Tracking Status
firefox29 --- unaffected
firefox30 --- fixed
firefox31 --- fixed
firefox-esr24 --- unaffected
b2g-v1.3 --- fixed
b2g-v1.3T --- fixed
b2g-v1.4 --- fixed
b2g-v2.0 --- fixed

People

(Reporter: RyanVM, Assigned: jwwang)

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Increase the timeout value for the canplaythrough event
2.99 KB, patch
jesup
: review+
Details | Diff | Splinter Review
https://tbpl.mozilla.org/php/getParsedLog.php?id=36824432&tree=Mozilla-Inbound b2g_emulator_vm mozilla-inbound debug test mochitest-debug-10 on 2014-03-27 11:51:55 PDT for push 012fea76225f slave: tst-linux64-spot-749 12:01:44 INFO - 8 INFO TEST-START | /tests/dom/media/tests/mochitest/test_getUserMedia_playVideoTwice.html 12:02:06 INFO - [Parent 641] WARNING: A control runnable was posted to a worker that is already shutting down!: file ../../../gecko/dom/workers/WorkerPrivate.cpp, line 2232 12:02:06 INFO - [Parent 641] WARNING: A control runnable was posted to a worker that is already shutting down!: file ../../../gecko/dom/workers/WorkerPrivate.cpp, line 2232 12:02:08 INFO - 9 INFO TEST-INFO | dumping last 3 message(s) 12:02:08 INFO - 10 INFO TEST-INFO | if you need more context, please use SimpleTest.requestCompleteLog() in your test 12:02:08 INFO - 11 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_getUserMedia_playVideoTwice.html | Call getUserMedia for {"video":true,"fake":true} 12:02:09 INFO - 12 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_getUserMedia_playVideoTwice.html | Stream should be a LocalMediaStream 12:02:09 INFO - 13 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_getUserMedia_playVideoTwice.html | Before starting the media element, currentTime = 0 12:02:09 INFO - 14 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_getUserMedia_playVideoTwice.html | Unexpected callback with = 'canplaythrough event never fired' at: ["@http://mochi.test:8888/tests/dom/media/tests/mochitest/test_getUserMedia_playVideoTwice.html:39:1",""] 12:02:10 INFO - 15 INFO TEST-INFO | MEMORY STAT vsize after test: 102948864 12:02:10 INFO - 16 INFO TEST-INFO | MEMORY STAT residentFast after test: 51515392 12:02:10 INFO - 17 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 13163068 12:02:11 INFO - *** UTM:SVC TimerManager:notify - notified timerID: user-agent-updates-timer 12:02:14 INFO - 18 INFO TEST-END | /tests/dom/media/tests/mochitest/test_getUserMedia_playVideoTwice.html | finished in 29715ms
https://tbpl.mozilla.org/php/getParsedLog.php?id=36880995&tree=Fx-Team
Summary: Intermittent test_getUserMedia_playVideoTwice.html | Unexpected callback with = 'canplaythrough event never fired' → Intermittent test_getUserMedia_playVideoTwice.html,test_getUserMedia_stopVideoAudioStreamWithFollowupVideoAudio.html | Unexpected callback with = 'canplaythrough event never fired'
Summary: Intermittent test_getUserMedia_playVideoTwice.html,test_getUserMedia_stopVideoAudioStreamWithFollowupVideoAudio.html | Unexpected callback with = 'canplaythrough event never fired' → Intermittent test_getUserMedia_playVideoTwice.html,test_getUserMedia_stopVideoAudioStreamWithFollowupVideoAudio.html,test_getUserMedia_gumWithinGum.html | Unexpected callback with = 'canplaythrough event never fired'
This seems to happen only with tests which try to do things twice with video on B2G emulator (in other words: the playAudioTwice.html never shows up). Not sure if that tells us anything useful.
cpearce: can you help out with this? It's B2G emulator-only. See also comment 45 by nils. Is there more info or debugging that would help? (It's pretty frequent, I imagine a test push with extra logging would hit it in a 5 or 10 respins of the test.) Could IPC be involved? Adding roc as well for visibility in case he has any thoughts.
Flags: needinfo?(cpearce)
jw: can you look into this when you get time please?
Flags: needinfo?(cpearce) → needinfo?(jwwang)
Sure.
Assignee: nobody → jwwang
Status: NEW → ASSIGNED
Flags: needinfo?(jwwang)
It looks like 'canplaythrough' is not fired. Since 'canplaythrough' depends on download speed and playback rate, it could fire zero or more than once. Is this event required for the test to pass?
Flags: needinfo?(jsmith)
(In reply to JW Wang[:jwwang] from comment #58) > It looks like 'canplaythrough' is not fired. Since 'canplaythrough' depends > on download speed and playback rate, it could fire zero or more than once. > Is this event required for the test to pass? Yes. canplaythrough is used to identify that the media element has began playback via the gUM media stream. So if this isn't firing, then this is likely a bug in the media stream code.
Flags: needinfo?(jsmith)
FWIW, this is currently the #3 orange on trunk.
(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #73) > FWIW, this is currently the #3 orange on trunk. Ok - let me ask :roc for input here on why canplaythrough is failing to fire here in these tests.
Flags: needinfo?(roc)
I added some logs to trace the state change of the media elemnt. 04-02 07:54:07.790 704 704 I PRLog : 2014-04-02 07:54:07.793277 UTC - 1074377864[40222080]: 440eaae0 Ready state changed to HAVE_CURRENT_DATA 04-02 07:54:29.890 704 704 I PRLog : 2014-04-02 07:54:29.892767 UTC - 1074377864[40222080]: 440eaae0 Queuing event loadeddata 04-02 07:54:29.890 704 704 I PRLog : 2014-04-02 07:54:29.893537 UTC - 1074377864[40222080]: 440eaae0 FirstFrameLoaded=0, mLoadedFirstFrame=1 04-02 07:54:29.890 704 704 I PRLog : 2014-04-02 07:54:29.893945 UTC - 1074377864[40222080]: 440eaae0 Ready state changed to HAVE_ENOUGH_DATA 04-02 07:54:29.890 704 704 I PRLog : 2014-04-02 07:54:29.894214 UTC - 1074377864[40222080]: 440eaae0 Queuing event canplay 04-02 07:54:29.890 704 704 I PRLog : 2014-04-02 07:54:29.894745 UTC - 1074377864[40222080]: 440eaae0 Queuing event playing 04-02 07:54:29.890 704 704 I PRLog : 2014-04-02 07:54:29.895208 UTC - 1074377864[40222080]: 440eaae0 Queuing event canplaythrough The interval between the first 2 log messages is over 10s which exceeds the timeout in mediaStreamPlayback.js. Therefore the test fails even though the 'canplaythrough' event comes later. There is only one place to dispatch 'loadeddata' event which is HTMLMediaElement::ChangeReadyState. It is surprising to see this function call last more than 10s. I will add more logs to see if they are coming from the same function call.
(In reply to JW Wang[:jwwang] from comment #82) > The interval between the first 2 log messages is over 10s which exceeds the > timeout in mediaStreamPlayback.js. Therefore the test fails even though the > 'canplaythrough' event comes later. There is only one place to dispatch > 'loadeddata' event which is HTMLMediaElement::ChangeReadyState. It is > surprising to see this function call last more than 10s. I will add more > logs to see if they are coming from the same function call. Maybe the 10s are not as crazy as you would think. The timer on this in mediaStreamPlayback.js starts early on in the test (directly from the html of the test case). But if 'canplaythrough' for video only fires if the data is successfully received from the network (which IMHO is a good/the correct implementation), then this could take quite some time, as first the PeerConnection with all its underlying layers (ICE etc) need to get established. Maybe the B2G emulator is just really slow here in general and therefore it takes so much time?! Currently the timeout measures basically 'test start' -> 'video plays'. I'm wondering if the right thing to do here is to change it to something like 'network connection got established' -> 'video plays'?
We should really get rid of the 10 second timeout if it's causing problems here. The goal of this test to make that media eventually starts playing & has the right attributes, not assess the length it takes for a certain event to fire.
This is the code with extra logs: void HTMLMediaElement::ChangeReadyState(nsMediaReadyState aState) { nsMediaReadyState oldState = mReadyState; mReadyState = aState; if (mNetworkState == nsIDOMHTMLMediaElement::NETWORK_EMPTY || oldState == mReadyState) { return; } LOG(PR_LOG_DEBUG, ("%p Ready state changed to %s", this, gReadyStateToString[aState])); TimeStamp t1 = TimeStamp::Now(); UpdateAudioChannelPlayingState(); // Handle raising of "waiting" event during seek (see 4.8.10.9) if (mPlayingBeforeSeek && oldState < nsIDOMHTMLMediaElement::HAVE_FUTURE_DATA) { DispatchAsyncEvent(NS_LITERAL_STRING("waiting")); } if (oldState < nsIDOMHTMLMediaElement::HAVE_CURRENT_DATA && mReadyState >= nsIDOMHTMLMediaElement::HAVE_CURRENT_DATA && !mLoadedFirstFrame) { DispatchAsyncEvent(NS_LITERAL_STRING("loadeddata")); mLoadedFirstFrame = true; TimeDuration dt = TimeStamp::Now() - t1; LOG(PR_LOG_DEBUG, ("%p dispatch loadeddata, dt=%f", this, dt.ToSeconds())); } And the logs: 04-02 22:33:07.558 689 689 I PRLog : 2014-04-02 22:33:07.560959 UTC - 1074377864[40222080]: 440ea2a0 Ready state changed to HAVE_CURRENT_DATA 04-02 22:33:30.128 689 689 I PRLog : 2014-04-02 22:33:30.133957 UTC - 1074377864[40222080]: 440ea2a0 Queuing event loadeddata 04-02 22:33:30.128 689 689 I PRLog : 2014-04-02 22:33:30.134644 UTC - 1074377864[40222080]: 440ea2a0 dispatch loadeddata, dt=22.572634 This is insane for it takes over 20s to run a few lines of the code. I suspect there are some IPC calls in UpdateAudioChannelPlayingState() which should attribute to this long latency.
Is this a debug build? I've noticed that it can take about 40 seconds to download gizmo.mp4 in test_seek.html mochitest. I suspected we're tickling httpd.js (the webserver mochitests uses) or necko in some way that's causing us to get bad performance. Maybe we're hitting the server connection limit? Or maybe httpd.js just sucks for some other reason?
1. Yes, this test failure seems to only happen in debug build. 2. I don't think the problem in comment 102 is related to http for those few lines of code do not involve http download.
https://tbpl.mozilla.org/?tree=Try&rev=bca6b16c98fb is with the mochitest canplaythrough timeout raised to 1000s. About 35 green runs, and over the last week the rate for this one bug has been at least 20% failure. If these run on VMs, it may be due to simply not getting enough cycles for long enough to cause operations to take a LOT longer than normal. nils was thinking of a) starting the timer after ICE completes, and b) greatly lengthening it but not to the point of full-test-timeout. Maybe 1/3 or 1/2 the full timeout of 300? seconds.
More logs: 04-03 06:28:14.202 697 697 I PRLog : 2014-04-03 06:28:14.205011 UTC - 1074377864[40222080]: 440eaae0 AudioChannelAgent::SetVisibilityState, dt=0.000402 04-03 06:28:32.102 641 641 I Gecko : --DOMWINDOW == 4 (0x46f658c0) [pid = 641] [serial = 4] [outer = 0x46f64d80] [url = about:blank] 04-03 06:28:34.052 641 641 I Gecko : [Parent 641] WARNING: A control runnable was posted to a worker that is already shutting down!: file ../../../gecko/dom/workers/WorkerPrivate.cpp, line 2232 04-03 06:28:34.062 641 641 I Gecko : [Parent 641] WARNING: A control runnable was posted to a worker that is already shutting down!: file ../../../gecko/dom/workers/WorkerPrivate.cpp, line 2232 04-03 06:28:34.513 697 697 I PRLog : 2014-04-03 06:28:34.514390 UTC - 1074377864[40222080]: 440eaae0 AudioChannelAgent::StartPlaying, dt=20.308723 mAudioChannelAgent->SetVisibilityState takes only 0.000402 seconds (https://hg.mozilla.org/try/file/e603d56ab5da/content/html/content/src/HTMLMediaElement.cpp#l3950). However mAudioChannelAgent->StartPlaying takes up to 20.308723 seconds (https://hg.mozilla.org/try/file/e603d56ab5da/content/html/content/src/HTMLMediaElement.cpp#l3958). Those warning messages might have something to do with the long latency of mAudioChannelAgent->StartPlaying. Should we call for someone who knows about AudioChannelService to take a look?
(In reply to JW Wang (PTO ~4/9) [:jwwang] from comment #107) > More logs: > > 04-03 06:28:14.202 697 697 I PRLog : 2014-04-03 06:28:14.205011 UTC - > 1074377864[40222080]: 440eaae0 AudioChannelAgent::SetVisibilityState, > dt=0.000402 > 04-03 06:28:32.102 641 641 I Gecko : --DOMWINDOW == 4 (0x46f658c0) > [pid = 641] [serial = 4] [outer = 0x46f64d80] [url = about:blank] > 04-03 06:28:34.052 641 641 I Gecko : [Parent 641] WARNING: A control > runnable was posted to a worker that is already shutting down!: file > ../../../gecko/dom/workers/WorkerPrivate.cpp, line 2232 > 04-03 06:28:34.062 641 641 I Gecko : [Parent 641] WARNING: A control > runnable was posted to a worker that is already shutting down!: file > ../../../gecko/dom/workers/WorkerPrivate.cpp, line 2232 > 04-03 06:28:34.513 697 697 I PRLog : 2014-04-03 06:28:34.514390 UTC - > 1074377864[40222080]: 440eaae0 AudioChannelAgent::StartPlaying, dt=20.308723 > > mAudioChannelAgent->SetVisibilityState takes only 0.000402 seconds > (https://hg.mozilla.org/try/file/e603d56ab5da/content/html/content/src/ > HTMLMediaElement.cpp#l3950). > However mAudioChannelAgent->StartPlaying takes up to 20.308723 seconds > (https://hg.mozilla.org/try/file/e603d56ab5da/content/html/content/src/ > HTMLMediaElement.cpp#l3958). > > Those warning messages might have something to do with the long latency of > mAudioChannelAgent->StartPlaying. > > Should we call for someone who knows about AudioChannelService to take a > look? Yes! I do know that the emulator audio and video devices have ... issues, and they might well be slow to start
As we see these timeouts only on gUM tests no ICE connections are involved. Therefore I think increasing the timeout values is the right thing to do.
Attachment #8401655 - Flags: review?(rjesup)
Attachment #8401655 - Flags: review?(rjesup) → review+
JW sorry for taking this over. I request to leave this open in case you want to keep investigating why things are so slow. But I think for now it is the right thing to increase the timeout to get these tests out of the orange list.
Keywords: checkin-needed, leave-open
Flags: needinfo?(roc)
Status: ASSIGNED → RESOLVED
Closed: 11 years ago
Keywords: leave-open
Resolution: --- → FIXED
status-b2g-v1.3: --- → affected
status-b2g-v1.4: --- → affected
status-b2g-v2.0: --- → fixed
status-firefox29: --- → unaffected
status-firefox30: --- → affected
status-firefox31: --- → fixed
status-firefox-esr24: --- → unaffected
Target Milestone: --- → mozilla31
status-b2g-v1.3T: --- → fixed
(In reply to Randell Jesup [:jesup] from comment #109) > Yes! I do know that the emulator audio and video devices have ... issues, > and they might well be slow to start Do you mean the warning messages are caused by the problem of emulator audio/video?
(In reply to Nils Ohlmeier [:drno] from comment #124) > JW sorry for taking this over. I request to leave this open in case you want > to keep investigating why things are so slow. But I think for now it is the > right thing to increase the timeout to get these tests out of the orange > list. I was on a PTO. Thanks for the patch. :) I am still concerned about the warning messages in comment 107. I will try to find the AudioChannelService or IPC guys to look at it.
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: