1506469 - Content should update when loading

Status: RESOLVED FIXED

(Core Graveyard :: Web Replay, defect, P1)

Description

[Jason Laster [:jlast]]

STR:

1. go to http://firefox-dev.tools/debugger-examples/examples/todomvc/
2. add a lot of todos
3. start recording


ER: you see the todos added in the content at the same time that you see a console Message "todo created"

AR: it looks like all of the console messages are logged and then you see the todos.

Comment 1

[Brian Hackett [Laid off!]]

Attachment: patch

I think performance is the real problem here.

When recording a TodoMVC page that has a bunch of TODOs already in it, the TODOs are all initialized when loading without any repainting that would happen during a normal execution.  However, when recording the execution we have to switch to a replaying child every time an object is logged via console.log, so that the object can have its contents inspected.  This is very slow, and all the back and forth switching between recording and replaying processes, flushing recording data to disk etc. causes the console messages to very slowly be filled in, once a second or so.

Repainting at each of these logs is one way of addressing the unexpected visual data, but I think it's better to just make the logging instantaneous: if we don't have to switch to a replaying child to inspect the logged data, things go much much faster.

The reason why we have to switch to a replaying child is that when a recording child responds to a debugger request it can't perform any operations with side effects (including simply enumerating the properties of an arbitrary object) as the operation will not happen while replaying and we might get a recording mismatch as a result.

It would be possible to fix this eventually, so that recording children can perform operations with side effects.  We would have to make sure the same operations were performed at the same place in replaying children, so this is a pretty involved fix, and it is probably not the best thing for the user in any case --- the side effects would be hard to show to the user, and they could see things like variables spontaneously changing values that would be pretty much impossible to figure out, like a poltergeist is haunting the recording or something.

Instead, this patch saves information in the recording/replaying process about the contents of objects that have been included in log messages, and does so in a way that the objects are inspected in a place that will execute while both recording and replaying.  This allows the inspection to take place while still operating on a recording child.  I had to put in a couple restrictions/hacks, where we don't report transitive object properties of logged console objects, or information about the object's prototype --- these will just be omitted from view in the devtools.  This was done to limit the scope of the amount of data we have to capture when logging console objects, and if someone is logging something really complicated they can always just seek to the log point and inspect state that way.

Comment 2

[Logan Smyth [:loganfsmyth]]

Comment on attachment 9024623 [details] [diff] [review]
patch

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

::: devtools/server/actors/replay/debugger.js
@@ +652,5 @@
> +  get proto() {
> +    // Don't allow inspection of the prototypes of objects logged to the
> +    // console. This is a hack that prevents the object inspector from crawling
> +    // the object's prototype chain.
> +    return this._forConsole ? null : this._dbg._getObject(this._data.proto);

Is there anything we could return here that would make it clear to users that this is explicitly being skipped, rather than actually `null`?

::: devtools/server/actors/replay/replay.js
@@ +182,5 @@
>    // created.
>    installPendingHandlers();
>  };
>  
> +const gConsoleObjectProperties = new Map();

Seems like we'd want this to be a WeakMap?

@@ +192,5 @@
> +  // a replaying child process, which is very slow when there are many console
> +  // messages, and B) trying to access objects transitively referred to by
> +  // logged console objects will fail when unpaused, and depends on the current
> +  // state of the process otherwise.
> +  return "value" in desc && !isNonNullObject(desc.value);

I'm not sure I understand this message fully. Why do we want to discard accessor properties?

Comment 3

[Brian Hackett [Laid off!]]

