1065722 - [jsdbg2] Expose the tracelogger to JS via the Debugger API

Status: RESOLVED WONTFIX

(Core :: JavaScript Engine, defect)

Description

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

We should be able to start/stop the tracelogger via the Debugger API and also periodically drain the log to get function calls/exits since either the last time we drained the log or when we started tracing.

Debugger.prototype.{startTraceLogger, stopTraceLogger, drainTraceLog} ?

Would love to have this data in the log:

* Shallow copy of the first n parameters passed to a function
* Type of frame exit (return vs exception vs yield)
  * And a shallow copy of the value returned/thrown/yielded
* The function's displayAtom name
* The function's definition site (filename, line, column)
* The frame entrance and exit sites (filename, line, column)

Comment 1

[Hannes Verschore [:h4writer]]

(In reply to Nick Fitzgerald [:fitzgen] from comment #0)
> * Shallow copy of the first n parameters passed to a function
I wouldn't recommend this. This will make this considerable slower. I understand one might find it interesting, but this can be retrieved by using the debugger itself, right? (Placing  breakpoint etc.). So I currently envision to not support this, though it might be possible with some extra work.

> * Type of frame exit (return vs exception vs yield)
This is currently not captured, but shouldn't be too hard. Now I would prefer to not do this on the first try. It can cause some serious debugging/testing before getting it right. 

>   * And a shallow copy of the value returned/thrown/yielded
Same concern as first. This will make this considerable slower. So I won't implement it (yet), but shouldn't be too hard.

> * The function's displayAtom name
> * The function's definition site (filename, line, column)

check

> * The frame entrance and exit sites (filename, line, column)
Currently nothing is saved about this. So this might also be follow-up work.

So I narrowed down the scope to scripts name and definition site for the first "version/try". I want to tackle the TL adjustments first before increasing the scope if that is alright?

Now we should probably discuss how "drainTraceLog" would/should look like? We need to find something where we can add new information easily, is easy to parse, but is not to complex (so easy/fast to construct).

What about:
[
 [Debugger.prototype.TL_START, "atomName", "filename", "line", "column"],
 [Debugger.prootype.TL_STOP],
 ...
]

so a list of [MessageType, extrainfo]?

Comment 2

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

(In reply to Hannes Verschore [:h4writer] from comment #1)
> (In reply to Nick Fitzgerald [:fitzgen] from comment #0)
> > * Shallow copy of the first n parameters passed to a function
> I wouldn't recommend this. This will make this considerable slower. I
> understand one might find it interesting, but this can be retrieved by using
> the debugger itself, right? (Placing  breakpoint etc.). So I currently
> envision to not support this, though it might be possible with some extra
> work.

I think we do want this, eventually. The idea is to provide a better printf-debugging experience and just knowing what is or isn't called isn't enough. Empirically, the first thing printf debugger types start doing is logging functions and the arguments they think are relevant to their problem at hand. I think paying the performance cost is perfectly fine, because it will still be a ton faster than using Debugger.prototype.onEnterFrame and friends. Breakpoints give you a close up, highly detailed, microscopic view of your program execution. Logging parameter values gives you a big picture, macroscopic view. You also don't run into the "oh crap, I didn't mean to continue from that BP, let me go back and inspect that state again" problem (although not as much as a record/replay experience, but that is off the table as far as I know).

Completely understand punting on this for a first pass just to get something out that actually works rather than getting stuck in add-just-one-more-feature limbo. But I'd really like it eventually.

Could totally be an option that you supply when starting the trace logger, too.

> > * Type of frame exit (return vs exception vs yield)
> This is currently not captured, but shouldn't be too hard. Now I would
> prefer to not do this on the first try. It can cause some serious
> debugging/testing before getting it right. 

Sure.

> > * The frame entrance and exit sites (filename, line, column)
> Currently nothing is saved about this. So this might also be follow-up work.
> 
> So I narrowed down the scope to scripts name and definition site for the
> first "version/try". I want to tackle the TL adjustments first before
> increasing the scope if that is alright?

Sounds 100% fine.

> Now we should probably discuss how "drainTraceLog" would/should look like?
> We need to find something where we can add new information easily, is easy
> to parse, but is not to complex (so easy/fast to construct).
> 
> What about:
> [
>  [Debugger.prototype.TL_START, "atomName", "filename", "line", "column"],
>  [Debugger.prootype.TL_STOP],
>  ...
> ]
> 
> so a list of [MessageType, extrainfo]?

I'd really prefer an array of objects of the form

  { type: CALL | RETURN | YIELD | THROW, // (these can be number constants)
    functionName: String,
    filename: String,
    lineNumber: Number,
    columnNumber: Number,
    ...
  }

rather than nested arrays. It is also easy to extend in the future by adding new properties, which I think is nicer than making the arrays longer.

I don't think that the nested arrays have any advantage over this.

What do you think?

Comment 3

[Hannes Verschore [:h4writer]]

(In reply to Nick Fitzgerald [:fitzgen] from comment #2)
> Could totally be an option that you supply when starting the trace logger, too.

Yeah. Since it is a must-have, I'll eventually implement this and then we can still decide to make an option out of it if it hurts performance big-time (like I'm predicting)

> I'd really prefer an array of objects of the form
> 
>   { type: CALL | RETURN | YIELD | THROW, // (these can be number constants)
>     functionName: String,
>     filename: String,
>     lineNumber: Number,
>     columnNumber: Number,
>     ...
>   }
> 
> rather than nested arrays. It is also easy to extend in the future by adding
> new properties, which I think is nicer than making the arrays longer.
> 
> I don't think that the nested arrays have any advantage over this.
> 
> What do you think?

Yes that is also good. I was a bit over-optimizing here, but speedwise it probably shouldn't make a big difference.

Comment 4

[Hannes Verschore [:h4writer]]

A small update on the progress. The biggest blockers are done now.
Not landed. I want to land them at the same time. Since they are quite incremental. And I don't want to fix bugs in the between states. My intention is to have a big test round before landing. Also I think it might be good to wait for the merge. Also making the target for this feature FF36.

Done:
Bug 996509 and bug 1071546: Enable building tracelogger by default
Bug 1072903: Split tracelogger logging from graph creation

Next (in order):
Bug XXX: Disable graph creation and time logging by default. (Is now easy with bug 1072903)
Bug 1072906: Make it possible to dynamically toggle logging in Baseline/IonMonkey (I expect this to be easy, famous last words)
Bug XXX: Change ContinuousSpace to a circular buffer
Bug 1072910: Create hooks for the Debugger.

So if everything goes smoothly I might have a version that spews logs to the Debugger at the end of next week.
After which it becomes polishing and improving towards giving more of the requested information. E.g. arguments of a function. I have already a plan for this, but this will also require some changes, which I didn't do yet, because they aren't needed for the first version.

Comment 5

[Hannes Verschore [:h4writer]]

https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=bfd0e9d69d20

Comment 6

[Hannes Verschore [:h4writer]]

Okey getting everything fixed on tbpl took a little bit longer than expected.
It is green now, but since merge is Monday, I'll wait till after the merge to land.

Comment 7

[Hannes Verschore [:h4writer]]

(In reply to Hannes Verschore [:h4writer] from comment #6)
> Okey getting everything fixed on tbpl took a little bit longer than expected.
> It is green now, but since merge is Monday, I'll wait till after the merge
> to land.

Scratch that. Merge date has been postponed. So landed :D.