cypress: fast sleep

[mmeeks]

We should be able to predict that nothing will happen when we sleep in cypress tests, and so execute them far faster. Of course, this may fall foul of JS timeouts - but if we can turn 250ms into 5ms a lot then I hope we can make a large difference to how quickly cypress tests run - without doing anything negative for reliability.

http://users.freedesktop.org/~michael/fast-sleep.patch

Has my random git stash - some of this eg. 'processtoidle' made it into master online I think, other bits: like getting the right browser (the one that actually has the websocket open) to send the right event, and check its return and post across to the cypress controlling process are more tricky. I would expect to see 'No socket' from bits of that from having not got that right.

Anyhow - hopefully a useful idea.

I expect we may in due course as/when it is working ensure we have got rid of server-side 'blink' timeouts that may create events that squash the range we can see ahead to.

HTH.

[tml1024]

In this:

+           console.assert(this._sleepFn, 'sleep fn is not set!');
+           this._sleepFn(this._sleepSerial == serial);
+           this._sleepFn = undefined;
+           return;

Shouldn't the sleepFn be set to undefined only when this._sleepSerial == serial is true? Otherwise, this doesn't make sense, does it? As this._sleepFn is called with the expression this._sleepSerial == serial, presumably this code can be hit also in cases where that expression is not true. (And the expectation is that later it will be hit when the expression is true.) But then in those later cases the assertion will fail. Or am I missing something? (And what if this code is hit more times, after this._sleepSerial == serial? Then the assertion will also fail.

[mmeeks]

Ah - of course, its horribly unfinished =) I think the idea of the serial was to make sure that the async reply assuring us that all is sleeping - is paired up with our request - so that there is/was nothing bad happening in between times that caused us to wake up and process another event and thus (perhaps) create more work etc. So - patch is really just a suggestion / base to work from.

[tml1024]

Here is my work in progress. After changing those added cy.log() calls to console.log() and adding some more, I finally notice that win.app does not exist in that added fastWait() function.

I simplified the callback a bit, no need to pass a parameter that is true or false, instead call the callback only for the true case, and also avoid a potential assertion failure (as mentioned in my previous comment). But, as none of that ever gets invoked, hard to say whether it works.

Continuing investigating.

