Closed Bug 920116 Opened 11 years ago Closed 10 years ago

Show full stack traces for console logged messages

Categories

(DevTools :: Console, defect, P3)

defect

Tracking

(Not tracked)

RESOLVED FIXED
Firefox 31

People

(Reporter: fitzgen, Assigned: msucan)

References

Details

Attachments

(7 files, 1 obsolete file)

It would be super awesome if we had a way to see the full stack at the time a message was logged. I know this could be expensive, but maybe we could do it only when the debugger was active on the page or something.
OS: Mac OS X → All
Hardware: x86 → All
Thanks for the bug report. Also see bug 814497 - which is about stack traces for errors.

For Console API it's easy to add the full stack, because we use Components.stack. We just need UI work. However, we have a performance issue, see bug 762995 - all console API calls would become much slower if we include the full stack.
Perhaps we can have this behind a pref in the options panel? Would be nice if we could fix bug 762995.
P2.5
Priority: -- → P2
Priority: P2 → P3
Severity: normal → major
Blocks: 967226
We decided to add full stacktraces to console.error/exception/assert(), in spite of the performance issues (bug 762995). Also, maybe after the c++ rewrite of the console API implementation getting the stack is faster (untested).

This is one of the important bugs we need to fix for the console output.

I'll submit a separate patch that updates the console output to show stackframes for the relevant console methods.
Assignee: nobody → mihai.sucan
Status: NEW → ASSIGNED
Attachment #8404940 - Flags: review?(bzbarsky)
Attached file Basic performance testcase (obsolete) —
So here's the thing.

Getting the stack is probably somewhat faster, in the sense that it all happens in C++ now, so some of the costs I mention in bug 762995 are no longer relevant.

I did a bit of measuring using this testcase.  What I see is that the trace() calls themselves take about 0.25ms for me with a deep stack, and there is another .25ms worth of browser-side processing time per call as well.  That's with a closed console.  With an open console I get additional beachballing after the timeout fires; presumably there's more async work going on there.

For comparison, in Chrome the relevant numbers are .012ms and .03ms.

One thing that I see happening right now is that we're actually eagerly extracting all the information (filenames, line numbers, function names) from the stack in the C++ console code, and passing it to the browser UI as a ConsoleStackEntry dictionary.  Could we maybe stop doing that and just pass the actual nsIStackFrame, so there's no work to be done until the console is actually opened or something?  Or do we need to have some sort of serializable object that we can pass across process boundaries here?
Attachment #8404980 - Attachment is obsolete: true
I guess one question is: how common are these methods in the wild, and what sort of performance is expected out of them?
Oh, and for scale, back before the C++ console rewrite that testcase was about 1.5ms per call plus about 0.04ms async work, with the console close.  So it's definitely _much_ faster now.  Just still really slow.  ;)
Comment on attachment 8404940 [details] [diff] [review]
bug920116-p1-1.diff - Console.cpp changes

r=me, but please file a followup on making this faster, and let's talk about how to do that.
Attachment #8404940 - Flags: review?(bzbarsky) → review+
One other note: my profile of that "more async work" with the console open is full of cross-compartment proxy gunk.  We should really look into why that's happening.  :(

