core: add timeout to all protocol commands #6347

connorjclark · 2018-10-19T21:30:46Z

connorjclark · 2018-10-19T21:32:53Z

lighthouse-core/gather/driver.js

-        }
-
-        const value = response.result.value;
+  async _evaluateInContext(expression, contextId) {


VSCode suggested this could be async, so I let it :) Thoughts on changing asynchronous syntax? FWIW, V8 just improved the performance of await to match Promises.

Thoughts on changing asynchronous syntax?

Totally fine. Since we adopted Node 8 as the base requirement we've mostly just followed the rule of only changing from Promises to async/await when we're touching the code for some other reason (see initial discussion in #3742), but to convert (or not) at will if that's the case.

We have some tricky uses of promises (see #6343 :) that need real review, which mass changes make difficult, especially since the indentation level changes and the git diffs end up not always the best, even when ignoring whitespace. We (I?) also end up using git blame a lot, and random changes in unrelated PRs make that annoying :)

It's definitely a fuzzy line, though, and sometimes drive by fixes are great.

(This case is totally different, though, because it's fundamentally changing anyways, so it's a prime candidate for fixing.)

patrickhulce

so simple and clean I love it nice work!

I am slightly worried about the commands that are going to come out of the woodwork failing though. I would want to trying running LH on some crappier hardware on some gnarly URLs (@paulirish has a ton of phones :)) and find the longest commands we have right now.

patrickhulce · 2018-10-19T22:30:15Z

lighthouse-core/gather/driver.js

-      });
-    });
+    // Encoding issues may lead to hanging getResponseBody calls: https://github.com/GoogleChrome/lighthouse/pull/4718
+    // driver.sendCommand will handle timeout after 5s.


Can we keep this at 1s? expanding to 5 could dramatically slow down the failure case when 3 of these go wrong :/

ok, I put it back to 1s

lighthouse-core/gather/driver.js

patrickhulce · 2018-10-19T22:33:32Z

lighthouse-core/gather/driver.js

+   * @param {number} timeout
+   */
+  setProtocolTimeout(timeout) {
+    this._protocolTimeout = timeout;


I afraid we'll need to make timeout a setting on sendCommand with a global default :/

We can move to that if it's really needed. It could complicate usage quite a bit, that + the unique typing on the method, I think the best option would be this:

/** * Call protocol methods. * @template {keyof LH.CrdpCommands} C * @param {C|{method: C, timeout: number}} methodOrOpts * @param {LH.CrdpCommands[C]['paramsType']} params, * @return {Promise<LH.CrdpCommands[C]['returnType']>} */ sendCommand(methodOrOpts, ...params) { const {method, timeout} = typeof methodOrOpts === 'object' ? methodOrOpts : { method: methodOrOpts, timeout: DEFAULT_PROTOCOL_TIMEOUT } }

That way, the calling code for most use cases can remain the same.

proto/lighthouse-result.proto

connorjclark · 2018-10-19T22:57:25Z

proto/lighthouse-result.proto

+  // Used when security error prevents page load.
+  INSECURE_DOCUMENT_REQUEST = 17;
+  // Used when security error prevents page load.
+  PROTOCOL_TIMEOUT = 18;


I removed REQUEST_CONTENT_TIMEOUT ... instead of making a new enum value for PROTOCOL_TIMEOUT, could we just reuse REQUEST_CONTENT_TIMEOUT's enum (rename it)? Would that be OK for proto compat?

nope, can't rename.

But actually looks like we never exposed REQUEST_CONTENT_TIMEOUT in the proto. So I think we're OK. :)

lighthouse-core/lib/lh-error.js

brendankenny · 2018-10-19T23:02:01Z

lighthouse-core/gather/driver.js

+        clearTimeout(asyncTimeout);
+        reject(err);
+      });
+    });


maybe drop keep the promise just to the thing that has to be a promise? e.g.

return new Promise(async (resolve, reject) => { const asyncTimeout = setTimeout((_ => { const err = new LHError(LHError.errors.PROTOCOL_TIMEOUT); err.message += ` Method: ${method}`; reject(err); }), this._protocolTimeout); try { const result = await this._connection.sendCommand(method, ...params); clearTimeout(asyncTimeout); resolve(result); } catch (err) { clearTimeout(asyncTimeout); reject(err); } });

brendankenny · 2018-10-19T23:42:03Z

ok, options:

