Last Comment Bug 648749 - Talos should capture error console output in the logs
: Talos should capture error console output in the logs
Status: RESOLVED FIXED
:
Product: Testing
Classification: Components
Component: Talos (show other bugs)
: unspecified
: All All
: -- normal (vote)
: ---
Assigned To: Wladimir Palant
:
Mentors:
Depends on: 651670
Blocks: 599169 AddonSlowStartup
  Show dependency treegraph
 
Reported: 2011-04-09 07:18 PDT by Wladimir Palant
Modified: 2011-05-11 11:34 PDT (History)
7 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---


Attachments
Proposed patch (2.39 KB, patch)
2011-04-18 15:41 PDT, Wladimir Palant
no flags Details | Diff | Splinter Review
[checked in]Patch v2 (3.88 KB, patch)
2011-04-20 04:35 PDT, Wladimir Palant
anodelman: review+
Details | Diff | Splinter Review

Description Wladimir Palant 2011-04-09 07:18:56 PDT
I can see that Download Statusbar performance testing results on OS X are unrealistically low - around 20ms slowdown both on March 26th and April 2nd. On other platforms the same extension adds 70-80ms to the startup time. The suspicion is that the extension was broken during testing and didn't actually do anything. Yet the log looks perfectly normal. To help investigate such cases (and also the cases where an extension is abnormally slow on some platform) Talos needs to capture error console output in addition to dump() calls.
Comment 1 alice nodelman [:alice] [:anode] 2011-04-11 11:50:55 PDT
Talos captures all console output - the basic command for running the browser is something like 'firefox.exe > log.txt'.  We are already capturing everything that there is to see.
Comment 2 Wladimir Palant 2011-04-11 13:48:12 PDT
Reopening - I was talking about Error Console (formerly JavaScript Console). In other words, JavaScript errors and various browser warnings need to be captured, this would in particular help verify that the test is valid.
Comment 3 alice nodelman [:alice] [:anode] 2011-04-11 21:57:59 PDT
Asked around, and this is how mozmill handles the problem:

https://github.com/ahal/mozmill/blob/consoleReporting/mozmill/mozmill/extension/resource/modules/frame.js#L449
Comment 4 Wladimir Palant 2011-04-12 03:36:44 PDT
Yes, registering an nsIConsoleListener instance and calling dump() for all the messages reported should be the way to go. Unfortunately, this won't be possible without having some minimal extension installed to do the job.
Comment 5 Wladimir Palant 2011-04-18 15:41:28 PDT
Created attachment 526852 [details] [diff] [review]
Proposed patch

Obviously, installing an extension to capture the errors isn't the ideal course of action - this extension itself might skew the results. Then again, only the messages during startup are interesting. So getting the list of messages from the console service in startup_test.html and tspaint_test.html should be sufficient.
Comment 6 alice nodelman [:alice] [:anode] 2011-04-18 16:09:53 PDT
I'll get this into talos staging and see how it goes.
Comment 7 alice nodelman [:alice] [:anode] 2011-04-18 16:48:28 PDT
I believe that the placement of the extra dump lines will affect our reported ts_shutdown numbers, as the the browser will have to complete the dump before it can continue shutting down.  We'll want to dump this info before we collect our pre-shutdown timestamp and close the browser.
Comment 8 Wladimir Palant 2011-04-20 04:35:09 PDT
Created attachment 527230 [details] [diff] [review]
[checked in]Patch v2

New patch, this time without skewing ts_shutdown results. Making window closing asynchronous isn't strictly necessary but I noticed that closing the browser synchronously in the load event skews the results considerably - for a synchronous close I see 200ms for ts_shutdown, with an asynchronous close I get only 175ms. I guess that this is because the browser isn't quite finished starting up when the load event fires so ts_shutdown right now ends up measuring some of the delayed startup overhead.

I had to get rid of document.write() - in the load event it will replace the current document which will clear the window's scope and break code executing asynchronously. Changing document.body.textContent will show the text without causing further reaching effects.
Comment 9 alice nodelman [:alice] [:anode] 2011-04-25 15:30:07 PDT
Will be testing new patch on staging this week.
Comment 10 alice nodelman [:alice] [:anode] 2011-04-27 14:04:57 PDT
The patch is green on all platforms.  I'm confident that it will not break the ts/tpaint tests.  It should be rolled out in an appropriate downtime as there could be number wobble.
Comment 11 alice nodelman [:alice] [:anode] 2011-04-28 10:28:36 PDT
Comment on attachment 527230 [details] [diff] [review]
[checked in]Patch v2

changeset:   233:025a27bd2cd8
Comment 12 alice nodelman [:alice] [:anode] 2011-05-11 11:34:22 PDT
Deployed.

Note You need to log in before you can comment on or make changes to this bug.