Page MenuHomePhabricator

Editing timing data incorrect for second load
Closed, ResolvedPublic

Description

Load the editor, close it then load it again, with network caching disabled so the second load isn't instant:
From the console of https://en.m.wikipedia.org/wiki/Thierry_Henry?trackdebug=1

## FIRST LOAD ##
timing.ve.mobile.performance.system.apiLoad 674ms
VM393:1298 mf.schemaEditAttemptStep.init 0ms
{action: "init", editor_interface: "visualeditor", editing_session_id: "4850fb14e4c83f1e8ef9", init_type: "section", init_mechanism: "click", …}
VM393:217 timing.ve.mobile.performance.system.restbaseLoad 2496ms
VM393:1298 mf.schemaEditAttemptStep.ready 2565ms
{action: "ready", editor_interface: "visualeditor", editing_session_id: "4850fb14e4c83f1e8ef9", ready_type: undefined, ready_mechanism: undefined, …}
VM393:1298 mf.schemaEditAttemptStep.loaded 2567ms

## CLOSE ##
{action: "loaded", editor_interface: "visualeditor", editing_session_id: "4850fb14e4c83f1e8ef9", loaded_type: undefined, loaded_mechanism: undefined, …}
VM393:1298 mf.schemaEditAttemptStep.abort 19163ms

## SECOND LOAD ##
{action: "abort", editor_interface: "visualeditor", editing_session_id: "4850fb14e4c83f1e8ef9", abort_type: "nochange", abort_mechanism: "cancel", …}
VM393:1298 mf.schemaEditAttemptStep.init 0ms
{action: "init", editor_interface: "visualeditor", editing_session_id: "bdb6e263386e70983290", init_type: "section", init_mechanism: "click", …}
VM393:1298 mf.schemaEditAttemptStep.ready 24ms
{action: "ready", editor_interface: "visualeditor", editing_session_id: "bdb6e263386e70983290", ready_type: undefined, ready_mechanism: undefined, …}
VM393:1298 mf.schemaEditAttemptStep.loaded 25ms
{action: "loaded", editor_interface: "visualeditor", editing_session_id: "bdb6e263386e70983290", loaded_type: undefined, loaded_mechanism: undefined, …}
VM393:217 timing.ve.mobile.performance.system.apiLoad 2203ms
VM393:217 timing.ve.mobile.performance.system.restbaseLoad 6498ms

Event Timeline

Specifically the timing.ve.mobile.performance bits?

Specifically this

{action: "init", editor_interface: "visualeditor", editing_session_id: "bdb6e263386e70983290", init_type: "section", init_mechanism: "click", …}
VM393:1298 mf.schemaEditAttemptStep.ready 24ms

Isn't the 24ms just it being a really quick load because ResourceLoader has already loaded everything that comes from the mw.loader.using( 'ext.visualEditor.targetLoader' ) call, so it's just legitimately much faster than the 2565ms the first time?

No, it's too quick. Even with the network requests cached we have to convert the document to linear model and build the view tree. That takes >1s for me.

Change 502992 had a related patch set uploaded (by Esanders; owner: Esanders):
[mediawiki/extensions/MobileFrontend@master] Fix timing of 'ready'/'loaded' events in VisualEditor

https://gerrit.wikimedia.org/r/502992

So it turns out the timing is incorrect for the first load too. It previously fired on #postRender which was before the VE target preparation was complete. I expect our timing stats to jump up after this is deployed, but it also possibly explains why we haven't seen as many gains in the stats from our performance improvements as we'd expected.

Change 502992 merged by jenkins-bot:
[mediawiki/extensions/MobileFrontend@master] Fix timing of 'ready'/'loaded' events in VisualEditor

https://gerrit.wikimedia.org/r/502992

For posterity, this did cause our timing metrics to increase: the mobile visual editor ready timings roughly doubled. So the mobile visual editor's loading performance is actually a lot worse than it appeared 😞

ready timings.png (455×875 px, 69 KB)

@Esanders it looks like this task is specific to mobile-VE. Did or does the same issue exist in desktop VE? And if so has it been fixed there too?

I have never used mobile VE, but I have been (unsuccessfully) trying for several years to tell the Foundation that VE load times were typically around twice as high as the software was reporting back. In one particular test I caught VE sending back ready.timing data below 4 seconds, when the actual time to reach a usable state was over 100 seconds. (VE is slow on large pages, and sometimes it can choke badly.)