Closed Bug 1013822 Opened 6 years ago Closed 6 years ago

Investigate long pauses in test execution

Categories

(Core :: WebRTC, defect)

defect
Not set

Tracking

()

RESOLVED FIXED
mozilla32

People

(Reporter: drno, Assigned: drno)

References

Details

Attachments

(1 file)

This try build log show a 5 second delay between setRemoteDescription (at 10:17:41) and setLocalDescription (at 10:17:45) in which according to the logs nothing is happening:
http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/bcampen@mozilla.com-61b6f0bbc337/try-macosx64-debug/try_mountainlion-debug_test-mochitest-3-bm106-tests1-macosx-build1363.txt.gz

This easily would explain all kind of ICE/connection errors. We need to find out what is causing these delays.
Assignee: nobody → drno
With some scripting I found a bunch of delays in between set*Description calls in the log for Bug 977944 below.
Interestingly Bug 963524 which also has ICE failures, does not show any noticeable delays in the logs. So presumably we identified here only one of several potential ICE connection problems.

    === File Name: 977944-101
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:04 ========
    ====== Log lines in between: 101 ======
    === File Name: 977944-102
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:02 ========
    ====== Log lines in between: 70 ======
    === File Name: 977944-104
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:02 ========
    ====== Log lines in between: 74 ======
    === File Name: 977944-105
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:03 ========
    ====== Log lines in between: 120 ======
    === File Name: 977944-106
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:03 ========
    ====== Log lines in between: 92 ======
    === File Name: 977944-107
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:02 ========
    ====== Log lines in between: 94 ======
    === File Name: 977944-108
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:03 ========
    ====== Log lines in between: 116 ======
    === File Name: 977944-114
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:02 ========
    ====== Log lines in between: 90 ======
    === File Name: 977944-116
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:04 ========
    ====== Log lines in between: 129 ======
    === File Name: 977944-117
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:02 ========
    ====== Log lines in between: 254 ======
    === File Name: 977944-122
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:03 ========
    ====== Log lines in between: 102 ======
    === File Name: 977944-123
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:02 ========
    ====== Log lines in between: 67 ======
    === File Name: 977944-124
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:02 ========
    ====== Log lines in between: 76 ======
    === File Name: 977944-128
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:03 ========
    ====== Log lines in between: 102 ======
    === File Name: 977944-85
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:03 ========
    ====== Log lines in between: 96 ======
    === File Name: 977944-89
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:03 ========
    ====== Log lines in between: 75 ======
    === File Name: 977944-90
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:03 ========
    ====== Log lines in between: 75 ======
    === File Name: 977944-91
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:02 ========
    ====== Log lines in between: 75 ======
    === File Name: 977944-92
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:03 ========
    ====== Log lines in between: 126 ======
    === File Name: 977944-94
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:02 ========
    ====== Log lines in between: 78 ======
    === File Name: 977944-95
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:03 ========
    ====== Log lines in between: 72 ======
    === File Name: 977944-96
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:03 ========
    ====== Log lines in between: 72 ======
    === File Name: 977944-97
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:02 ========
    ====== Log lines in between: 73 ======
    === File Name: 977944-98
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:04 ========
    ====== Log lines in between: 97 ======
    === File Name: 977944-99
    **** Test Name: ipc/test_ipc.html
    ****** Real Test Name: mochitest/test_peerConnection_basicAudioVideo.html
    ====== set*Description Time Diff: 0:00:02 ========
    ====== Log lines in between: 88 ======
Blocks: 977944
Calculates and dumps time delays between setLocalDescription and setRemoteDescription and delays for switching signaling state to stable into the logs in case ICE failed to connect.
Attachment #8427315 - Flags: review?(docfaraday)
Comment on attachment 8427315 [details] [diff] [review]
bug_1013822_warn_about_setDescription_delay.patch

Review of attachment 8427315 [details] [diff] [review]:
-----------------------------------------------------------------

I guess some of the logging here is a little ambiguous; we aren't measuring when we called setLocal/setRemote, but rather when we got a success callback for these calls, right? Might not matter though. But, this looks sane to me, just a minor formatting concern otherwise.

::: dom/media/tests/mochitest/templates.js
@@ +20,5 @@
>    }
> +
> +  if ((typeof test.pcLocal.setRemoteDescDate !== 'undefined') &&
> +    (typeof test.pcRemote.setLocalDescDate !== 'undefined')) {
> +    var delta = deltaSeconds(test.pcLocal.setRemoteDescDate, test.pcRemote.setLocalDescDate);

What's the convention for line wrapping in these files?
Attachment #8427315 - Flags: review?(docfaraday) → review+
(In reply to Byron Campen [:bwc] from comment #3)
> I guess some of the logging here is a little ambiguous; we aren't measuring
> when we called setLocal/setRemote, but rather when we got a success callback
> for these calls, right? Might not matter though. But, this looks sane to me,
> just a minor formatting concern otherwise.

Good point. We could also record the time from before calling the setLocal/setRemote functions. Maybe we spend actually that much time in the functions them self.
 
> ::: dom/media/tests/mochitest/templates.js
> @@ +20,5 @@
> >    }
> > +
> > +  if ((typeof test.pcLocal.setRemoteDescDate !== 'undefined') &&
> > +    (typeof test.pcRemote.setLocalDescDate !== 'undefined')) {
> > +    var delta = deltaSeconds(test.pcLocal.setRemoteDescDate, test.pcRemote.setLocalDescDate);
> 
> What's the convention for line wrapping in these files?

The file has already tons of lines without any wrapping. But we should probably clean this up at some point in the future.
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/cb3b68267af4
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla32
You need to log in before you can comment on or make changes to this bug.