(In reply to Logan Smyth [:loganfsmyth] from comment #2)
> Comment on attachment 9024623 [details] [diff] [review]
> patch
> 
> Review of attachment 9024623 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: devtools/server/actors/replay/debugger.js
> @@ +652,5 @@
> > +  get proto() {
> > +    // Don't allow inspection of the prototypes of objects logged to the
> > +    // console. This is a hack that prevents the object inspector from crawling
> > +    // the object's prototype chain.
> > +    return this._forConsole ? null : this._dbg._getObject(this._data.proto);
> 
> Is there anything we could return here that would make it clear to users
> that this is explicitly being skipped, rather than actually `null`?

I don't think so, .proto has to return an object or null.  An alternative would be to capture the contents of the prototype chain as well, which would allow the server to inspect the prototype chain without having to switch to a replaying child.  In that case the __prototype__ would appear as part of the object in the UI, but trying to inspect it would usually break things because we have to be paused to inspect objects.

> 
> ::: devtools/server/actors/replay/replay.js
> @@ +182,5 @@
> >    // created.
> >    installPendingHandlers();
> >  };
> >  
> > +const gConsoleObjectProperties = new Map();
> 
> Seems like we'd want this to be a WeakMap?

We could, but objects logged to the console will be entrained forever via references from gConsoleMessages, so the two should be equivalent.

> @@ +192,5 @@
> > +  // a replaying child process, which is very slow when there are many console
> > +  // messages, and B) trying to access objects transitively referred to by
> > +  // logged console objects will fail when unpaused, and depends on the current
> > +  // state of the process otherwise.
> > +  return "value" in desc && !isNonNullObject(desc.value);
> 
> I'm not sure I understand this message fully. Why do we want to discard
> accessor properties?

If the server wants to get the values of properties that have getters, it will need to call those getters, which requires switching to a replaying process.  We could provide a value here that shows the property is being skipped, even something as simple as a constant string "value unavailable".

Comment 4

[Logan Smyth [:loganfsmyth]]

> I don't think so, .proto has to return an object or null.  An alternative
> would be to capture the contents of the prototype chain as well, which would
> allow the server to inspect the prototype chain without having to switch to
> a replaying child.  In that case the __prototype__ would appear as part of
> the object in the UI, but trying to inspect it would usually break things
> because we have to be paused to inspect objects.

My concern is essentially that as-is this makes the console potentially misleading when the prototype is inaccessible rather than `null`. If that's the best we can do its not the end of the world, but it doesn't seem ideal.

> trying to inspect it would usually break things
> because we have to be paused to inspect objects.

I'm not sure I understand this part. Why does that arise in this case but in general console display cases?


> We could, but objects logged to the console will be entrained forever via
> references from gConsoleMessages, so the two should be equivalent.
> 

Ah right, fair enough then.


> > @@ +192,5 @@
> > > +  // a replaying child process, which is very slow when there are many console
> > > +  // messages, and B) trying to access objects transitively referred to by
> > > +  // logged console objects will fail when unpaused, and depends on the current
> > > +  // state of the process otherwise.
> > > +  return "value" in desc && !isNonNullObject(desc.value);
> > 
> > I'm not sure I understand this message fully. Why do we want to discard
> > accessor properties?
> 
> If the server wants to get the values of properties that have getters, it
> will need to call those getters, which requires switching to a replaying
> process.  We could provide a value here that shows the property is being
> skipped, even something as simple as a constant string "value unavailable".

My concern is that `this._properties` is also used to implement `getOwnPropertyNames`, so this filtering would make accessor properties entirely invisible, not just inacessible, where it seems like ideally we'd shown then with some kind of flag to indicate that they can't be accessed.

Comment 5

[Brian Hackett [Laid off!]]

(In reply to Logan Smyth [:loganfsmyth] from comment #4)
> > trying to inspect it would usually break things
> > because we have to be paused to inspect objects.
> 
> I'm not sure I understand this part. Why does that arise in this case but in
> general console display cases?

This is tied closely to how the console is implemented.  From what I've seen, when console.log(object) is called the object's immediate contents are expanded and shown in the UI, and the user can click on the object to expand its contents and inspect things it refers to (including its prototype).

With this patch I was trying to get the queries done when fetching the immediate contents to work without needing to switch to a replaying child, and additionally avoid exposing objects to the console which would allow the object to be clicked/expanded and lead to things breaking.

Would it be better to do this in the web console code itself, perhaps?  This could also go through a more formal design process at the next web replay meeting, but it would also be nice if things weren't visibly broken / super slow for users.

Comment 6

[Jason Laster [:jlast]]

This patch feels like a stop-gap, but it has a huge impact on the recording performance, which is the most important metric at the moment.

I think there are some open questions on "how" the console should work when we're paused and not paused.

How does it sound to land this patch as-is and focus on performance and stepping quality pre-orlando and discuss the console architecture at the all-hands?

Comment 7

[Logan Smyth [:loganfsmyth]]

Comment on attachment 9024623 [details] [diff] [review]
patch

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

In the end this seems fine, we can always iterate as we go, I mostly wanted to voice my concerns around the changes in behavior for replay.

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/a424be1d8a66
Allow inspecting objects logged to the console without switching to a replaying child, r=lsmyth.

Comment 9

[Bogdan Tara[:bogdan_tara | bogdant]]

https://hg.mozilla.org/mozilla-central/rev/a424be1d8a66