Closed
Bug 1429764
Opened 6 years ago
Closed 6 years ago
Intermittent dom/tests/mochitest/general/test_resource_timing.html | Expected fetchStart to happen before domainLookupStart, got fetchStart = 1076.06, domainLookupStart = 1076.04
Categories
(Core :: DOM: Core & HTML, defect, P1)
Core
DOM: Core & HTML
Tracking
()
RESOLVED
FIXED
mozilla59
Tracking | Status | |
---|---|---|
firefox-esr52 | --- | unaffected |
firefox57 | --- | unaffected |
firefox58 | + | fixed |
firefox59 | + | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: tjr)
References
Details
(Keywords: intermittent-failure, regression, Whiteboard: [stockwell fixed:product])
Attachments
(1 file)
59 bytes,
text/x-review-board-request
|
bkelly
:
review+
timhuang
:
review+
jcristau
:
approval-mozilla-release+
|
Details |
Filed by: apavel [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=155591585&repo=mozilla-inbound https://queue.taskcluster.net/v1/task/PyLaSSaSTe2W8Bj7RKlMeQ/runs/0/artifacts/public/logs/live_backing.log [task 2018-01-11T11:21:52.034Z] 11:21:52 INFO - TEST-START | dom/tests/mochitest/general/test_resource_timing.html [task 2018-01-11T11:21:52.237Z] 11:21:52 INFO - GECKO(2041) | ++DOMWINDOW == 43 (0x7fc820108c00) [pid = 2102] [serial = 177] [outer = 0x7fc82c17ba40] [task 2018-01-11T11:21:52.345Z] 11:21:52 INFO - GECKO(2041) | ++DOCSHELL 0x7fc8209b0800 == 5 [pid = 2102] [id = {0f71f68a-fbe3-4f59-9011-34c20b23d6b2}] [task 2018-01-11T11:21:52.345Z] 11:21:52 INFO - GECKO(2041) | ++DOMWINDOW == 44 (0x7fc82c17c7d0) [pid = 2102] [serial = 178] [outer = (nil)] [task 2018-01-11T11:21:52.426Z] 11:21:52 INFO - GECKO(2041) | ++DOMWINDOW == 45 (0x7fc820108000) [pid = 2102] [serial = 179] [outer = 0x7fc82c17c7d0] [task 2018-01-11T11:21:52.605Z] 11:21:52 INFO - GECKO(2041) | WARN:webrender::prim_store: invalid primitive rect TypedRect(0Ă—0 at (0,0)) [task 2018-01-11T11:21:52.621Z] 11:21:52 INFO - GECKO(2041) | WARN:webrender::prim_store: invalid primitive rect TypedRect(0Ă—0 at (0,0)) [task 2018-01-11T11:21:52.682Z] 11:21:52 INFO - GECKO(2041) | WARN:webrender::prim_store: invalid primitive rect TypedRect(0Ă—0 at (0,0)) [task 2018-01-11T11:21:52.747Z] 11:21:52 INFO - GECKO(2041) | WARN:webrender::prim_store: invalid primitive rect TypedRect(0Ă—0 at (0,0)) [task 2018-01-11T11:21:52.812Z] 11:21:52 INFO - GECKO(2041) | WARN:webrender::prim_store: invalid primitive rect TypedRect(0Ă—0 at (0,0)) [task 2018-01-11T11:21:52.848Z] 11:21:52 INFO - GECKO(2041) | ++DOMWINDOW == 46 (0x7fc82093b800) [pid = 2102] [serial = 180] [outer = 0x7fc82c17c7d0] [task 2018-01-11T11:21:52.913Z] 11:21:52 INFO - GECKO(2041) | WARN:webrender::prim_store: invalid primitive rect TypedRect(0Ă—0 at (0,0)) [task 2018-01-11T11:21:53.749Z] 11:21:53 INFO - GECKO(2041) | WARN:webrender::scene: Property binding PropertyBindingKey { id: PropertyBindingId { namespace: IdNamespace(2041), uid: 31 }, _phantom: PhantomData } has an invalid value. [task 2018-01-11T11:21:53.749Z] 11:21:53 INFO - GECKO(2041) | WARN:webrender::prim_store: invalid primitive rect TypedRect(0Ă—0 at (0,0)) [task 2018-01-11T11:21:54.299Z] 11:21:54 INFO - GECKO(2041) | ++DOCSHELL 0x7fc8209a5000 == 6 [pid = 2102] [id = {03f802d0-3de1-439d-9328-e840a137a286}] [task 2018-01-11T11:21:54.300Z] 11:21:54 INFO - GECKO(2041) | ++DOMWINDOW == 47 (0x7fc82c17d370) [pid = 2102] [serial = 181] [outer = (nil)] [task 2018-01-11T11:21:55.177Z] 11:21:55 INFO - GECKO(2041) | --DOMWINDOW == 46 (0x7fc82c17c010) [pid = 2102] [serial = 148] [outer = (nil)] [url = about:blank] [task 2018-01-11T11:21:55.179Z] 11:21:55 INFO - GECKO(2041) | --DOMWINDOW == 45 (0x7fc82c17c200) [pid = 2102] [serial = 158] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/tests/mochitest/general/performance_timeline_main_test.html] [task 2018-01-11T11:21:55.180Z] 11:21:55 INFO - GECKO(2041) | --DOMWINDOW == 44 (0x7fc82c17be20) [pid = 2102] [serial = 144] [outer = (nil)] [url = about:blank] [task 2018-01-11T11:21:55.479Z] 11:21:55 INFO - GECKO(2041) | [Child 2102, Main Thread] WARNING: Listener is not retargetable: file /builds/worker/workspace/build/src/netwerk/protocol/http/HttpChannelChild.cpp, line 3506 [task 2018-01-11T11:21:55.544Z] 11:21:55 INFO - GECKO(2041) | [Child 2102, Main Thread] WARNING: Listener is not retargetable: file /builds/worker/workspace/build/src/netwerk/protocol/http/HttpChannelChild.cpp, line 3506 [task 2018-01-11T11:21:55.593Z] 11:21:55 INFO - GECKO(2041) | ++DOMWINDOW == 45 (0x7fc820934c00) [pid = 2102] [serial = 182] [outer = 0x7fc82c17d370] [task 2018-01-11T11:21:56.881Z] 11:21:56 INFO - TEST-INFO | started process screentopng [task 2018-01-11T11:21:57.866Z] 11:21:57 INFO - TEST-INFO | screentopng: exit 0 [task 2018-01-11T11:21:57.867Z] 11:21:57 INFO - Buffered messages logged at 11:21:56 [task 2018-01-11T11:21:57.868Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | http://mochi.test:8888/tests/image/test/mochitest/damon.jpg should be a valid entry name [task 2018-01-11T11:21:57.870Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | This iframe should NOT contain itself as an entry [task 2018-01-11T11:21:57.871Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | Performance object should exist [task 2018-01-11T11:21:57.872Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | Performance.getEntries() should exist [task 2018-01-11T11:21:57.873Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | Performance.getEntriesByName() should exist [task 2018-01-11T11:21:57.874Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | Performance.getEntriesByType() should exist [task 2018-01-11T11:21:57.875Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | Performance.getEntriesByType() returned wrong number of entries. [task 2018-01-11T11:21:57.876Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The serialization should contain key: initiatorType [task 2018-01-11T11:21:57.877Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The serialization should contain key: redirectStart [task 2018-01-11T11:21:57.878Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The serialization should contain key: redirectEnd [task 2018-01-11T11:21:57.892Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The serialization should contain key: fetchStart [task 2018-01-11T11:21:57.899Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The serialization should contain key: domainLookupStart [task 2018-01-11T11:21:57.903Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The serialization should contain key: domainLookupEnd [task 2018-01-11T11:21:57.905Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The serialization should contain key: connectStart [task 2018-01-11T11:21:57.912Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The serialization should contain key: connectEnd [task 2018-01-11T11:21:57.914Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The serialization should contain key: secureConnectionStart [task 2018-01-11T11:21:57.918Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The serialization should contain key: requestStart [task 2018-01-11T11:21:57.921Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The serialization should contain key: responseStart [task 2018-01-11T11:21:57.922Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The serialization should contain key: responseEnd [task 2018-01-11T11:21:57.925Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The serialization should contain key: name [task 2018-01-11T11:21:57.926Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The serialization should contain key: entryType [task 2018-01-11T11:21:57.930Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The serialization should contain key: startTime [task 2018-01-11T11:21:57.932Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The serialization should contain key: duration [task 2018-01-11T11:21:57.941Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | Performance.getEntriesByType() should return some results [task 2018-01-11T11:21:57.942Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | Performance.getEntriesByName() should return some results [task 2018-01-11T11:21:57.942Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | getEntriesByType() should return a different array object every time. [task 2018-01-11T11:21:57.948Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The arrays should have the same entries. [task 2018-01-11T11:21:57.950Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry should not be null [task 2018-01-11T11:21:57.952Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.name should be valid. [task 2018-01-11T11:21:57.955Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.startTime should be grater than 0 [task 2018-01-11T11:21:57.962Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.redirectStart should be part of PerformanceEntry [task 2018-01-11T11:21:57.964Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.redirectEnd should be part of PerformanceEntry [task 2018-01-11T11:21:57.970Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.fetchStart should be part of PerformanceEntry [task 2018-01-11T11:21:57.973Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.domainLookupStart should be part of PerformanceEntry [task 2018-01-11T11:21:57.977Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.domainLookupEnd should be part of PerformanceEntry [task 2018-01-11T11:21:57.985Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.connectStart should be part of PerformanceEntry [task 2018-01-11T11:21:57.988Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.connectEnd should be part of PerformanceEntry [task 2018-01-11T11:21:57.994Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.secureConnectionStart should be part of PerformanceEntry [task 2018-01-11T11:21:57.997Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.requestStart should be part of PerformanceEntry [task 2018-01-11T11:21:57.998Z] 11:21:57 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.responseStart should be part of PerformanceEntry [task 2018-01-11T11:21:58.002Z] 11:21:58 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.responseEnd should be part of PerformanceEntry [task 2018-01-11T11:21:58.003Z] 11:21:58 INFO - TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | Expected redirectEnd to happen before fetchStart, got redirectEnd = 0, fetchStart = 1076.06 [task 2018-01-11T11:21:58.003Z] 11:21:58 INFO - Buffered messages finished [task 2018-01-11T11:21:58.012Z] 11:21:58 INFO - TEST-UNEXPECTED-FAIL | dom/tests/mochitest/general/test_resource_timing.html | Expected fetchStart to happen before domainLookupStart, got fetchStart = 1076.06, domainLookupStart = 1076.04 [task 2018-01-11T11:21:58.013Z] 11:21:58 INFO - ok@dom/tests/mochitest/general/resource_timing_main_test.html:55:3 [task 2018-01-11T11:21:58.014Z] 11:21:58 INFO - checkEntries@dom/tests/mochitest/general/resource_timing_main_test.html:182:9 [task 2018-01-11T11:21:58.015Z] 11:21:58 INFO - window.onload@dom/tests/mochitest/general/resource_timing_main_test.html:112:3 [task 2018-01-11T11:21:58.018Z] 11:21:58 INFO - EventHandlerNonNull*@dom/tests/mochitest/general/resource_timing_main_test.html:76:1
Comment hidden (Intermittent Failures Robot) |
Comment 2•6 years ago
|
||
There are 38 failures in the past 7 days. Platforms: android-api-16-gradle opt, android-4-3-armv7-api16 opt, Linux x64 debug, linux64-qr debug and linux32-stylo-disabled debug. Recent log event: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=155783761 Relevant part of the log: [task 2018-01-12T00:15:44.215Z] 00:15:44 INFO - Buffered messages finished 2176 [task 2018-01-12T00:15:44.216Z] 00:15:44 INFO - 288 INFO TEST-UNEXPECTED-FAIL | dom/tests/mochitest/general/test_resource_timing.html | Expected fetchStart to happen before domainLookupStart, got fetchStart = 2346.62, domainLookupStart = 2346.6 2177 [task 2018-01-12T00:15:44.216Z] 00:15:44 INFO - ok@dom/tests/mochitest/general/resource_timing_main_test.html:55:3 2178 [task 2018-01-12T00:15:44.217Z] 00:15:44 INFO - checkEntries@dom/tests/mochitest/general/resource_timing_main_test.html:182:9 2179 [task 2018-01-12T00:15:44.217Z] 00:15:44 INFO - window.onload@dom/tests/mochitest/general/resource_timing_main_test.html:112:3 2180 [task 2018-01-12T00:15:44.218Z] 00:15:44 INFO - 289 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | Expected domainLookupStart to happen before domainLookupEnd, got domainLookupStart = 2346.6, domainLookupEnd = 2346.6 2181 [task 2018-01-12T00:15:44.219Z] 00:15:44 INFO - 290 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | Expected domainLookupEnd to happen before connectStart, got domainLookupEnd = 2346.6, connectStart = 2346.6 2182 [task 2018-01-12T00:15:44.219Z] 00:15:44 INFO - 291 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | Expected connectStart to happen before connectEnd, got connectStart = 2346.6, connectEnd = 2346.6 2183 [task 2018-01-12T00:15:44.220Z] 00:15:44 INFO - 292 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | Expected connectEnd to happen before requestStart, got connectEnd = 2346.6, requestStart = 2691.48 2184 [task 2018-01-12T00:15:44.220Z] 00:15:44 INFO - 293 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | Expected requestStart to happen before responseStart, got requestStart = 2691.48, responseStart = 2741.04 2185 [task 2018-01-12T00:15:44.221Z] 00:15:44 INFO - 294 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | Expected responseStart to happen before responseEnd, got responseStart = 2741.04, responseEnd = 2778.68 2186 [task 2018-01-12T00:15:44.221Z] 00:15:44 INFO - 295 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry should not be null 2187 [task 2018-01-12T00:15:44.222Z] 00:15:44 INFO - 296 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.name should be valid. 2188 [task 2018-01-12T00:15:44.223Z] 00:15:44 INFO - 297 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.startTime should be grater than 0 2189 [task 2018-01-12T00:15:44.223Z] 00:15:44 INFO - 298 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | Entries list should be in chronological order with respect to startTime. 2190 [task 2018-01-12T00:15:44.224Z] 00:15:44 INFO - 299 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.redirectStart should be part of PerformanceEntry 2191 [task 2018-01-12T00:15:44.224Z] 00:15:44 INFO - 300 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.redirectEnd should be part of PerformanceEntry 2192 [task 2018-01-12T00:15:44.225Z] 00:15:44 INFO - 301 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.fetchStart should be part of PerformanceEntry 2193 [task 2018-01-12T00:15:44.226Z] 00:15:44 INFO - 302 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.domainLookupStart should be part of PerformanceEntry 2194 [task 2018-01-12T00:15:44.226Z] 00:15:44 INFO - 303 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.domainLookupEnd should be part of PerformanceEntry 2195 [task 2018-01-12T00:15:44.227Z] 00:15:44 INFO - 304 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.connectStart should be part of PerformanceEntry 2196 [task 2018-01-12T00:15:44.227Z] 00:15:44 INFO - 305 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.connectEnd should be part of PerformanceEntry 2197 [task 2018-01-12T00:15:44.228Z] 00:15:44 INFO - 306 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.secureConnectionStart should be part of PerformanceEntry 2198 [task 2018-01-12T00:15:44.228Z] 00:15:44 INFO - 307 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.requestStart should be part of PerformanceEntry 2199 [task 2018-01-12T00:15:44.229Z] 00:15:44 INFO - 308 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.responseStart should be part of PerformanceEntry 2200 [task 2018-01-12T00:15:44.229Z] 00:15:44 INFO - 309 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | PerformanceEntry.responseEnd should be part of PerformanceEntry 2201 [task 2018-01-12T00:15:44.230Z] 00:15:44 INFO - 310 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | Expected redirectEnd to happen before fetchStart, got redirectEnd = 0, fetchStart = 2381.54 2202 [task 2018-01-12T00:15:44.230Z] 00:15:44 INFO - 311 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | Expected fetchStart to happen before domainLookupStart, got fetchStart = 2381.54, domainLookupStart = 2381.54 2203 [task 2018-01-12T00:15:44.231Z] 00:15:44 INFO - 312 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | Expected domainLookupStart to happen before domainLookupEnd, got domainLookupStart = 2381.54, domainLookupEnd = 2381.54 2204 [task 2018-01-12T00:15:44.232Z] 00:15:44 INFO - 313 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | Expected domainLookupEnd to happen before connectStart, got domainLookupEnd = 2381.54, connectStart = 2381.54 2205 [task 2018-01-12T00:15:44.232Z] 00:15:44 INFO - 314 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | Expected connectStart to happen before connectEnd, got connectStart = 2381.54, connectEnd = 2381.54 2206 [task 2018-01-12T00:15:44.233Z] 00:15:44 INFO - 315 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | Expected connectEnd to happen before requestStart, got connectEnd = 2381.54, requestStart = 2876.5 2207 [task 2018-01-12T00:15:44.233Z] 00:15:44 INFO - 316 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | Expected requestStart to happen before responseStart, got requestStart = 2876.5, responseStart = 2895.5 2208 [task 2018-01-12T00:15:44.234Z] 00:15:44 INFO - 317 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | Expected responseStart to happen before responseEnd, got responseStart = 2895.5, responseEnd = 2896.16 2209 [task 2018-01-12T00:15:44.234Z] 00:15:44 INFO - 318 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | An entry with the name 'http://mochi.test:8888/tests/SimpleTest/test.css' should be available 2210 [task 2018-01-12T00:15:44.235Z] 00:15:44 INFO - 319 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The resource name is invalid 2211 [task 2018-01-12T00:15:44.235Z] 00:15:44 INFO - 320 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The initiator type for http://mochi.test:8888/tests/SimpleTest/test.css is invalid 2212 [task 2018-01-12T00:15:44.236Z] 00:15:44 INFO - 321 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | An entry with the name 'http://mochi.test:8888/tests/image/test/mochitest/blue.png' should be available 2213 [task 2018-01-12T00:15:44.237Z] 00:15:44 INFO - 322 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The resource name is invalid 2214 [task 2018-01-12T00:15:44.237Z] 00:15:44 INFO - 323 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The initiator type for http://mochi.test:8888/tests/image/test/mochitest/blue.png is invalid 2215 [task 2018-01-12T00:15:44.238Z] 00:15:44 INFO - 324 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | An entry with the name 'http://mochi.test:8888/tests/image/test/mochitest/red.png' should be available 2216 [task 2018-01-12T00:15:44.238Z] 00:15:44 INFO - 325 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The resource name is invalid 2217 [task 2018-01-12T00:15:44.239Z] 00:15:44 INFO - 326 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The initiator type for http://mochi.test:8888/tests/image/test/mochitest/red.png is invalid 2218 [task 2018-01-12T00:15:44.240Z] 00:15:44 INFO - 327 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | An entry with the name 'http://mochi.test:8888/tests/image/test/mochitest/big.png' should be available 2219 [task 2018-01-12T00:15:44.240Z] 00:15:44 INFO - 328 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The resource name is invalid 2220 [task 2018-01-12T00:15:44.241Z] 00:15:44 INFO - 329 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The initiator type for http://mochi.test:8888/tests/image/test/mochitest/big.png is invalid 2221 [task 2018-01-12T00:15:44.241Z] 00:15:44 INFO - 330 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | An entry with the name 'http://mochi.test:8888/tests/dom/tests/mochitest/general/resource_timing_iframe.html' should be available 2222 [task 2018-01-12T00:15:44.242Z] 00:15:44 INFO - 331 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The resource name is invalid 2223 [task 2018-01-12T00:15:44.243Z] 00:15:44 INFO - 332 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The initiator type for http://mochi.test:8888/tests/dom/tests/mochitest/general/resource_timing_iframe.html is invalid 2224 [task 2018-01-12T00:15:44.243Z] 00:15:44 INFO - 333 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | http://mochi.test:8888/tests/image/test/mochitest/damon.jpg should be a valid entry name 2225 [task 2018-01-12T00:15:44.244Z] 00:15:44 INFO - 334 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | No entries should be removed when setResourceTimingBufferSize is called. 2226 [task 2018-01-12T00:15:44.244Z] 00:15:44 INFO - 335 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | No entries should be removed when setResourceTimingBufferSize is called. 2227 [task 2018-01-12T00:15:44.245Z] 00:15:44 INFO - 336 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | All the entries should be removed when when clearResourceTimings is being called. 2228 [task 2018-01-12T00:15:56.817Z] 00:15:56 INFO - 337 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The first xhr entry was not added. 2229 [task 2018-01-12T00:15:56.817Z] 00:15:56 INFO - 338 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The initiatorType is incorrect for this entry 2230 [task 2018-01-12T00:15:56.818Z] 00:15:56 INFO - 339 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | The second xhr entry should not be returned since the buffer size was set to 1. 2231 [task 2018-01-12T00:15:56.818Z] 00:15:56 INFO - 340 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | We returned the second xhr instead of the first one 2232 [task 2018-01-12T00:15:56.818Z] 00:15:56 INFO - 341 INFO TEST-PASS | dom/tests/mochitest/general/test_resource_timing.html | onresourcetimingbufferfull called a wrong number of times 2233 [task 2018-01-12T00:15:56.818Z] 00:15:56 INFO - 342 INFO TEST-OK | dom/tests/mochitest/general/test_resource_timing.html | took 18446ms 2234 [task 2018-01-12T00:15:56.818Z] 00:15:56 INFO - 343 INFO TEST-START | dom/tests/mochitest/general/test_resource_timing_cross_origin.html 2235 [task 2018-01-12T00:16:03.234Z] 00:16:03 INFO - JavaScript error: resource://gre/modules/FileUtils.jsm, line 64: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIProperties.get] :overholt Could you please take a look?
Flags: needinfo?(overholt)
Comment 3•6 years ago
|
||
This should be a regression from bug 1424341.
Assignee | ||
Comment 4•6 years ago
|
||
Oh this is a serious one. I'll dig into it today.
Assignee | ||
Updated•6 years ago
|
Assignee: nobody → tom
Flags: needinfo?(tom)
Updated•6 years ago
|
Priority: -- → P1
Updated•6 years ago
|
status-firefox58:
--- → ?
status-firefox59:
--- → affected
tracking-firefox58:
--- → ?
tracking-firefox59:
--- → +
Assignee | ||
Updated•6 years ago
|
Comment hidden (mozreview-request) |
Assignee | ||
Comment 6•6 years ago
|
||
After thinking about this a bit, I think it's caused by floating point fuzziness. I couldn't reproduce this locally, so I added logging and sent a try run: https://treeherder.mozilla.org/#/jobs?repo=try&revision=b40337e946899429d1c9e1110e3ac49d4a722594
Assignee | ||
Comment 7•6 years ago
|
||
I reproed it with that try run, but my logging didn't include enough decimal places to be sure of what was going on. New try run: https://treeherder.mozilla.org/#/jobs?repo=try&revision=372da7a78ecf0a87bf5326456e02884d3bd3e53e
Comment hidden (mozreview-request) |
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 10•6 years ago
|
||
Okay, I think what's happening is that we're calling ReduceTimePrecision multiple times. How many depends on the call chain. FetchStart is supposed to be before DomainLookupStart; but if DomainLookupStart isn't set, FetchStart is returned. But when we fall back to FetchStart, we call ReduceTimePrecision an additional time. This shouldn't be a problem. But it is because a) floats are fuzzy and b) ReduceTimePrecision clamps time _downwards_. So that additional extra call winds up reducing the value an additional epislon (in this case 20us). So there's a few possible fixes here. We can try to avoid calling ReduceTimePrecision multiple times. (I identified one case we can definetly and easily remove, so that will happen.) But this is tough, because we would have to overload methods like PerformanceTiming::FetchStartHighRes() to take a bool clamp = true argument, and then provide 'false' whenever we're returning this value though a callstack that will round it itself. Ew. We can change the clamping algorithm to say "If you're within .00001 of a value, just use the value instead of clamping it downward." That's kind of ugly code, and it's a nightmare to test. It's also confusing when you're trying to account for fuzzy numbers using numbers that are themselves fuzzy... We can change ReducetimePrecision to *round* time, instead of *clamping* it. This means that a value like 63.5999999997 will be rounded to 63.6 instead of clamped to 63.4. Is this okay? Not sure. It makes me a little nervous because we're moving time into the future. But perhaps the argument is that is if at time T, we've started rounding towards B - and there does not exist a current timestamp that would ever be rounded to A. But how does this interact with the addition of different timestamps.
Assignee | ||
Comment 11•6 years ago
|
||
Actually, I refactored the calls to avoid calling ReducetimePrecision multiple times without making it more complicated. I think that works: https://treeherder.mozilla.org/#/jobs?repo=try&revision=99a556245fc480e5dd1a5d61e2e2d6162b014fc1 But the problem of RTP rounding down when it ideally shouldn't because of float fuzziness is still present. It might not break anything, but it's probably something we should fix.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (mozreview-request) |
Comment hidden (Intermittent Failures Robot) |
Comment 15•6 years ago
|
||
mozreview-review |
Comment on attachment 8942285 [details] Bug 1429764 Do not call ReduceTimerPrecision twice for DOM Navigation timers https://reviewboard.mozilla.org/r/212570/#review218446 ::: dom/performance/PerformanceTiming.h:72 (Diff revision 3) > * @return the duration of an event with a given TimeStamp, relative to the > * navigationStart TimeStamp (the moment the user landed on the > * page), if the given TimeStamp is valid. Otherwise, it will return > * the FetchStart timing value. > */ > - inline DOMHighResTimeStamp TimeStampToDOMHighResOrFetchStart(TimeStamp aStamp) > + inline DOMHighResTimeStamp ReducedTimeStampToDOMHighResOrFetchStart(TimeStamp aStamp) I am wondering that if the name 'ReducedTimeStampToDOMHighResOrFetchStart' fits the meaning of this function. This function accepts timestamp and returns a reduced DOMHighResTimeStamp, so, maybe, 'TimeStampToReducedDOMHighResOrFetchStart' would serve a better meaning of this.
Attachment #8942285 -
Flags: review?(tihuang) → review+
Comment hidden (Intermittent Failures Robot) |
Comment hidden (mozreview-request) |
Comment 18•6 years ago
|
||
mozreview-review |
Comment on attachment 8942285 [details] Bug 1429764 Do not call ReduceTimerPrecision twice for DOM Navigation timers https://reviewboard.mozilla.org/r/212570/#review218892
Attachment #8942285 -
Flags: review?(bkelly) → review+
Assignee | ||
Updated•6 years ago
|
Keywords: checkin-needed
Comment hidden (Intermittent Failures Robot) |
Comment 20•6 years ago
|
||
Pushed by ryanvm@gmail.com: https://hg.mozilla.org/integration/autoland/rev/17bf5819b42f Do not call ReduceTimerPrecision twice for DOM Navigation timers r=bkelly,timhuang
Keywords: checkin-needed
Comment 21•6 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/17bf5819b42f
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla59
Assignee | ||
Comment 22•6 years ago
|
||
Comment on attachment 8942285 [details] Bug 1429764 Do not call ReduceTimerPrecision twice for DOM Navigation timers Approval Request Comment [Feature/Bug causing the regression]: Bug 1424341 (which is not enabled in beta by default, but we will probably turn it on post-release) [User impact if declined]: Time will go backwards in a small percentage of cases. [Is this code covered by automated tests?]: Yes, the tests are what caused the bug. [Has the fix been verified in Nightly?]: No, it landed there last night. [Needs manual test from QE? If yes, steps to reproduce]: No. [List of other uplifts needed for the feature/fix]: None. [Is the change risky? Why?]: It's subtle. And subtle is complex and complex is risky. But I double checked it with fresh eyes and it makes sense to me, and the tests pass. We can let it bake on Nightly a little bit, but we should try to get this into beta before the window closes because I still believe we are going to turn on the pref post-release. [String changes made/needed]: None
Attachment #8942285 -
Flags: approval-mozilla-beta?
Comment 23•6 years ago
|
||
I think we need to get this into RC2.
status-firefox57:
--- → unaffected
status-firefox-esr52:
--- → unaffected
Flags: needinfo?(gchang)
Whiteboard: [stockwell disable-recommended] → [stockwell fixed:product]
Comment 24•6 years ago
|
||
Comment on attachment 8942285 [details] Bug 1429764 Do not call ReduceTimerPrecision twice for DOM Navigation timers followup for the spectre mitigation timer changes, release58+, for rc2.
Flags: needinfo?(gchang)
Attachment #8942285 -
Flags: approval-mozilla-beta? → approval-mozilla-release+
Updated•6 years ago
|
Comment 25•6 years ago
|
||
bugherder uplift |
https://hg.mozilla.org/releases/mozilla-release/rev/ff6f39465890
Flags: in-testsuite+
Comment 26•6 years ago
|
||
bugherder uplift |
https://hg.mozilla.org/releases/mozilla-beta/rev/8c87bd688e54 (FIREFOX_58b_RELBRANCH)
Comment hidden (Intermittent Failures Robot) |
Updated•5 years ago
|
Component: DOM → DOM: Core & HTML
You need to log in
before you can comment on or make changes to this bug.
Description
•