Fix performance interface timing member #25205

shnmorimoto · 2019-12-07T17:40:50Z

./mach build -d does not report any errors
./mach test-tidy does not report any errors
These changes fix #23330 and #24468 (GitHub issue number if applicable)

There are tests for these changes

highfive · 2019-12-07T17:40:55Z

Heads up! This PR modifies the following files:

@asajeffrey: components/script/dom/performance.rs, components/script/network_listener.rs, components/script/script_thread.rs, components/script/dom/servoparser/mod.rs, components/script/dom/webidls/Performance.webidl
@KiChjang: components/script/dom/performance.rs, components/script/network_listener.rs, components/script/script_thread.rs, components/script/dom/servoparser/mod.rs, components/script/dom/webidls/Performance.webidl

shnmorimoto · 2019-12-08T13:31:47Z

When I run ./mach run https://www.google.com , I get a crash.

> ./mach run https://www.google.com                                                                                                                                    fix_performance_interface_timing_member ✱
[2019-12-08T07:06:36Z ERROR script::dom::bindings::error] Error at https://www.google.com/:345:1419 document.f.q is undefined
internal error: entered unreachable code: Are we trying to expose Performance.timing in workers? (thread ScriptThread PipelineId { namespace_id: PipelineNamespaceId(1), index: PipelineIndex(1) }, at components/script/dom/
performance.rs:394)
stack backtrace:
   0: backtrace::backtrace::trace_unsynchronized
   1: <servo::backtrace::Print as core::fmt::Debug>::fmt
   2: core::fmt::write
   3: <std::io::stdio::Stdout as std::io::Write>::write_fmt
   4: std::io::stdio::_print
   5: servo::backtrace::print
   6: servo::main::{{closure}}
   7: std::panicking::rust_panic_with_hook
   8: rust_begin_unwind
   9: std::panicking::begin_panic_fmt
  10: <script::dom::performance::Performance as script::dom::bindings::codegen::Bindings::PerformanceBinding::PerformanceBinding::PerformanceMethods>::Timing
  11: script::dom::bindings::codegen::Bindings::PerformanceBinding::PerformanceBinding::get_timing::{{closure}}
  12: core::ops::function::FnOnce::call_once
  13: <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
  14: std::panicking::try::do_call
  15: __rust_maybe_catch_panic
  16: std::panicking::try
  17: std::panic::catch_unwind
  18: mozjs::panic::wrap_panic
  19: script::dom::bindings::codegen::Bindings::PerformanceBinding::PerformanceBinding::get_timing
  20: CallJitGetterOp
  21: script::dom::bindings::utils::generic_call
  22: script::dom::bindings::utils::generic_getter
  23: _ZN2js23InternalCallOrConstructEP9JSContextRKN2JS8CallArgsENS_14MaybeConstructE
  24: _ZN2js10CallGetterEP9JSContextN2JS6HandleINS2_5ValueEEES5_NS2_13MutableHandleIS4_EE
  25: _ZN2js17NativeGetPropertyEP9JSContextN2JS6HandleIPNS_12NativeObjectEEENS3_INS2_5ValueEEENS3_INS2_11PropertyKeyEEENS2_13MutableHandleIS7_EE
  26: _ZN2js3jit17DoGetElemFallbackEP9JSContextPNS0_13BaselineFrameEPNS0_18ICGetElem_FallbackEN2JS6HandleINS7_5ValueEEESA_NS7_13MutableHandleIS9_EE

[2019-12-08T07:06:38Z ERROR servo] internal error: entered unreachable code: Are we trying to expose Performance.timing in workers?

I'm trying to find out the cause of this error.

shnmorimoto · 2019-12-09T15:13:07Z

@jdm
I inserted debug log like this.