diff --git a/browser/src/core/Socket.js b/browser/src/core/Socket.js
index 82b663fce..5e64264c0 100644
--- a/browser/src/core/Socket.js
+++ b/browser/src/core/Socket.js
@@ -27,6 +27,7 @@ app.definitions.Socket = L.Class.extend({

    initialize: function (map) {
        window.app.console.debug('socket.initialize:');
+       this._serial = 0;
        this._map = map;
        this._msgQueue = [];
        this._delayedMessages = [];
@@ -153,6 +154,7 @@ app.definitions.Socket = L.Class.extend({
    },

    _doSend: function(msg) {
+       this._serial++;
        // Only attempt to log text frames, not binary ones.
        if (typeof msg === 'string')
            this._logSocket('OUTGOING', msg);
@@ -375,6 +377,19 @@ app.definitions.Socket = L.Class.extend({
    // buffer of web-socket messages in the client that we can't
    // process so - slurp and the emit at idle - its faster to delay!
    _slurpMessage: function(e) {
+
+       // accelerated idling for unit tests
+       if (e.textMsg && e.textMsg.startsWith('idle: serial=')) {
+           var serial = parseInt(e.textMsg.substr(13));
+           if (this._sleepDoneFn && this._sleepSerial == serial) {
+               this._sleepDoneFn();
+               this._sleepDoneFn = undefined;
+           }
+           return;
+       }
+
+       this._serial++;
+
        if (!this._slurpQueue || !this._slurpQueue.length) {
            this._queueSlurpEventEmission();
            this._slurpQueue = [];
@@ -383,6 +398,15 @@ app.definitions.Socket = L.Class.extend({
        this._slurpQueue.push(e);
    },

+   // Use processeventstoidle - to queue a sleep, calls back with
+   // the resulting sleep serial on success.
+   _sleepFast: function(cb, t) {
+       console.assert(!this._sleepDoneFn, '_sleepDoneFn already set!');
+       this._sleepDoneFn = cb;
+       this._sleepSerial = this._serial + 1;
+       this.sendMessage('processtoidle timeout=' + t + ' serial=' + this._sleepSerial);
+   },
+
    // make profiling easier
    _extractCopyObject: function(e) {
        var index;
diff --git a/cypress_test/integration_tests/common/helper.js b/cypress_test/integration_tests/common/helper.js
index aa2c03a53..242a0eb46 100644
--- a/cypress_test/integration_tests/common/helper.js
+++ b/cypress_test/integration_tests/common/helper.js
@@ -830,6 +830,24 @@ function canvasShouldNotBeFullWhite(selector,frameId) {
    canvasShouldBeFullWhiteOrNot(selector, false, frameId);
 }

+// This hooks into the socket & the core if it can to accelerate sleeping
+function fastWait(callback, waitOnce, maxDuration) {
+   cy.window().then((win) => {
+       if (win.app) {
+           if (win.app.socket) {
+               console.log('**************** fastWait: Calling _sleepFast');
+               win.app.socket._sleepFast(callback, maxDuration);
+               } else {
+               console.log('**************** fastWait: No win.app.socket');
+           }
+       } else {
+           console.log('**************** fastWait: No win.app');
+       }
+   });
+
+   cy.wait(waitOnce, { log: false });
+}
+
 // Waits until a DOM element becomes idle (does not change for a given time).
 // It's useful to handle flickering on the UI, which might make cypress
 // tests unstable. If the UI flickers, we can use this method to wait
@@ -845,10 +863,12 @@ function waitUntilIdle(selector, content, waitingTime = mobileWizardIdleTime) {
    cy.log('Param - waitingTime: ' + waitingTime);

    var item;
-   // We check every 'waitOnce' time whether we are idle.
-   var waitOnce = 250;
    // 'idleSince' variable counts the idle time so far.
    var idleSince = 0;
+   // We check every 'waitOnce' time whether we are idle.
+   var waitOnce = 25;
+   // can we look ahead and show we are idle already ?
+   let isDone = false;
    if (content) {
        // We get the initial DOM item first.
        cy.contains(selector, content, { log: false })
@@ -857,9 +877,12 @@ function waitUntilIdle(selector, content, waitingTime = mobileWizardIdleTime) {
            });

        cy.waitUntil(function() {
-           cy.wait(waitOnce, { log: false });
+           fastWait(function() {
+               isDone = true;
+               console.log('**************** fastWait 1 callback: Set isDone to true');
+           }, waitOnce, waitingTime - idleSince);

-           return cy.contains(selector, content, { log: false })
+           return isDone || cy.contains(selector, content, { log: false })
                .then(function(itemToIdle) {
                    if (Cypress.dom.isDetached(item[0])) {
                        cy.log('Item was detached after ' + (idleSince + waitOnce).toString() + ' ms.');
@@ -879,9 +902,12 @@ function waitUntilIdle(selector, content, waitingTime = mobileWizardIdleTime) {
            });

        cy.waitUntil(function() {
-           cy.wait(waitOnce, { log: false });
+           fastWait(function() {
+               isDone = true;
+                   console.log('**************** fastWait 2 callback: Set isDone to true');
+           }, waitOnce, waitingTime - idleSince);

-           return cy.get(selector, { log: false })
+           return isDone || cy.get(selector, { log: false })
                .then(function(itemToIdle) {
                    if (Cypress.dom.isDetached(item[0])) {
                        cy.log('Item was detached after ' + (idleSince + waitOnce).toString() + ' ms.');
diff --git a/cypress_test/support/index.js b/cypress_test/support/index.js
index 340b984ed..21f36f6b9 100644
--- a/cypress_test/support/index.js
+++ b/cypress_test/support/index.js
@@ -13,7 +13,7 @@ if (Cypress.env('INTEGRATION') === 'php-proxy') {
    });
 }

-var COMMAND_DELAY = 1000;
+var COMMAND_DELAY = 0; // 1000;

 if (Cypress.browser.isHeaded) {
    Cypress.Commands.overwrite('get', function(originalFn, selector, options) {
diff --git a/kit/Kit.cpp b/kit/Kit.cpp
index b7efdf433..bde538e1b 100644
--- a/kit/Kit.cpp
+++ b/kit/Kit.cpp
@@ -124,6 +124,11 @@ static Document *singletonDocument = nullptr;
 /// flush sockets with a 'processtoidle' -> 'idle' reply.
 static std::chrono::steady_clock::time_point ProcessToIdleDeadline;

+/// A stamp we return to inform the other end that we processed
+/// all messages up to this serial, to allow them to pair a
+/// "processtoidle" with the correct "idle" reply.
+static uint32_t ProcessToIdleSerial;
+
 #ifndef BUILDING_TESTS
 static bool AnonymizeUserData = false;
 static uint64_t AnonymizationSalt = 82589933;
@@ -1560,7 +1565,7 @@ public:
             return; // more to do
         }

-        sendTextFrame("idle");
+        sendTextFrame("idle: serial=" + std::to_string(ProcessToIdleSerial));

         // get rid of idle check for now.
         ProcessToIdleDeadline = std::chrono::steady_clock::now() - std::chrono::milliseconds(10);
@@ -1605,9 +1610,11 @@ public:
                 else if (tokens.equals(0, "processtoidle"))
                 {
                     ProcessToIdleDeadline = std::chrono::steady_clock::now();
-                    uint32_t timeoutUs = 0;
-                    if (tokens.getUInt32(1, "timeout", timeoutUs))
-                        ProcessToIdleDeadline += std::chrono::microseconds(timeoutUs);
+                    uint32_t val = 0;
+                    if (tokens.getUInt32(1, "timeout", val))
+                        ProcessToIdleDeadline += std::chrono::microseconds(val);
+                    if (tokens.getUInt32(1, "serial", val))
+                        ProcessToIdleSerial = val;
                 }
                 else if (tokens.equals(0, "callback"))
                 {
diff --git a/wsd/ClientSession.cpp b/wsd/ClientSession.cpp
index eb6f7bc10..83b894d4f 100644
--- a/wsd/ClientSession.cpp
+++ b/wsd/ClientSession.cpp
@@ -959,6 +959,7 @@ bool ClientSession::_handleInput(const char *buffer, int length)
              tokens.equals(0, "getchildid") ||
              tokens.equals(0, "gettextselection") ||
              tokens.equals(0, "paste") ||
+             tokens.equals(0, "processtoidle") ||
              tokens.equals(0, "insertfile") ||
              tokens.equals(0, "key") ||
              tokens.equals(0, "textinput") ||

[tml1024]

I tried changing the

cy.window().then((win) => { ... }

in the fastWait function to

cy.window().then(function(win) { ... }

which is the form used in other places, but did not help. I still get the **************** fastWait: No win.app

[tml1024]

But apparently those two things mean the same anyway?

[tml1024]

I see in git commit messages and in the code mentions of the concept of something being "detached". Is that what having "different JS VMs" for different parts of the code refers to?

[tml1024]

I tried for instance moving those fastWait() calls into the function passed to the then() call in the function passed to the cy.waitUntil() call in waitUntilIdle(), just randomly hoping that might work, that window.app would exist then, but nope.

[tml1024]

Ha, progress: If I use getCoolFrameWindow() instead of cy.window() in the fastWait() function then win.app and win.app.socket actually exist.

[tml1024]

This is what I currently have, but sadly the many Cypress checks fail with this.

diff --git a/browser/src/core/Socket.js b/browser/src/core/Socket.js
index 75a9a56ef..56b090e04 100644
--- a/browser/src/core/Socket.js
+++ b/browser/src/core/Socket.js
@@ -27,6 +27,7 @@ app.definitions.Socket = L.Class.extend({

    initialize: function (map) {
        window.app.console.debug('socket.initialize:');
+       this._serial = 0;
        this._map = map;
        this._msgQueue = [];
        this._delayedMessages = [];
@@ -153,6 +154,7 @@ app.definitions.Socket = L.Class.extend({
    },

    _doSend: function(msg) {
+       this._serial++;
        // Only attempt to log text frames, not binary ones.
        if (typeof msg === 'string')
            this._logSocket('OUTGOING', msg);
@@ -375,6 +377,19 @@ app.definitions.Socket = L.Class.extend({
    // buffer of web-socket messages in the client that we can't
    // process so - slurp and the emit at idle - its faster to delay!
    _slurpMessage: function(e) {
+
+       // accelerated idling for unit tests
+       if (e.textMsg && e.textMsg.startsWith('idle: serial=')) {
+           var serial = parseInt(e.textMsg.substr(13));
+           if (this._sleepDoneFn && this._sleepSerial == serial) {
+               this._sleepDoneFn();
+               this._sleepDoneFn = undefined;
+           }
+           return;
+       }
+
+       this._serial++;
+
        if (!this._slurpQueue || !this._slurpQueue.length) {
            this._queueSlurpEventEmission();
            this._slurpQueue = [];
@@ -383,6 +398,13 @@ app.definitions.Socket = L.Class.extend({
        this._slurpQueue.push(e);
    },

+   // Use processeventstoidle - to queue a sleep, calls back with
+   // the resulting sleep serial on success.
+   _sleepFast: function(cb, t) {
+       this._sleepSerial = this._serial + 1;
+       this.sendMessage('processtoidle timeout=' + t + ' serial=' + this._sleepSerial);
+   },
+
    // make profiling easier
    _extractCopyObject: function(e) {
        var index;
diff --git a/cypress_test/integration_tests/common/helper.js b/cypress_test/integration_tests/common/helper.js
index aa2c03a53..46cbbc9fc 100644
--- a/cypress_test/integration_tests/common/helper.js
+++ b/cypress_test/integration_tests/common/helper.js
@@ -830,6 +830,25 @@ function canvasShouldNotBeFullWhite(selector,frameId) {
    canvasShouldBeFullWhiteOrNot(selector, false, frameId);
 }

+// This hooks into the socket & the core if it can to accelerate sleeping
+function fastWait(callback, waitOnce, maxDuration) {
+   getCoolFrameWindow().then((win) => {
+       // cy.debug();
+       if (win.app) {
+           if (win.app.socket) {
+               console.log('**************** fastWait: Calling _sleepFast');
+               win.app.socket._sleepFast(callback, maxDuration);
+               } else {
+               console.log('**************** fastWait: No win.app.socket');
+           }
+       } else {
+           console.log('**************** fastWait: No win.app');
+       }
+   });
+
+   cy.wait(waitOnce, { log: false });
+}
+
 // Waits until a DOM element becomes idle (does not change for a given time).
 // It's useful to handle flickering on the UI, which might make cypress
 // tests unstable. If the UI flickers, we can use this method to wait
@@ -845,10 +864,16 @@ function waitUntilIdle(selector, content, waitingTime = mobileWizardIdleTime) {
    cy.log('Param - waitingTime: ' + waitingTime);

    var item;
-   // We check every 'waitOnce' time whether we are idle.
-   var waitOnce = 250;
    // 'idleSince' variable counts the idle time so far.
    var idleSince = 0;
+   // We check every 'waitOnce' time whether we are idle.
+   var waitOnce = 25;
+   // can we look ahead and show we are idle already ?
+   let isDone = false;
+   let fastWaitCallback = function() {
+       isDone = true;
+       console.log('**************** fastWait callback: Set isDone to true');
+   };
    if (content) {
        // We get the initial DOM item first.
        cy.contains(selector, content, { log: false })
@@ -856,10 +881,14 @@ function waitUntilIdle(selector, content, waitingTime = mobileWizardIdleTime) {
                item = itemToIdle;
            });

+       getCoolFrameWindow().then((win) => {
+           console.assert(!win.app.socket._sleepDoneFn, '_sleepDoneFn already set!');
+           win.app.socket._sleepDoneFn = fastWaitCallback;
+       });
        cy.waitUntil(function() {
-           cy.wait(waitOnce, { log: false });
+           fastWait(fastWaitCallback, waitOnce, waitingTime - idleSince);

-           return cy.contains(selector, content, { log: false })
+           return isDone || cy.contains(selector, content, { log: false })
                .then(function(itemToIdle) {
                    if (Cypress.dom.isDetached(item[0])) {
                        cy.log('Item was detached after ' + (idleSince + waitOnce).toString() + ' ms.');
@@ -879,9 +908,9 @@ function waitUntilIdle(selector, content, waitingTime = mobileWizardIdleTime) {
            });

        cy.waitUntil(function() {
-           cy.wait(waitOnce, { log: false });
+           fastWait(fastWaitCallback, waitOnce, waitingTime - idleSince);

-           return cy.get(selector, { log: false })
+           return isDone || cy.get(selector, { log: false })
                .then(function(itemToIdle) {
                    if (Cypress.dom.isDetached(item[0])) {
                        cy.log('Item was detached after ' + (idleSince + waitOnce).toString() + ' ms.');
diff --git a/cypress_test/support/index.js b/cypress_test/support/index.js
index 340b984ed..21f36f6b9 100644
--- a/cypress_test/support/index.js
+++ b/cypress_test/support/index.js
@@ -13,7 +13,7 @@ if (Cypress.env('INTEGRATION') === 'php-proxy') {
    });
 }

-var COMMAND_DELAY = 1000;
+var COMMAND_DELAY = 0; // 1000;

 if (Cypress.browser.isHeaded) {
    Cypress.Commands.overwrite('get', function(originalFn, selector, options) {
diff --git a/kit/Kit.cpp b/kit/Kit.cpp
index b7efdf433..bde538e1b 100644
--- a/kit/Kit.cpp
+++ b/kit/Kit.cpp
@@ -124,6 +124,11 @@ static Document *singletonDocument = nullptr;
 /// flush sockets with a 'processtoidle' -> 'idle' reply.
 static std::chrono::steady_clock::time_point ProcessToIdleDeadline;

+/// A stamp we return to inform the other end that we processed
+/// all messages up to this serial, to allow them to pair a
+/// "processtoidle" with the correct "idle" reply.
+static uint32_t ProcessToIdleSerial;
+
 #ifndef BUILDING_TESTS
 static bool AnonymizeUserData = false;
 static uint64_t AnonymizationSalt = 82589933;
@@ -1560,7 +1565,7 @@ public:
             return; // more to do
         }

-        sendTextFrame("idle");
+        sendTextFrame("idle: serial=" + std::to_string(ProcessToIdleSerial));

         // get rid of idle check for now.
         ProcessToIdleDeadline = std::chrono::steady_clock::now() - std::chrono::milliseconds(10);
@@ -1605,9 +1610,11 @@ public:
                 else if (tokens.equals(0, "processtoidle"))
                 {
                     ProcessToIdleDeadline = std::chrono::steady_clock::now();
-                    uint32_t timeoutUs = 0;
-                    if (tokens.getUInt32(1, "timeout", timeoutUs))
-                        ProcessToIdleDeadline += std::chrono::microseconds(timeoutUs);
+                    uint32_t val = 0;
+                    if (tokens.getUInt32(1, "timeout", val))
+                        ProcessToIdleDeadline += std::chrono::microseconds(val);
+                    if (tokens.getUInt32(1, "serial", val))
+                        ProcessToIdleSerial = val;
                 }
                 else if (tokens.equals(0, "callback"))
                 {
diff --git a/wsd/ClientSession.cpp b/wsd/ClientSession.cpp
index eb6f7bc10..83b894d4f 100644
--- a/wsd/ClientSession.cpp
+++ b/wsd/ClientSession.cpp
@@ -959,6 +959,7 @@ bool ClientSession::_handleInput(const char *buffer, int length)
              tokens.equals(0, "getchildid") ||
              tokens.equals(0, "gettextselection") ||
              tokens.equals(0, "paste") ||
+             tokens.equals(0, "processtoidle") ||
              tokens.equals(0, "insertfile") ||
              tokens.equals(0, "key") ||
              tokens.equals(0, "textinput") ||

[mmeeks]

Hi Tor - patch looks sensible; any joy if we reduce the COMMAND_DELAY to say 10ms instead of 1000 ? perhaps we need some time to make progress in the browser. Also - I suggest running this with SAL_LOG for the scheduler - and see what is running there. I expect the cursor blinking timeout needs disabling in LOK mode - and (quite possibly) causes a lot of un-necessary wake-ups left and right (which would be good to do separately).

Thanks!