1594042 - Improve logpoint performance

Status: RESOLVED FIXED

(Core Graveyard :: Web Replay, enhancement)

Description

[Brian Hackett [Laid off!]]

When a logpoint is added that hits in a lot of places, we show a "Loading..." message in the console for each of those hits, which will be replaced with the actual logged value when a replaying process is brought to the hit and is able to do the evaluation. This latter process is generally very slow if there is a significant number of hits. For example, if I add 25 todos to the todomvc example site and log each of them, it takes 15 seconds to evaluate all of the logpoint hits. Getting the final logpoint text is very important for usability and we should make it as fast as possible.

Part of the reason this is slow is that we get pause data for each of the logpoint hits at the same time that we evaluate the logpoint text. This is slow and simply not doing this improves the time to 8 seconds. The pause data can still be fetched after doing all the logpoint evaluations in a region of the recording, which ends up being a net simplification.

Another improvement is to the order in which logpoint hits are evaluated. Right now we add all of them at the same time as pending work that processes can do, and while this allows things to happen in parallel more easily it doesn't necessarily make things faster, as processes might end up running through the same parts of the recording as each other and ignoring logpoints in other parts of the recording. Serially processing the logpoints associated with each saved checkpoint (which are spaced a couple seconds apart in the recording) gives the processes a better chance to spread out, and saving snapshots at the interim checkpoints in these regions avoids the need for excessive rewinding. Making this change improves the time to 2-3 seconds.

A final, experimental improvement is to avoid diverging from the recording and having to rewind after each logpoint evaluation. When there are lots of logpoint hits then the time taken for these rewinds adds up. If the logpoint evaluation is not effectful then there is no need to rewind to erase side effects, and the replay can continue executing to later logpoint hits afterwards. We don't have a way to determine that a logpoint evaluation is not effectful (we need stronger guarantees than the eager evaluation support in bug 1561424) but just to see the benefits I added this functionality and put it behind a new devtools.recordreplay.fastLogpoints preference. This change improves the time to 0.1 seconds, a 150x improvement over the current state of things.

The attached patch makes all these changes, and a couple more besides:

• If a logpoint is removed from the client, the control logic stops evaluating that logpoint and getting pause data for its hits.

• Fix a couple bugs I noticed when starting the recording with a logpoint in the async store. Logpoint messages could disappear from the console or appear multiple times.

Comment 1

[Brian Hackett [Laid off!]]

Attachment: Bug 1594042 - Improve logpoint performance, r=jlast.

Comment 2

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/08a9629903ba
Improve logpoint performance, r=jlast.

Comment 3

[Stefan Hindli [:stefan_hindli]]

https://hg.mozilla.org/mozilla-central/rev/08a9629903ba