Closed Bug 1260714 Opened 8 years ago Closed 8 years ago

Intermittent browser_computed_search-filter_clear.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -

Categories

(DevTools :: Inspector, defect, P3)

defect

Tracking

(firefox48 fixed)

RESOLVED FIXED
Firefox 48
Tracking Status
firefox48 --- fixed

People

(Reporter: cbook, Assigned: nchevobbe, Mentored)

References

()

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

https://treeherder.mozilla.org/logviewer.html#?job_id=8306037&repo=fx-team

 17:19:27 INFO - 131 INFO TEST-UNEXPECTED-FAIL | devtools/client/inspector/computed/test/browser_computed_search-filter_clear.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -
Triaging (filter on CLIMBING SHOES).
Priority: -- → P3
Assignee: nobody → chevobbe.nicolas
Status: NEW → ASSIGNED
As discussed on IRC, this test is borderline timeout even when successful.
(the current mochitest timeout is set to 45 seconds) 
=> looks like a valid case for splitting up or requesting longer timeout IMO.

Looking at the bug it doesn't seem to be doing a lot though. And the two tested functions are somehow tied together.

Since we can't rely on the timestamps from the logs, currently we have no idea what actually takes time in this test. Before deciding how to split, it could be interesting to try and log the time at different steps of the test. Maybe we can understand what's taking so long.
Mentor: jdescottes
Looking a bit more at the tests, there are two hints worth mentioning:
- the "include browser styles" checkbox is ticked
- we send "background-color" key by key

Each key triggers a filtering + repainting of the whole list. On a debug & non optimized build, this could very well take a lot of time.
So, a rough measuring using performance.now in the test gives me this : 

- addTab from-start: "107", since-last: "107"
- openComputedView from-start: "1551", since-last: "1445"
- selectNode from-start: "1682", since-last: "130"
- testAddTextInFilter from-start: "2526", since-last: "844"
- testClearSearchFilter from-start: "2859", since-last: "333"

The main culprit are the opening of the computedView, on which we can't speed things up ( or at least, not quiclky ), and the testAddTextInFilter. 
In the test, if we don't click the "includes browser style", it goes down to ~300ms ( similar to what we have for testClearSearchFilter ). It's great but then the tests fails.

