1197585 - The tablewidget tests spend a lot of time printing CSS warnings to the console

Status: RESOLVED FIXED

(DevTools :: Framework, defect)

Description

[Sami Jaktholm]

When those tests are executed locally following messages are printed to the output (example):
> 7654 INFO Console message: [JavaScript Warning: "Property contained reference to invalid variable.  Error in parsing value for 'color'.  Falling back to 'inherit'." {file: "chrome://browser/skin/devtools/widgets.css" line: 1272 column: 30380 source: " var(--theme-body-color)"}]

Those messages are printed as the variables are defined in theme-specific sheets which are not loaded in the test document and require the .theme-{light, dark} class to be set.

For a recent mozilla-central push [1] the runtimes are:
* browser_tableWidget_basic.js: 23988ms
* browser_tableWidget_keyboard_interaction.js: 7120ms
* browser_tableWidget_mouse_interaction.js: 6496ms

They are very slow considering that the tests are very simple.
[1] http://ftp.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/mozilla-central-linux/1440171639/mozilla-central_ubuntu32_vm_test-mochitest-devtools-chrome-2-bm05-tests1-linux32-build5.txt.gz

Comment 1

[Sami Jaktholm]

Attachment: bug-1197585-tablewidget-warnings.patch

Here's a patch that fixes the warnings by introducing the required theme sheet and class to the test document.

With this patch the times are following [1]:
* browser_tableWidget_basic.js: 1555ms
* browser_tableWidget_keyboard_interaction.js: 1239ms
* browser_tableWidget_mouse_interaction.js: 1336ms

Try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=63ae08917a29

[1] http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/[e-mail]-63ae08917a29/try-linux/try_ubuntu32_vm_test-mochitest-devtools-chrome-2-bm03-tests1-linux32-build36.txt.gz

Comment 2

[Brian Grinstead [:bgrins]]

Comment on attachment 8651496 [details] [diff] [review]
bug-1197585-tablewidget-warnings.patch

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

Good catch - thanks for the patch!

Relatedly, we should profile why it's that slow to print all those messages.  That's even without the browser console opened, so it might be a good way to capture backend slowness

Comment 3

[Pulsebot]

https://hg.mozilla.org/integration/fx-team/rev/54ac9a920d85

Comment 4

[Sami Jaktholm]

Took a quick profile and 42% of the total time is spent in Tester.onConsoleMessage() [1] (self cost 8%) and most of that is spent in StructuredLogger._dumpMessage() (self cost 31%) [2].

So it's not the backend that is slow, it's just the dumping which is expensive.

[1] https://dxr.mozilla.org/mozilla-central/rev/ba43a48d3c528cc956335793e02504e5ca2c149f/testing/mochitest/browser-test.js#400
[2] https://dxr.mozilla.org/mozilla-central/rev/ba43a48d3c528cc956335793e02504e5ca2c149f/testing/mochitest/tests/SimpleTest/TestRunner.js#266

Comment 5

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/54ac9a920d85

Comment 6

[Brian Grinstead [:bgrins]]

(In reply to Sami Jaktholm from comment #4)
> Took a quick profile and 42% of the total time is spent in
> Tester.onConsoleMessage() [1] (self cost 8%) and most of that is spent in
> StructuredLogger._dumpMessage() (self cost 31%) [2].
> 
> So it's not the backend that is slow, it's just the dumping which is
> expensive.
> 
> [1]
> https://dxr.mozilla.org/mozilla-central/rev/
> ba43a48d3c528cc956335793e02504e5ca2c149f/testing/mochitest/browser-test.
> js#400
> [2]
> https://dxr.mozilla.org/mozilla-central/rev/
> ba43a48d3c528cc956335793e02504e5ca2c149f/testing/mochitest/tests/SimpleTest/
> TestRunner.js#266

Ah, good to know - thanks!