impl PerformanceMethods for Performance {
    // FIXME(avada): this should be deprecated in the future, but some sites still use it
    // https://dvcs.w3.org/hg/webperf/raw-file/tip/specs/NavigationTiming/Overview.html#performance-timing-attribute
    fn Timing(&self) -> DomRoot<PerformanceNavigationTiming> {
        debug!("#25205 call Timing function");
        let entries = self.GetEntriesByType(DOMString::from("navigation"));
 ....

And, I investigated when each function was called.

[2019-12-09T15:01:15Z DEBUG script::dom::servoparser] #25205 call process_response func
[2019-12-09T15:01:15Z DEBUG script::dom::servoparser] #25205 call submit_resource_timing func
[2019-12-09T15:01:16Z DEBUG script::dom::performance] #25205 call Timing function
[2019-12-09T15:01:20Z DEBUG script::dom::servoparser] #25205 call process_response_eof func
[2019-12-09T15:01:20Z DEBUG script::dom::performance] #25205 call update_entry function
[2019-12-09T15:01:21Z DEBUG script::dom::performance] #25205 call Timing function
[2019-12-09T15:01:21Z DEBUG script::dom::performance] #25205 call Timing function
internal error: entered unreachable code: Are we trying to expose Performance.timing in workers? (thread ScriptThread PipelineId { namespace_id: PipelineNamespaceId(1), index: PipelineIndex(1) }, at components/script/dom/performance.rs:396)
[2019-12-09T15:01:21Z ERROR servo] internal error: entered unreachable code: Are we trying to expose Performance.timing in workers?
[2019-12-09T15:01:22Z DEBUG constellation::constellation] Sending log entry Panic("internal error: entered unreachable code: Are we trying to expose Performance.timing in workers?", "stack backtrace:\n   0: backtrace::backtrace::trace_unsynchronized\n   1: backtrace::backtrace::trace\n   2: backtrace::capture::Backtrace::create\n   3: backtrace::capture::Backtrace::new\n   4: constellation::constellation::log_entry\n   5: <constellation::constellation::FromCompositorLogger as log::Log>::log\n   6: <servo::BothLogger<Log1,Log2> as log::Log>::log\n   7: log::__private_api_log\n   8: servo::main::{{closure}}\n   9: std::panicking::rust_panic_with_hook\n  10: rust_begin_unwind\n  11: std::panicking::begin_panic_fmt\n  12: <script::dom::performance::Performance as script::dom::bindings::codegen::Bindings::PerformanceBinding::PerformanceBinding::PerformanceMethods>::Timing\n  13: script::dom::bindings::codegen::Bindings::PerformanceBinding::PerformanceBinding::get_timing::{{closure}}\n  14: core::ops::function::FnOnce::call_once\n  15: <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once\n  16: std::panicking::try::do_call\n  17: __rust_maybe_catch_panic\n  18: std::panicking::try\n  19: std::panic::catch_unwind\n  20: mozjs::panic::wrap_panic\n  21: script::dom::bindings::codegen::Bindings::PerformanceBinding::PerformanceBinding::get_timing\n  22: CallJitGetterOp\n  23: script::dom::bindings::utils::generic_call\n  24: script::dom::bindings::utils::generic_getter\n  25: _ZN2js23InternalCallOrConstructEP9JSContextRKN2JS8CallArgsENS_14MaybeConstructE\n  26: _ZN2js10CallGetterEP9JSContextN2JS6HandleINS2_5ValueEEES5_NS2_13MutableHandleIS4_EE\n  27: _ZN2js17NativeGetPropertyEP9JSContextN2JS6HandleIPNS_12NativeObjectEEENS3_INS2_5ValueEEENS3_INS2_11PropertyKeyEEENS2_13MutableHandleIS7_EE\n  28: _ZN2js3jit17DoGetElemFallbackEP9JSContextPNS0_13BaselineFrameEPNS0_18ICGetElem_FallbackEN2JS6HandleINS7_5ValueEEESA_NS7_13MutableHandleIS9_EE\n").
[2019-12-09T15:01:22Z DEBUG constellation::constellation] Received log entry Panic("internal error: entered unreachable code: Are we trying to expose Performance.timing in workers?", "stack backtrace:\n   0: backtrace::backtrace::trace_unsynchronized\n   1: backtrace::backtrace::trace\n   2: backtrace::capture::Backtrace::create\n   3: backtrace::capture::Backtrace::new\n   4: constellation::constellation::log_entry\n   5: <constellation::constellation::FromCompositorLogger as log::Log>::log\n   6: <servo::BothLogger<Log1,Log2> as log::Log>::log\n   7: log::__private_api_log\n   8: servo::main::{{closure}}\n   9: std::panicking::rust_panic_with_hook\n  10: rust_begin_unwind\n  11: std::panicking::begin_panic_fmt\n  12: <script::dom::performance::Performance as script::dom::bindings::codegen::Bindings::PerformanceBinding::PerformanceBinding::PerformanceMethods>::Timing\n  13: script::dom::bindings::codegen::Bindings::PerformanceBinding::PerformanceBinding::get_timing::{{closure}}\n  14: core::ops::function::FnOnce::call_once\n  15: <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once\n  16: std::panicking::try::do_call\n  17: __rust_maybe_catch_panic\n  18: std::panicking::try\n  19: std::panic::catch_unwind\n  20: mozjs::panic::wrap_panic\n  21: script::dom::bindings::codegen::Bindings::PerformanceBinding::PerformanceBinding::get_timing\n  22: CallJitGetterOp\n  23: script::dom::bindings::utils::generic_call\n  24: script::dom::bindings::utils::generic_getter\n  25: _ZN2js23InternalCallOrConstructEP9JSContextRKN2JS8CallArgsENS_14MaybeConstructE\n  26: _ZN2js10CallGetterEP9JSContextN2JS6HandleINS2_5ValueEEES5_NS2_13MutableHandleIS4_EE\n  27: _ZN2js17NativeGetPropertyEP9JSContextN2JS6HandleIPNS_12NativeObjectEEENS3_INS2_5ValueEEENS3_INS2_11PropertyKeyEEENS2_13MutableHandleIS7_EE\n  28: _ZN2js3jit17DoGetElemFallbackEP9JSContextPNS0_13BaselineFrameEPNS0_18ICGetElem_FallbackEN2JS6HandleINS7_5ValueEEESA_NS7_13MutableHandleIS9_EE\n").
[2019-12-09T15:01:22Z DEBUG constellation::constellation] Panic handler for top-level browsing context (0,1): internal error: entered unreachable code: Are we trying to expose Performance.timing in workers?.
[2019-12-09T15:01:22Z DEBUG script::dom::servoparser] #25205 call process_response func
[2019-12-09T15:01:22Z DEBUG script::dom::servoparser] #25205 call submit_resource_timing func
[2019-12-09T15:01:22Z DEBUG script::dom::servoparser] #25205 call process_response_eof func
[2019-12-09T15:01:22Z DEBUG script::dom::performance] #25205 call update_entry function

From the above results, it seems that there is a timing when Timing func is called earlier than process_response func.

Is there a way to investigate the cause of the problem?

jdm · 2019-12-09T15:58:09Z

Yes, this is #24468. I believe I have described the solution I have in mind that in that issue; let me know if it is unclear at all!

jdm · 2019-12-09T15:58:48Z

Oh, sorry, I didn't read your last message closely enough. I'll try and figure out what to do.

jdm · 2019-12-09T16:14:30Z

@shnmorimoto Do either of the following trigger the problem?

<iframe src="javascript:console.log(performance.timing)"></iframe>

<iframe srcdoc="<script>console.log(performance.timing)</script>"></iframe>

shnmorimoto · 2019-12-10T12:21:03Z

@jdm Thanks! Neither way caused problems.
This is the html used for the test.

<!DOCTYPE html>
<html>
<head>
<title>iframe 1</title>
</head>
<body>

Hello World.
<iframe src="javascript:console.log(performance.timing)"></iframe>

</body>
</html>

<!DOCTYPE html>
<html>
<head>
<title>iframe 2</title>
</head>
<body>

Hello World.

<iframe srcdoc="<script>console.log(performance.timing)</script>"></iframe>

</body>
</html>

jdm · 2019-12-10T16:16:20Z

@shnmorimoto I ended up using a debugger to figure out what was going on - I set a breakpoint in Performance::queue_entry and watched as self->buffer grew over time, then suddenly was empty. Looking at the code that modifies self.buffer, I realized that clear_entries_by_name_and_type has a bug - it is modeled after get_entries_by_name_and_type, so it ends up keeping any entries that match the name/type being cleared and throwing away any non-matching ones, which is the opposite behaviour from what we want. Fixing that bug should fix the google.com problem.

shnmorimoto · 2019-12-11T12:03:34Z

@jdm Thank you for finding the cause and explaining how to way to find out.
I will try it when the same thing happens next time.

I understand the cause. I'll try to fix it.

shnmorimoto · 2019-12-11T13:47:12Z

I've fixed the clear_entries_by_name_and_type bug and confirmed that the google.com problem is resolved.

components/script/dom/performance.rs

jdm · 2019-12-11T15:32:57Z

@bors-servo try=wpt

bors-servo · 2019-12-11T15:33:03Z

⌛ Trying commit aba4f0e with merge 9a60282...


        Auto merge of #25205 - shnmorimoto:fix_performance_interface_timing_m…

…ember, r=<try> Fix performance interface timing member  ---  - [x] `./mach build -d` does not report any errors - [x] `./mach test-tidy` does not report any errors - [x] These changes fix #23330 and #24468 (GitHub issue number if applicable)  - [x] There are tests for these changes

bors-servo · 2019-12-11T16:13:28Z

💔 Test failed - status-taskcluster

jdm · 2019-12-13T20:35:05Z

@bors-servo r+

bors-servo · 2019-12-13T20:35:06Z

📌 Commit 9b153ac has been approved by jdm

bors-servo · 2019-12-13T20:35:11Z

⌛ Testing commit 9b153ac with merge f811bfa...


        Auto merge of #25205 - shnmorimoto:fix_performance_interface_timing_m…

…ember, r=jdm Fix performance interface timing member  ---  - [x] `./mach build -d` does not report any errors - [x] `./mach test-tidy` does not report any errors - [x] These changes fix #23330 and #24468 (GitHub issue number if applicable)  - [x] There are tests for these changes

bors-servo · 2019-12-13T21:20:59Z

💔 Test failed - status-taskcluster

jdm · 2019-12-13T21:24:29Z

@bors-servo retry

#24762

bors-servo · 2019-12-13T21:58:12Z

⌛ Testing commit 9b153ac with merge 483f907...


        Auto merge of #25205 - shnmorimoto:fix_performance_interface_timing_m…

…ember, r=jdm Fix performance interface timing member  ---  - [x] `./mach build -d` does not report any errors - [x] `./mach test-tidy` does not report any errors - [x] These changes fix #23330 and #24468 (GitHub issue number if applicable)  - [x] There are tests for these changes

bors-servo · 2019-12-13T22:10:35Z

💔 Test failed - status-taskcluster

jdm · 2019-12-14T15:32:19Z

@bors-servo retry

#25296 #24622

bors-servo · 2019-12-14T15:42:18Z

⌛ Testing commit 9b153ac with merge 226b341...


        Auto merge of #25205 - shnmorimoto:fix_performance_interface_timing_m…

…ember, r=jdm Fix performance interface timing member  ---  - [x] `./mach build -d` does not report any errors - [x] `./mach test-tidy` does not report any errors - [x] These changes fix #23330 and #24468 (GitHub issue number if applicable)  - [x] There are tests for these changes

bors-servo · 2019-12-14T16:54:26Z

☀️ Test successful - status-taskcluster
Approved by: jdm
Pushing 226b341 to master...

highfive assigned SimonSapin Dec 7, 2019

highfive added the S-awaiting-review label Dec 7, 2019

jdm assigned jdm and unassigned SimonSapin Dec 9, 2019

jdm added S-needs-code-changes and removed S-awaiting-review labels Dec 10, 2019

shnmorimoto force-pushed the shnmorimoto:fix_performance_interface_timing_member branch from 2e91f26 to b0cabb7 Dec 11, 2019

highfive added S-awaiting-review and removed S-needs-code-changes labels Dec 11, 2019

jdm requested changes Dec 11, 2019

View changes

components/script/dom/performance.rs Outdated Show resolved Hide resolved

jdm added S-needs-code-changes and removed S-awaiting-review labels Dec 11, 2019

shnmorimoto force-pushed the shnmorimoto:fix_performance_interface_timing_member branch from b0cabb7 to aba4f0e Dec 11, 2019

highfive added S-awaiting-review and removed S-needs-code-changes labels Dec 11, 2019

highfive added the S-tests-failed label Dec 11, 2019

highfive added S-awaiting-review and removed S-tests-failed labels Dec 13, 2019

highfive added S-awaiting-merge and removed S-awaiting-review labels Dec 13, 2019

highfive added S-tests-failed and removed S-awaiting-merge labels Dec 13, 2019

highfive added S-awaiting-merge and removed S-tests-failed labels Dec 13, 2019

highfive added S-tests-failed and removed S-awaiting-merge labels Dec 13, 2019

highfive added S-awaiting-merge and removed S-tests-failed labels Dec 14, 2019

bors-servo merged commit 9b153ac into servo:master Dec 14, 2019
2 checks passed

2 checks passed

Community-TC (pull_request) TaskGroup: success
Details

homu Test successful
Details

highfive removed the S-awaiting-merge label Dec 14, 2019

bors-servo mentioned this pull request Dec 14, 2019

Performance interface's timing member as an attribute change #24466

Closed

4 of 5 tasks complete

CYBAI mentioned this pull request Dec 14, 2019

Resource fetch timing information is stored too late during document navigation #24468

Closed

atouchet added this to Done in PanoMoments Feb 23, 2020

servo / servo

Fix performance interface timing member #25205

Fix performance interface timing member #25205

shnmorimoto commented Dec 7, 2019

highfive commented Dec 7, 2019

shnmorimoto commented Dec 8, 2019

shnmorimoto commented Dec 9, 2019

jdm commented Dec 9, 2019

jdm commented Dec 9, 2019

jdm commented Dec 9, 2019 •

edited

shnmorimoto commented Dec 10, 2019

jdm commented Dec 10, 2019

shnmorimoto commented Dec 11, 2019

shnmorimoto commented Dec 11, 2019

jdm commented Dec 11, 2019

bors-servo commented Dec 11, 2019

bors-servo commented Dec 11, 2019

jdm commented Dec 13, 2019

bors-servo commented Dec 13, 2019

bors-servo commented Dec 13, 2019

bors-servo commented Dec 13, 2019

jdm commented Dec 13, 2019

bors-servo commented Dec 13, 2019

bors-servo commented Dec 13, 2019

jdm commented Dec 14, 2019

bors-servo commented Dec 14, 2019

bors-servo commented Dec 14, 2019

servo / servo

Join GitHub today

Fix performance interface timing member #25205

Fix performance interface timing member #25205

Conversation

shnmorimoto commented Dec 7, 2019

highfive commented Dec 7, 2019

shnmorimoto commented Dec 8, 2019

shnmorimoto commented Dec 9, 2019

jdm commented Dec 9, 2019

jdm commented Dec 9, 2019

jdm commented Dec 9, 2019 • edited

shnmorimoto commented Dec 10, 2019

jdm commented Dec 10, 2019

shnmorimoto commented Dec 11, 2019

shnmorimoto commented Dec 11, 2019

jdm commented Dec 11, 2019

bors-servo commented Dec 11, 2019

bors-servo commented Dec 11, 2019

jdm commented Dec 13, 2019

bors-servo commented Dec 13, 2019

bors-servo commented Dec 13, 2019

bors-servo commented Dec 13, 2019

jdm commented Dec 13, 2019

bors-servo commented Dec 13, 2019

bors-servo commented Dec 13, 2019

jdm commented Dec 14, 2019

bors-servo commented Dec 14, 2019

bors-servo commented Dec 14, 2019

jdm commented Dec 9, 2019 •

edited