I guess we could restrict the list of properties to check, ignoring the browser styles' one.
Does it sounds a good things to do ? I think it's kind of harmless, since we test the filtering with the browser style in a sibling test ( browser_compted_search-filter.js) .
Flags: needinfo?(jdescottes)
(In reply to Nicolas Chevobbe from comment #4)
> So, a rough measuring using performance.now in the test gives me this : 
> 
> - addTab from-start: "107", since-last: "107"
> - openComputedView from-start: "1551", since-last: "1445"
> - selectNode from-start: "1682", since-last: "130"
> - testAddTextInFilter from-start: "2526", since-last: "844"
> - testClearSearchFilter from-start: "2859", since-last: "333"
> 

Thanks for measuring! As discussed on IRC please do a try push with these logs to get some more data.

> The main culprit are the opening of the computedView, on which we can't
> speed things up ( or at least, not quiclky ), and the testAddTextInFilter. 
> In the test, if we don't click the "includes browser style", it goes down to
> ~300ms ( similar to what we have for testClearSearchFilter ). It's great but
> then the tests fails.
> 
> I guess we could restrict the list of properties to check, ignoring the
> browser styles' one.
> Does it sounds a good things to do ? I think it's kind of harmless, since we
> test the filtering with the browser style in a sibling test (
> browser_compted_search-filter.js) .

Sounds good to me. 
The only non "browser style" property is "color" for now, we will have to add a few others to keep the filtering relevant.
Flags: needinfo?(jdescottes)
I pushed my patch with my measurement logs : https://treeherder.mozilla.org/logviewer.html#?job_id=18926736&repo=try ( filter on NCHEVOBBE ), and fortunately, the failure shown up.

The test are indeed much slower on Linux : 

* [NCHEVOBBE] start add_task | since start:3ms | since last:3ms
* [NCHEVOBBE] addTab | since start:919ms | since last:917ms
* [NCHEVOBBE] openComputedView | since start:9912ms | since last:8992ms
* [NCHEVOBBE] selectNode | since start:13292ms | since last:3380ms
* [NCHEVOBBE] testAddTextInFilter | since start:37514ms | since last:24222ms
* [NCHEVOBBE] testClearSearchFilter | since start:45369ms | since last:7855ms

Undoubtly, testAddTextInFilter really takes too much time compared to testClearSearchFilter. As discussed previously, I'll edit the test to not show the browser styles and will push again.
I edited the test and pushed again ( https://treeherder.mozilla.org/#/jobs?repo=try&revision=68e2799fe2dd&group_state=expanded&selectedJob=18935618 ), this time, no failures. The measures now are : 

* [NCHEVOBBE] start add_task | since start:13ms | since last:13ms
* [NCHEVOBBE] addTab | since start:903ms | since last:890ms
* [NCHEVOBBE] openComputedView | since start:11099ms | since last:10197ms
* [NCHEVOBBE] selectNode | since start:15270ms | since last:4171ms
* [NCHEVOBBE] testAddTextInFilter | since start:17054ms | since last:1784ms
* [NCHEVOBBE] testClearSearchFilter | since start:19267ms | since last:2213ms

Which is definitely better.
(In reply to Nicolas Chevobbe from comment #7)
> I edited the test and pushed again (
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=68e2799fe2dd&group_state=expanded&selectedJob=18935618
> ), this time, no failures. The measures now are : 
> 
> * [NCHEVOBBE] start add_task | since start:13ms | since last:13ms
> * [NCHEVOBBE] addTab | since start:903ms | since last:890ms
> * [NCHEVOBBE] openComputedView | since start:11099ms | since last:10197ms
> * [NCHEVOBBE] selectNode | since start:15270ms | since last:4171ms
> * [NCHEVOBBE] testAddTextInFilter | since start:17054ms | since last:1784ms
> * [NCHEVOBBE] testClearSearchFilter | since start:19267ms | since last:2213ms
> 
> Which is definitely better.

Great ! 
For info you can use propView.hasMatchedSelectors to check if a property is not coming from a browser style. This way the last check can be turned into:

> is(propView.visible, propView.hasMatchedSelectors, "span " + name + " property visibility check");

and no need for an intermediary object.
> Great ! 
> For info you can use propView.hasMatchedSelectors to check if a property is
> not coming from a browser style. This way the last check can be turned into:
> 
> > is(propView.visible, propView.hasMatchedSelectors, "span " + name + " property visibility check");
> 
> and no need for an intermediary object.

Even greater ! I was unsure about my code, it definitely look nicer your way.
The test used to time out, mainly because we were checking 'Browser styles' on the
computed properties panel, which is quite slow. As the 'Browser styles' checkbox
is already tested in its own test, we can remove it from here, and adapt this test
to take this into account.

Review commit: https://reviewboard.mozilla.org/r/43949/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/43949/
Attachment #8737404 - Flags: review?(jdescottes)
Comment on attachment 8737404 [details]
MozReview Request: Bug 1260714 - Fix intermittent browser_computed_search-filter_clear.js . r=jdescottes

https://reviewboard.mozilla.org/r/43949/#review40549

Perfect, thanks for fixing this Nicolas!

One last try push for this changeset and we are good to go.
Attachment #8737404 - Flags: review?(jdescottes) → review+
The TRY run is over ( https://treeherder.mozilla.org/#/jobs?repo=try&revision=02f8b7b30936 ) and everything looks good, the failure did not occurred.
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/bf1bd53f98ad
Status: ASSIGNED → RESOLVED
Closed: 8 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 48
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: