1925128 - School Edsby website hangs

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect, P2)

Description

[Neha Kochar [:neha]]

​​My son's school uses an edsby website for parent-teacher comms and it used to work smoothly before and recently (maybe since last 2 months) it hangs. I captured a profile with it: https://share.firefox.dev/3A1CihU . Hopefully this helps.
The website https://rotherglen.edsby.com requires login so I'm happy to collect more info if you can direct me to collect whatever you might need to fix it.

Steps to Reproduce:

1. Login to https://rotherglen.edsby.com
2. On the left menu, click on the child name to get info for the child's class.

Expected Results:
Class teacher posts including pictures are shown in chronological order.

Actual Results:
None of the class posts load, the content area is empty.
The content finally loads after 2 minutes.

Profile URL:
https://share.firefox.dev/3A1CihU

Comment 1

[Neha Kochar [:neha]]

Doing the same in Chrome, it isn't immediate but the content on the page loads in 1-2 seconds.

Comment 2

[Markus Stange [:mstange]]

The time is spent doing nursery collections while parsing JSON. https://share.firefox.dev/3zP5VDe

It would be interesting to find out which JSON is being parsed, so that we can turn it into an anonymized testcase.

Comment 3

[Jeff Muizelaar [:jrmuizel]]

The JS code is accessible here: https://rotherglen.edsby.com/static/compiled/dc8774a59c9f69e949d2d7a88904af1e60e052af92eaedfe5f85c1bc71bab5db/core/engine.min.js

Comment 4

[Jeff Muizelaar [:jrmuizel]]

I believe the JSON parsing is coming from here:

        _clone_internal: function(e) {
            if (e instanceof A) {
                let t = "c";
                return b.deserializeClass(e.serialize(t), t);
            }
            try {
                let t = Math.random(), a = JSON.stringify(e, function(e, a) {
                    return "object" == typeof this[e] && this[e] instanceof A ? this[e].serialize(t) : a;
                });
                return JSON.parse(a, function(e, a) {
                    return "object" == typeof a ? b.deserializeClass(a, t) : a;
                });
            } catch (e) {}
        }

Comment 5

[Jeff Muizelaar [:jrmuizel]]

Neha, can you check if it's a regression using mozregression?

Comment 6

[Jan de Mooij [:jandem]]

This is likely a regression from the json-parse-with-source feature we implemented (bug 1913085 or an earlier bug).

Because it's calling JSON.parse with a reviver function, we maintain "parse record" objects that basically mirror the parsed JSON objects but store source information for it. We're fully tracing these maps on each nursery GC it looks like.

Comment 7

[Jan de Mooij [:jandem]]

For the JS shell micro-benchmark below:

--setpref=experimental.json_parse_with_source=false: 450 ms
--setpref=experimental.json_parse_with_source=true : 13442 ms

Bryan, as a first step I think we should flip the pref, definitely on beta, because it will give us more time to fix this regression on Nightly.

function f() {
    var o = [];
    for (var i = 0; i < 100000; i++) {
        o.push({x: "foo".repeat(10) + i, y: "bar".repeat(10) + i});
    }
    var json = JSON.stringify(o);
    var res;
    var t = new Date;
    for (var i = 0; i < 5; i++) {
        res = JSON.parse(json, (key, value) => value);
    }
    print(new Date - t);
    return res;
}
f();

Comment 8

[Markus Stange [:mstange]]

(unsetting needinfo for Neha, I don't think we need the regression range anymore)

Comment 9

[Bryan Thrall [:bthrall]]

We expected the json-parse-with-source feature to make calling JSON.parse with a reviver function more expensive, but this is worse than I expected.

Most of the cost appears to be from allocating JSStrings for the "source", but about a third of it comes from just allocating the context parameter to the reviver.

I'll look into reducing the cost from those two allocations.

Comment 10

[Jan de Mooij [:jandem]]

I think the bigger problem is the GC fully tracing the parse record object roots. You can see this in the flame graph tab of the profiles in comment 0 and comment 2, and in a profile for the micro-benchmark in comment 7.

The tracing gets slow for large object graphs, because there's more and more stuff to trace through.

Comment 11

[BugBot [:suhaib / :marco]]

Set release status flags based on info from the regressing bug 1913085

Comment 12

[Jon Coppeard (:jonco)]

I think the bigger problem is the GC fully tracing the parse record object roots.

Yes, the problem is that there's a large data structure on the stack which is getting traced every time we do a minor GC. One fix for this would be to use JSObjects to hold the ParseRecordObject tree. These would become tenured and since nursery tracing stops when it reaches a tenured object this would greatly reduce the amount of stuff traced.

Another improvement we could make is to pass gcHeap as the third parameter to NewStringCopy in JSONReviveHandler<CharT>::finishPrimitiveParseRecord. Half the minor GCs in the profile come from that site. This would stop allocating source strings in the nursery when the output tree becomes too large to fit in the nursery.

Comment 13

[Jon Coppeard (:jonco)]

(In reply to Jon Coppeard (:jonco) from comment #12)
I also wondered about the possibility of calling the reviver functions as we parse the JSON tree so avoiding the need to create this data structure in the first place. I didn't check the spec too closely so maybe that doesn't work.

Comment 14

[BugBot [:suhaib / :marco]]

Set release status flags based on info from the regressing bug 1913085

Comment 15

[Bryan Thrall [:bthrall]]

Attachment: Bug 1925128 - Convert ParseRecordObject to a NativeObject r=mgaudet!

This reduces the load per minor GC when parsing large JSON structures, which
requires a corresponding large (temporary) ParseRecordObject structure.

InternalizeJSONProperty() can be passed a null parseRecord pointer if, for
example, a reviver function modifies a value and then Steps 2a(iii)(1) or
2c(ii)(1) cannot find the id they are looking for. In the previous version of
the code, this was the same as a ParseRecordObject with undefined value
member.

The ParseRecordObject entries are stored as enumerated properties to avoid
having to allocate an extra JSObject.

Comment 16

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/44b15e68383a
Convert ParseRecordObject to a NativeObject r=mgaudet

Comment 17

[amarc]

Backed out for causing build bustages @ parse-oom.js

• Backout link
• Push with failures
• Failure Log
• Failure line:

TEST-UNEXPECTED-FAIL | js/src/jit-test/tests/JSON/parse-oom.js | [9263] Assertion failure: GCPolicy<T>::isValid(*ptr), at /builds/worker/workspace/obj-spider/dist/include/js/RootingAPI.h:717 (code -11, args "--enable-json-parse-with-source") [0.0 s]

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/8361dc766ac8
Convert ParseRecordObject to a NativeObject r=mgaudet

Comment 19

[Sandor Molnar[:smolnar]]

Backed out for causing SM failures

Backout link: https://hg.mozilla.org/integration/autoland/rev/7e8997918e2dfd9d1b178746fcd987dd34162e95

Push with failures

Failure log -> TEST-UNEXPECTED-FAIL | non262/JSON/parse-with-source.js | (args: "--gc-param=semispaceNurseryEnabled=1") [0.1 s]

Comment 20

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/3775e0d0c233
Convert ParseRecordObject to a NativeObject r=mgaudet

Comment 21

[Norisz Fay [:noriszfay]]

https://hg.mozilla.org/mozilla-central/rev/3775e0d0c233

Comment 22

[Bryan Thrall [:bthrall]]

:neha, would you mind verifying that this is resolved on the original edsby website?

Comment 23

[Neha Kochar [:neha]]

Somehow I missed replying to this, apologies. Yes, I no longer see this issue. Thank you for fixing it.