I filed bug 995047 on speeding up the C++ side of trace() a bit more.
(In reply to Boris Zbarsky [:bz] from comment #5)
> Created attachment 8404980 [details]
> Basic performance testcase
> 
> So here's the thing.
> 
> Getting the stack is probably somewhat faster, in the sense that it all
> happens in C++ now, so some of the costs I mention in bug 762995 are no
> longer relevant.

Yes, this is what I was thinking of as well.

> I did a bit of measuring using this testcase.  What I see is that the
> trace() calls themselves take about 0.25ms for me with a deep stack, and
> there is another .25ms worth of browser-side processing time per call as
> well.  That's with a closed console.  With an open console I get additional
> beachballing after the timeout fires; presumably there's more async work
> going on there.

When you open the console we spend a lot of time shuffling the console messages from the server to the client, then we display them. Output code can still get more perf work - in the work we did for bug 778766 we have focused on the visual improvements and UX, along with moving away from aging code. We will soon be able to remove the slow parts.


> For comparison, in Chrome the relevant numbers are .012ms and .03ms.
> 
> One thing that I see happening right now is that we're actually eagerly
> extracting all the information (filenames, line numbers, function names)
> from the stack in the C++ console code, and passing it to the browser UI as
> a ConsoleStackEntry dictionary.  Could we maybe stop doing that and just
> pass the actual nsIStackFrame, so there's no work to be done until the
> console is actually opened or something?  Or do we need to have some sort of
> serializable object that we can pass across process boundaries here?

I would love to see the |stacktrace| property lazy-populated on the ConsoleEvent object - only when it is read. This would speed-up the generic case: console API calls would be faster for web apps, when devtools are not open.

We need the object to be serializable - we serialize ConsoleEvents to send them through the remote debugging protocol to the client.


(In reply to Boris Zbarsky [:bz] from comment #7)
> I guess one question is: how common are these methods in the wild, and what
> sort of performance is expected out of them?

console.error/exception/assert() are only used when there are potential errors. We dont have any data, but we expect they are less used than log/warn/info/debug(). Also, stacktraces are mainly important for error-related output, so we dont have to do this for all calls.


(In reply to Boris Zbarsky [:bz] from comment #8)
> Oh, and for scale, back before the C++ console rewrite that testcase was
> about 1.5ms per call plus about 0.04ms async work, with the console close. 
> So it's definitely _much_ faster now.  Just still really slow.  ;)

This is a good improvement, but yes, more work is needed.


(In reply to Boris Zbarsky [:bz] from comment #9)
> Comment on attachment 8404940 [details] [diff] [review]
> bug920116-p1-1.diff - Console.cpp changes
> 
> r=me, but please file a followup on making this faster, and let's talk about
> how to do that.

Thanks! Will do.


(In reply to Boris Zbarsky [:bz] from comment #10)
> One other note: my profile of that "more async work" with the console open
> is full of cross-compartment proxy gunk.  We should really look into why
> that's happening.  :(

What do you mean with 'cross-compartment proxy gunk'?


> I filed bug 995047 on speeding up the C++ side of trace() a bit more.

Thanks!
Reported bug 995295 for making console.trace() faster.
Blocks: 995295
The combination of the patches in bug 995047, bug 995442 and bug 995295 brings the trace() time for a 200-deep stack down from .25ms to .02ms for me (and the "async" time in the testcase goes from 0.25ms to 0.05ms).

> We will soon be able to remove the slow parts.

Awesome, thanks!

> What do you mean with 'cross-compartment proxy gunk'?

Objects that are created in one global (e.g. a jsm) being touched by script in another global (e.g. a different JSM or some window)...  It works, but has to go through cross-compartment proxies so can be somewhat slower than accessing objects created in the same global.
(In reply to Boris Zbarsky [:bz] from comment #13)
> The combination of the patches in bug 995047, bug 995442 and bug 995295
> brings the trace() time for a 200-deep stack down from .25ms to .02ms for me
> (and the "async" time in the testcase goes from 0.25ms to 0.05ms).

Thanks for your work on this.
Keywords: checkin-needed
Whiteboard: [leave open]
This patch adds stacktraces to all of the console.error/exception/assert() messages. They are not displayed by default, you can expand the message to see the stack. This is to keep output fairly clean.

Also changed the styling of all messages with severity=error. Making them more obvious. This solves a bug that I cant find the number for now. Errors are hard to spot in the console output.

Comments and feedback is very much welcomed.

First try push: https://tbpl.mozilla.org/?tree=Try&rev=0534fca4d352

(This patch is missing a new test. I will write a test, hopefully tomorrow.)
Attachment #8407719 - Flags: review?(rcampbell)
Now with a test specific to the new feature being added.

New try push: https://tbpl.mozilla.org/?tree=Try&rev=14493cfa57d8
Attachment #8407719 - Attachment is obsolete: true
Attachment #8407719 - Flags: review?(rcampbell)
Attachment #8408508 - Flags: review?(rcampbell)
Comment on attachment 8407719 [details] [diff] [review]
webconsole changes v1

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

Looks good to me.

::: browser/themes/shared/devtools/webconsole.inc.css
@@ +170,5 @@
> +}
> +
> +.theme-dark .message[severity=error] {
> +  background-color: rgba(255, 100, 100, 0.3);
> +}

we're bad at mixing color units in this file. Would love to see these closer to devtools/common.css.

where'd these color values come from? I don't see them in https://developer.mozilla.org/en-US/docs/Tools/DevToolsColors

doing a quick color flip, these look ok.
Attachment #8407719 - Attachment is obsolete: false
Attachment #8408508 - Flags: review?(rcampbell) → review+
(In reply to Rob Campbell [:rc] (:robcee) from comment #19)
> Comment on attachment 8407719 [details] [diff] [review]
> webconsole changes v1
> 
> Review of attachment 8407719 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Looks good to me.

Thanks for the review.


> ::: browser/themes/shared/devtools/webconsole.inc.css
> @@ +170,5 @@
> > +}
> > +
> > +.theme-dark .message[severity=error] {
> > +  background-color: rgba(255, 100, 100, 0.3);
> > +}
> 
> we're bad at mixing color units in this file. Would love to see these closer
> to devtools/common.css.

Agreed, however common.css uses rgba, hsl/a and hex colors as well. We should unify all of our css files...

webconsole.css uses hex and rgba only. The wiki page you pointed to also uses rgba, so I think the patch is fine. Please let me know if you think I should change anything.

> where'd these color values come from? I don't see them in
> https://developer.mozilla.org/en-US/docs/Tools/DevToolsColors

I picked the colors such that they dont stand out too much. A strong red would be too much.

> doing a quick color flip, these look ok.

Good. I'll land this patch and submit a screenshot to ask Darrin for his opinion. If he wants any color tuning we can go for adjustments in a quick follow up patch.
Landed: https://hg.mozilla.org/integration/fx-team/rev/1c12ded4cd82
Whiteboard: [leave open] → [fixed-in-fx-team]
Attached image screenshot - dark theme
Darrin: can you please check if the red color we picked here is fine? Also please check attachment 8410470 [details] for the dark theme. Thank you!
Attachment #8410472 - Flags: ui-review?(dhenein)
Attached image contrast-results.png
(In reply to Mihai Sucan [:msucan] from comment #23)
> Created attachment 8410472 [details]
> screenshot - light theme
> 
> Darrin: can you please check if the red color we picked here is fine? Also
> please check attachment 8410470 [details] for the dark theme. Thank you!

The foreground and background colors on the dark theme does not have enough contrast (see screenshot tested at http://snook.ca/technical/colour_contrast/colour.html).

Maybe you could use the "Red" for light and dark theme from https://developer.mozilla.org/en-US/docs/Tools/DevToolsColors as a base point and add some alpha.  It is going to be tricky to add much background color opacity though, especially on the dark theme, because the string values are orangeish and the color values are just too close.

My suggestion for the dark theme would be to switch .theme-fg-color6 (the orange) to the new 'light orange' color #d99b28, then to use a background like rgba(235, 83, 104, 0.1).  There are probably other ways to do it, but this does reach compliance for contrast.
https://hg.mozilla.org/mozilla-central/rev/1c12ded4cd82
Status: ASSIGNED → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Whiteboard: [fixed-in-fx-team]
Target Milestone: --- → Firefox 31
(In reply to Brian Grinstead [:bgrins] from comment #24)
> Created attachment 8410993 [details]
> contrast-results.png
> 
> (In reply to Mihai Sucan [:msucan] from comment #23)
> > Created attachment 8410472 [details]
> > screenshot - light theme
> > 
> > Darrin: can you please check if the red color we picked here is fine? Also
> > please check attachment 8410470 [details] for the dark theme. Thank you!
> 
> The foreground and background colors on the dark theme does not have enough
> contrast (see screenshot tested at
> http://snook.ca/technical/colour_contrast/colour.html).
> 
> Maybe you could use the "Red" for light and dark theme from
> https://developer.mozilla.org/en-US/docs/Tools/DevToolsColors as a base
> point and add some alpha.  It is going to be tricky to add much background
> color opacity though, especially on the dark theme, because the string
> values are orangeish and the color values are just too close.
> 
> My suggestion for the dark theme would be to switch .theme-fg-color6 (the
> orange) to the new 'light orange' color #d99b28, then to use a background
> like rgba(235, 83, 104, 0.1).  There are probably other ways to do it, but
> this does reach compliance for contrast.

Another option to get more contrast would be to use a different color for strings that are logged to the console - we could use a blue color instead of orange.
Comment on attachment 8410470 [details]
screenshot - dark theme

This is a tricky one, the light theme looks fine but clearly the dark theme is borderline illegible. I see two options: 

1. Fine tune the orange/background combo as per bgrins' suggestion to get contrast compliance;

2. Re-evaluate the dark theme text colors in general, as even on black some of the colors lack strong clarity.
Comment on attachment 8410472 [details]
screenshot - light theme

Light theme looks great. Dark theme screenshot has comments.

Nit: Text in some lines seems off-center vertically, we should fix this before landing anything.
Attachment #8410472 - Flags: ui-review?(dhenein) → feedback+
Depends on: 1000243
Mihai: I've updated the Web Console doc: https://developer.mozilla.org/en-US/docs/Tools/Web_Console#Error_messages - am I right that it's only error messages that have a stack trace?
Flags: needinfo?(mihai.sucan)
If messageToggleDetails is a tooltip, please remove the period. Tooltips are never written in imperative mood but infinitive mood instead, hence proper absence/presence of periods isn’t just a matter of consistency for en-US but also vital info for localizers. Also see bug 951132.
(In reply to Ton from comment #31)
> If messageToggleDetails is a tooltip, please remove the period. Tooltips are
> never written in imperative mood but infinitive mood instead, hence proper
> absence/presence of periods isn’t just a matter of consistency for en-US but
> also vital info for localizers. Also see bug 951132.

Honestly, I still find this tooltip rule quite subtle and surprising, even as a native English speaker!  I am sure there are many developers who are not aware of it.  So, I've added a note about this to the localization best practices[1] page.  Feel free to edit it, as I've essentially paraphrased your comment here.

[1]: https://developer.mozilla.org/en-US/docs/Mozilla/Localization/Localization_best_practices#Tooltips
(In reply to Will Bamberg [:wbamberg] from comment #29)
> Mihai: I've updated the Web Console doc:
> https://developer.mozilla.org/en-US/docs/Tools/Web_Console#Error_messages -
> am I right that it's only error messages that have a stack trace?

Yes, and asserts. Thank you!

(In reply to Ton from comment #31)
> If messageToggleDetails is a tooltip, please remove the period. Tooltips are
> never written in imperative mood but infinitive mood instead, hence proper
> absence/presence of periods isn’t just a matter of consistency for en-US but
> also vital info for localizers. Also see bug 951132.

Please file a bug report.
Flags: needinfo?(mihai.sucan)
Depends on: 1218089
(In reply to Mihai Sucan [:msucan] from comment #17)
> Created attachment 8407719 [details] [diff] [review]
> webconsole changes v1
> 
> This patch adds stacktraces to all of the console.error/exception/assert()
> messages. They are not displayed by default, you can expand the message to
> see the stack. This is to keep output fairly clean.

Does that also apply to errors generated by uncaught exceptions? I don't see a way to look at a stack of those in the error console.
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.