920116 - Show full stack traces for console logged messages

Status: RESOLVED FIXED

(DevTools :: Console, defect, P3)

Description

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

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.

Comment 1

[Mihai Sucan [:msucan]]

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.

Comment 2

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Perhaps we can have this behind a pref in the options panel? Would be nice if we could fix bug 762995.

Comment 3

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

P2.5

Comment 4

[Mihai Sucan [:msucan]]

Attachment: bug920116-p1-1.diff - Console.cpp changes

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.

Comment 5

[Boris Zbarsky [:bzbarsky]]

Attachment: 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.

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?

Comment 6

[Boris Zbarsky [:bzbarsky]]

Attachment: Er, testcase with an actual deep stack

Comment 7

[Boris Zbarsky [:bzbarsky]]

I guess one question is: how common are these methods in the wild, and what sort of performance is expected out of them?

Comment 8

[Boris Zbarsky [:bzbarsky]]

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 9

[Boris Zbarsky [:bzbarsky]]

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.

Comment 10

[Boris Zbarsky [:bzbarsky]]

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.

Comment 11

[Mihai Sucan [:msucan]]

(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!

Comment 12

[Mihai Sucan [:msucan]]

Reported bug 995295 for making console.trace() faster.

Comment 13

[Boris Zbarsky [:bzbarsky]]

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.

Comment 14

[Mihai Sucan [:msucan]]

(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.

Comment 15

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/fx-team/rev/50ed9e6646ad

Comment 16

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/50ed9e6646ad

Comment 17

[Mihai Sucan [:msucan]]

Attachment: 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.

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.)

Comment 18

[Mihai Sucan [:msucan]]

Attachment: webconsole changes v2

Now with a test specific to the new feature being added.

New try push: https://tbpl.mozilla.org/?tree=Try&rev=14493cfa57d8

Comment 19

[Rob Campbell [:rc] (:robcee)]

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.

Comment 20

[Mihai Sucan [:msucan]]

(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.

Comment 21

[Mihai Sucan [:msucan]]

Landed: https://hg.mozilla.org/integration/fx-team/rev/1c12ded4cd82

Comment 22

[Mihai Sucan [:msucan]]

Attachment: screenshot - dark theme

Comment 23

[Mihai Sucan [:msucan]]

Attachment: 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!

Comment 24

[Brian Grinstead [:bgrins]]

Attachment: 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.

Comment 25

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/1c12ded4cd82

Comment 26

[Brian Grinstead [:bgrins]]

(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 27

[Darrin Henein [:darrin]]

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 28

[Darrin Henein [:darrin]]

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.

Comment 29

[Will Bamberg [:wbamberg]]

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?

Comment 31

[Ton [:Tonnes]]

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.

Comment 32

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

(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

Comment 33

[Mihai Sucan [:msucan]]

(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.

Comment 34

[The 8472]

(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.