sendCommand(methodOrOpts, ...params)
call setNextProtocolTimeout(60000) right before sendCommand() and have it reset itself after that next sendCommand call
have sendCommand() have a 5s default, but have a second unboundedSendCommand() that can be called if needed (e.g. by evaluateAsync)
some kind of sneaky currying that we haven't figured out yet
wait for the typescript team to support appending to tuple types/parameters

other options? (1) worries me about exposing complexity for the 5% case that may be with us forever (see: every js API that takes as its first parameter a string, or if it's a number it acts like this, or if it's an object it's an options object, or if it's a stream it...). OTOH it is overhead when writing code, but is fairly self explanatory when reading it, and I take @hoten's point that it's basically equivalent to (2)

patrickhulce · 2018-10-20T03:22:27Z

lighthouse-core/lib/lh-error.js

+    lhrRuntimeError: true,
+  },
+
+  // Hey! When adding a new error type, update lighthouse-result.proto too.


connorjclark · 2018-10-23T16:33:46Z

@patrickhulce I'll test it out on some slower devices today.

connorjclark · 2018-10-23T22:09:10Z

Tested on an old Nexus 4 device. Didn't come across any protocol timeouts.

connorjclark · 2018-10-23T22:34:46Z

Got some timings. https://gist.github.com/Hoten/de38179b2d941b6d195c3c4383d0bd8d

Runtime.evaluate took ~9s on Nexus 4 (this command has an explicit 60s timeout). The next slowest was ~4.1s (brushing up on the 5s timeout). Everything that took longer than 1s seems related to font stuff (CSS.getComputedStyleForNode), which I think we are getting rid of soon? If not, we might consider 1) increasing the timeout for those commands or 2) instead of sending them all at once, send them in batches.

paulirish · 2018-10-23T23:08:18Z

Everything that took longer than 1s seems related to font stuff (CSS.getComputedStyleForNode)

Yup looks like it's the font-size gatherer:

lighthouse/lighthouse-core/gather/gatherers/seo/font-size.js

