1463347 - Add distinction between timeLog and timeEnd messages

Status: RESOLVED FIXED

(DevTools :: Console, enhancement, P3)

Description

[Nicolas Chevobbe [:nchevobbe]]

I know that timeLog can have multiple arguments to clarify what call it refers to, but if none provided, it's a bit hard to follow what's going on.

The following code: 

```js
console.time("bar");
console.timeLog("bar");
console.timeLog("bar");
console.timeEnd("bar");
```

will output: 

> bar: 1ms
> bar: 2ms
> bar: 3ms

I feel like the timeEnd should have either a different label, or an icon or something that indicate that it _is_ the timeEnd. For example: 

> bar: 1ms
> bar: 2ms
> bar: 3ms - timer ended

I'm really not sure about the naming and the style of it though.
Victoria, would you have some thoughts on this ?

Comment 1

[Victoria Wang [:victoria]]

Hi Nicolas! That message sounds good. I noticed that this page (https://developer.mozilla.org/en-US/docs/Web/API/console#Timers) mentions there's also a 'Timer started' message which appears on its own line - this seems like it would be nice for the timer ended message too (unless that makes it seem to have a different meaning of less immediacy or something).

Maybe an icon like https://design.firefox.com/icons/viewer/#info (or possibly even https://design.firefox.com/icons/viewer/#history) and Gray 50 color would help to set it apart. If we can't have icons here, it could have brackets or other text decoration instead: [Timer ended]

Comment 2

[Victoria Wang [:victoria]]

Haha, the emoji I put in that comment destroyed my example text - I was suggesting it could look something like this:

[i] Timer started
 bar: 1ms
 bar: 2ms
 bar: 3ms
[i] Timer ended

Comment 3

[Nicolas Chevobbe [:nchevobbe]]

(In reply to Victoria Wang [:victoria] from comment #2)
> Haha, the emoji I put in that comment destroyed my example text - I was
> suggesting it could look something like this:
> 
> [i] Timer started
>  bar: 1ms
>  bar: 2ms
>  bar: 3ms
> [i] Timer ended

We don't have the "timer started" message anymore (but we can have it back).
Icons would be nice, I'll put up a quick patch to try them and put screenshots here.
The last thing is that in this mockup we have 2 "messages" in response to `console.timeEnd("bar")`:
- The actual timer
- The message saying that the timer has ended

I'd prefer if we only have one.
So maybe it could look like

[i] Timer <bar> started
bar: 1ms
bar: 2ms
[i] Timer <bar> ended: 3ms

?

Comment 4

[Victoria Wang [:victoria]]

Ah, I see what you mean about needing to have those two messages grouped. Yes, this sounds good. Actually, now that I realize the timer end needs to be next to the 3ms, I like your first suggestion as well, since it's nice to have the seconds lined up. The 'timer started' message doesn't necessarily need to be added back in unless you think it's helpful. Will defer to you on how to proceed here :).

Comment 5

[u634192]

Hey!

I'm an outreach candidate, and I would like to work on this bug fix.

Comment 6

[Erik Carrillo [:E_Carr]]

(In reply to Nicolas Chevobbe from comment #0)

I know that timeLog can have multiple arguments to clarify what call it
refers to, but if none provided, it's a bit hard to follow what's going on.

The following code:

console.time("bar");
console.timeLog("bar");
console.timeLog("bar");
console.timeEnd("bar");

will output:

bar: 1ms
bar: 2ms
bar: 3ms

I feel like the timeEnd should have either a different label, or an icon or
something that indicate that it is the timeEnd. For example:

bar: 1ms
bar: 2ms
bar: 3ms - timer ended

I'm really not sure about the naming and the style of it though.
Victoria, would you have some thoughts on this ?

If this bug is still unassigned, can I please be assigned to it. Thanks.

Comment 7

[Nicolas Chevobbe [:nchevobbe]]

(In reply to Sola from comment #5)

Hey!

I'm an outreach candidate, and I would like to work on this bug fix.

Hello Sola, I assigned you the bug.

You can read http://docs.firefox-dev.tools/getting-started/ to setup the work environment. Make sure to choose Artifact Builds when asked to as it's much faster.

For the bug, we will need to change how console.timeEnd messages are displayed.
This is where we manage those messages: devtools/client/webconsole/utils/messages.js#115-133

    case "timeLog":
    case "timeEnd":
      if (timer && timer.error) {
        parameters = null;
        messageText = l10n.getFormatStr(timer.error, [timer.name]);
        level = MESSAGE_LEVEL.WARN;
      } else if (timer) {
        // We show the duration to users when calls console.timeLog/timeEnd is called,
        // if corresponding console.time() was called before.
        const duration = Math.round(timer.duration * 100) / 100;
        if (type === "timeEnd") {
          messageText = l10n.getFormatStr("timeEnd", [timer.name, duration]);
          parameters = null;
        } else if (type === "timeLog") {
          const [, ...rest] = parameters;
          parameters = [
            l10n.getFormatStr("timeLog", [timer.name, duration]),
            ...rest,
          ];
        }

The part we should be interested in is the one in the else if (timer) { :

if (type === "timeEnd") {
  messageText = l10n.getFormatStr("timeEnd", [timer.name, duration]);
  parameters = null;
}

So, this means we use localization to show the message. We get a "timeEnd" label, and we pass it the timer name and duration.
This label is defined here: devtools/client/locales/en-US/webconsole.properties#43-46.

# LOCALIZATION NOTE (timeEnd): this string is used to display the result of
# the console.timeEnd() call. Parameters: %1$S is the name of the timer, %2$S
# is the number of milliseconds.
timeEnd=%1$S: %2$Sms

What we need to do is change this so we add a label at the end like:

console.timeEnd=%1$S: %2$Sms - timer ended

You can see that we changed the name of the label. This is needed so people who translate this know that there were a change. This means that we will have to change the label in messages.js (to l10n.getFormatStr("console.timeEnd", [timer.name, duration])).

Comment 8

[u634192]

Attachment: Bug 1463347 - Add distinction between timeLog and timeEnd messages r=nchevobbe

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/0d9daf8104d7
Add distinction between timeLog and timeEnd messages r=nchevobbe

Comment 10

[Cristina Coroiu [:ccoroiu]]

Backed out changeset 0d9daf8104d7 (bug 1463347) for devtools failures at webconsole/test/fixtures/stub-generators/browser_webconsole_check_stubs_console_api.js

Backout: https://hg.mozilla.org/integration/autoland/rev/6b58c76fab103a497ef3a8bf86acc41b9a2f68b2

Failure push: https://treeherder.mozilla.org/#/jobs?repo=autoland&selectedJob=231612653&revision=0d9daf8104d7199600b2664557891c33118d36d0

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=231612653&repo=autoland&lineNumber=14379

task 2019-03-04T10:15:50.795Z] 10:15:50 INFO - TEST-PASS | devtools/client/webconsole/test/fixtures/stub-generators/browser_webconsole_check_stubs_console_api.js | wrapper exists -
[task 2019-03-04T10:15:50.796Z] 10:15:50 INFO - Buffered messages logged at 10:15:49
[task 2019-03-04T10:15:50.796Z] 10:15:50 INFO - Removing tab.
[task 2019-03-04T10:15:50.796Z] 10:15:50 INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2019-03-04T10:15:50.799Z] 10:15:50 INFO - Got event: 'TabClose' on [object XULElement].
[task 2019-03-04T10:15:50.801Z] 10:15:50 INFO - Tab removed and finished closing
[task 2019-03-04T10:15:50.803Z] 10:15:50 INFO - Buffered messages finished
[task 2019-03-04T10:15:50.806Z] 10:15:50 INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/fixtures/stub-generators/browser_webconsole_check_stubs_console_api.js | The consoleApi stubs file needs to be updated by running mach test devtools/client/webconsole/test/fixtures/stub-generators/browser_webconsole_update_stubs_console_api.js -
[task 2019-03-04T10:15:50.806Z] 10:15:50 INFO - Stack trace:
[task 2019-03-04T10:15:50.809Z] 10:15:50 INFO - chrome://mochikit/content/browser-test.js:test_ok:1304
[task 2019-03-04T10:15:50.809Z] 10:15:50 INFO - chrome://mochitests/content/browser/devtools/client/webconsole/test/fixtures/stub-generators/browser_webconsole_check_stubs_console_api.js:null:17
[task 2019-03-04T10:15:50.809Z] 10:15:50 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1106
[task 2019-03-04T10:15:50.811Z] 10:15:50 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1134
[task 2019-03-04T10:15:50.811Z] 10:15:50 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:995
[task 2019-03-04T10:15:50.813Z] 10:15:50 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803
[task 2019-03-04T10:15:50.816Z] 10:15:50 INFO - Leaving test bound
[task 2019-03-04T10:15:50.819Z] 10:15:50 INFO - GECKO(3001) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2019-03-04T10:15:50.822Z] 10:15:50 INFO - GECKO(3001) | MEMORY STAT | vsize 1848MB | residentFast 378MB | heapAllocated 135MB

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/0c4c0810b93f
Add distinction between timeLog and timeEnd messages r=nchevobbe

Comment 12

[Bogdan Tara[:bogdan_tara | bogdant]]

https://hg.mozilla.org/mozilla-central/rev/0c4c0810b93f