Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Update user timing to record the timeout deadline with 'waiting' events #12479

Conversation

flarnie
Copy link
Contributor

@flarnie flarnie commented Mar 28, 2018

what is the change?:
When we are processing work during reconciliation, we have a "timeout"
deadline to finish the work. It's a safety measure that forces things to
finish up synchronously if they are taking too long.

The "timeout" is different depending on the type of interaction which
triggered the reconciliation. We currently have a shorter "timeout" for
"interactive updates", meaning we will try to finish work faster if the
reconciliation was triggered by a click or other user interaction.

For collecting more data in our logs we want to differentiate the
'waiting for async callback...' events based on the "timeout" so I'm
adding that to the logging.

One interesting note - in one of the snapshot tests the "timeout" was
super high.
screen shot 2018-03-28 at 3 36 41 pm
Weird? Going to look into that.

why make this change?:
Right now we are debugging cases where an interaction triggers a
reconciliation and the "waiting for async callback...' events are too
long, getting blocked because the main thread is too busy. We are
keeping logs of these user timing events and want to filter to focus on
the reconciliation triggered by interaction.

test plan:
Manually tested and also updated snapshot tests.

screen shot 2018-03-28 at 3 19 34 pm

**what is the change?:**
When we are processing work during reconciliation, we have a "timeout"
deadline to finish the work. It's a safety measure that forces things to
finish up synchronously if they are taking too long.

The "timeout" is different depending on the type of interaction which
triggered the reconciliation. We currently have a shorter "timeout" for
"interactive updates", meaning we will try to finish work faster if the
reconciliation was triggered by a click or other user interaction.

For collecting more data in our logs we want to differentiate the
'waiting for async callback...' events based on the "timeout" so I'm
adding that to the logging.

One interesting note - in one of the snapshot tests the "timeout" was
super high. Going to look into that.

**why make this change?:**
Right now we are debugging cases where an interaction triggers a
reconciliation and the "waiting for async callback...' events are too
long, getting blocked because the main thread is too busy. We are
keeping logs of these user timing events and want to filter to focus on
the reconciliation triggered by interaction.

**test plan:**
Manually tested and also updated snapshot tests.

(Flarnie will insert a screenshot)
@@ -218,7 +218,7 @@ exports[`ReactDebugFiberPerf measures deprioritized work 1`] = `
⚛ (Committing Host Effects: 1 Total)
⚛ (Calling Lifecycle Methods: 0 Total)

⚛ (Waiting for async callback...)
⚛ (Waiting for async callback... timeout is 10737418210)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is probably because <div hidden> doesn't ever expire.

@@ -1,7 +1,7 @@
// Jest Snapshot v1, https://goo.gl/fbAQLP

exports[`ReactDebugFiberPerf captures all lifecycles 1`] = `
"⚛ (Waiting for async callback...)
"⚛ (Waiting for async callback... timeout is 5230)
Copy link
Collaborator

@gaearon gaearon Mar 28, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Maybe we can make it clearer what this number means?

e.g. (Waiting for async callback... will force flush in 5320 ms)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I like that! Will fix.

@flarnie flarnie merged commit 125dd16 into facebook:master Mar 29, 2018
rhagigi pushed a commit to rhagigi/react that referenced this pull request Apr 19, 2018
…ts (facebook#12479)

* Update user timing to record the timeout deadline with 'waiting' events

**what is the change?:**
When we are processing work during reconciliation, we have a "timeout"
deadline to finish the work. It's a safety measure that forces things to
finish up synchronously if they are taking too long.

The "timeout" is different depending on the type of interaction which
triggered the reconciliation. We currently have a shorter "timeout" for
"interactive updates", meaning we will try to finish work faster if the
reconciliation was triggered by a click or other user interaction.

For collecting more data in our logs we want to differentiate the
'waiting for async callback...' events based on the "timeout" so I'm
adding that to the logging.

One interesting note - in one of the snapshot tests the "timeout" was
super high. Going to look into that.

**why make this change?:**
Right now we are debugging cases where an interaction triggers a
reconciliation and the "waiting for async callback...' events are too
long, getting blocked because the main thread is too busy. We are
keeping logs of these user timing events and want to filter to focus on
the reconciliation triggered by interaction.

**test plan:**
Manually tested and also updated snapshot tests.

(Flarnie will insert a screenshot)

* Improve wording of message

* ran prettier
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

3 participants