1013822 - Investigate long pauses in test execution

Status: RESOLVED FIXED

(Core :: WebRTC, defect)

Description

[Nils Ohlmeier [:drno]]

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/[e-mail]-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.

Comment 1

[Nils Ohlmeier [: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 ======

Comment 2

[Nils Ohlmeier [:drno]]

Attachment: bug_1013822_warn_about_setDescription_delay.patch

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.

Comment 3

[Byron Campen [:bwc]]

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?

Comment 4

[Nils Ohlmeier [:drno]]

(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.

Comment 5

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/cb3b68267af4

Comment 6

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/cb3b68267af4