Lines 216 to 220 in 879141d

    
           async function fetchComputedFontSize(driver, textNode) { 
        
             try { 
        
               const {computedStyle} = await driver.sendCommand('CSS.getComputedStyleForNode', { 
        
                 nodeId: textNode.parentId, 
        
               });

I was hoping it was the fonts one that was removed this morning. but alas.

TBH I think that situation is OK. I don't really want the font-size gatherer taking >5s.

patrickhulce

LGTM!

thanks so much for jumping on that slow device timeout investigation @hoten! sorry I spaced out hearing the first half of your update 😳

patrickhulce · 2018-10-24T01:23:33Z

lighthouse-core/gather/driver.js

@@ -240,23 +248,48 @@ class Driver {
    }
  }

+  /**
+   * NOTE: This can eventually be replaced when TypeScript


Is this still true now? Maybe add a bit more to the comment then because I haven't the faintest clue how we can remove the method and the variadic types header at the top of that issue just makes me dizzy 🤣

Oh, this is referring to sendCommand. That might be the confusion...

My understanding is that the linked issue will eventually allow types such as:

type TypedArray = [string, number]; type ExtendedTypedArray = TypedArray + [string]; const value: ExtendedTypedArray = ['', 12, ''];

If so, we'd be able to type that variadic parameter as LH.CrdpCommands[C]['paramsType'] + [?{timeout: number}]

Oooooh, that makes much more sense. Move the comments down there then near that parameter? :)

patrickhulce · 2018-10-24T01:25:32Z

lighthouse-core/gather/driver.js

@@ -860,27 +878,17 @@ class Driver {
   * Return the body of the response with the given ID. Rejects if getting the
   * body times out.
   * @param {string} requestId
-   * @param {number} [timeout]
+   * @param {number} timeout


isn't this param still optional?

yeah. how do you mark optional? Are the brackets "clojure style"?

{number=} is closure style :)

brackets are jsdoc

paulirish

This looks great. Nice job handling some really core driver internals. :D

paulirish · 2018-10-24T01:34:28Z

proto/lighthouse-result.proto

+  // Used when security error prevents page load.
+  INSECURE_DOCUMENT_REQUEST = 17;
+  // Used when security error prevents page load.
+  PROTOCOL_TIMEOUT = 18;


nope, can't rename.

But actually looks like we never exposed REQUEST_CONTENT_TIMEOUT in the proto. So I think we're OK. :)

paulirish · 2018-10-24T20:43:50Z

@hoten proto conflict for ya

connorjclark · 2018-10-24T22:01:07Z

@paulirish resolved

brendankenny · 2018-10-24T23:02:26Z

Yup looks like it's the font-size gatherer

That gatherer sends all those CSS.getComputedStyleForNode commands at once, up to 500, depending on the page's node count. It's possible command overhead/contention causes issues, especially on an older phone. We could try doing them in batches instead of all at once to see if that's a solution.

It's also remotely possible we hit some gross style-recalc issue, depending on the page and how the commands are coming in. It's possible it would be more efficient to do all the lookups in the page at once with evaluateAsync, since we could guarantee running them all in the same turn of the event loop/without reforcing layout. We'd have to resync node info and debugger nodeIds, though. Maybe there's a similar coalesced solution, though.

core: add timeout to all protocol commands (#6296)

fafc315

connorjclark requested review from brendankenny, exterkamp, patrickhulce and paulirish as code owners October 19, 2018 21:30

connorjclark commented Oct 19, 2018

View reviewed changes

connorjclark changed the title ~~core: add timeout to all protocol commands (#6296)~~ core: add timeout to all protocol commands Oct 19, 2018

patrickhulce suggested changes Oct 19, 2018

View reviewed changes

connorjclark commented Oct 19, 2018

View reviewed changes

brendankenny reviewed Oct 19, 2018

View reviewed changes

setNextProtocolTimeout, lhRuntimeError

0e70d6f

patrickhulce reviewed Oct 20, 2018

View reviewed changes

patrickhulce approved these changes Oct 24, 2018

View reviewed changes

paulirish approved these changes Oct 24, 2018

View reviewed changes

getRequestContent 1s

368f722

connorjclark force-pushed the issue-6296-protocol-timeout branch from 18e9b9b to 368f722 Compare October 24, 2018 18:37

mark timeout param as optional

3e9c538

Merge branch 'master' into issue-6296-protocol-timeout

417f0af

paulirish merged commit 9f15c6c into master Oct 24, 2018

paulirish deleted the issue-6296-protocol-timeout branch October 24, 2018 22:13

paulirish mentioned this pull request Oct 24, 2018

Speed up the slow font-size gatherer #6386

Closed

exterkamp mentioned this pull request Dec 6, 2018

core(driver): handle promise rejections from sendCommand #6739

Merged

brendankenny mentioned this pull request Mar 15, 2019

core(oopif): autoattach to all descendants #7517

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

core: add timeout to all protocol commands #6347

core: add timeout to all protocol commands #6347

connorjclark commented Oct 19, 2018

connorjclark Oct 19, 2018

brendankenny Oct 19, 2018

brendankenny Oct 19, 2018

patrickhulce left a comment

patrickhulce Oct 19, 2018

connorjclark Oct 20, 2018

patrickhulce Oct 19, 2018

connorjclark Oct 19, 2018 •

edited

Loading

connorjclark Oct 19, 2018 •

edited

Loading

paulirish Oct 24, 2018

brendankenny Oct 19, 2018

brendankenny commented Oct 19, 2018 •

edited

Loading

patrickhulce Oct 20, 2018

connorjclark commented Oct 23, 2018

connorjclark commented Oct 23, 2018

connorjclark commented Oct 23, 2018

paulirish commented Oct 23, 2018

patrickhulce left a comment

patrickhulce Oct 24, 2018

connorjclark Oct 24, 2018 •

edited

Loading

patrickhulce Oct 24, 2018

patrickhulce Oct 24, 2018

connorjclark Oct 24, 2018

patrickhulce Oct 24, 2018

paulirish left a comment

paulirish Oct 24, 2018

paulirish commented Oct 24, 2018

connorjclark commented Oct 24, 2018

brendankenny commented Oct 24, 2018

core: add timeout to all protocol commands #6347

core: add timeout to all protocol commands #6347

Conversation

connorjclark commented Oct 19, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

patrickhulce left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

connorjclark Oct 19, 2018 • edited Loading

Choose a reason for hiding this comment

connorjclark Oct 19, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

brendankenny commented Oct 19, 2018 • edited Loading

Choose a reason for hiding this comment

connorjclark commented Oct 23, 2018

connorjclark commented Oct 23, 2018

connorjclark commented Oct 23, 2018

paulirish commented Oct 23, 2018

patrickhulce left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

connorjclark Oct 24, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

paulirish left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

paulirish commented Oct 24, 2018

connorjclark commented Oct 24, 2018

brendankenny commented Oct 24, 2018

connorjclark Oct 19, 2018 •

edited

Loading

connorjclark Oct 19, 2018 •

edited

Loading

brendankenny commented Oct 19, 2018 •

edited

Loading

connorjclark Oct 24, 2018 •

edited

Loading