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

Reddit.com doesn't load completely within browser.html #11223

Closed
paulrouget opened this issue May 17, 2016 · 49 comments
Closed

Reddit.com doesn't load completely within browser.html #11223

paulrouget opened this issue May 17, 2016 · 49 comments
Assignees

Comments

@paulrouget
Copy link
Contributor

@paulrouget paulrouget commented May 17, 2016

Duplicate of browserhtml/browserhtml#1037 as this is apparently a servo bug.

Often the mozbrowser iframe doesn't get the loadend event when loading reddit.com.

It appears to happen only with browserhtml.

This is what I managed to figure out so far:

  • In document.rs, in finish_load, for the reddit.com pipeline, DocumentLoadsComplete is properly sent. Which means that loader.is_blocked() return false.
  • then, in script_thread.rs, in handle_loads_complete, doc.loader().is_blocked() returns true, preventing finishing the load.

So I guess we need to figure out why sometimes the loader gets blocked.

@paulrouget
Copy link
Contributor Author

@paulrouget paulrouget commented May 17, 2016

Just to confirm, the loaders we are talking about in finish_load and in handle_loads_complete (which comes after), are both the same (same pipeline).

@paulrouget
Copy link
Contributor Author

@paulrouget paulrouget commented May 17, 2016

This script is added:

https://engine.a.redditmedia.com/ados?t=1463476273520&request={%22Placements%22:[{%22A%22:5146,%22S%22:24950,%22D%22:%22main%22,%22AT%22:5,%22Properties%22:{}},{%22A%22:5146,%22S%22:24950,%22D%22:%22sponsorship%22,%22AT%22:8,%22Properties%22:{}}],%22Keywords%22:%22s.frontpage%2Cs.loggedout%2Cs.sfw%22,%22Referrer%22:%22undefined%22,%22IsAsync%22:true,%22WriteResults%22:true}

… and never removed from the loader list.

@paulrouget
Copy link
Contributor Author

@paulrouget paulrouget commented May 17, 2016

So we never get the headers for this script. So I guess it's a network issue.

@paulrouget
Copy link
Contributor Author

@paulrouget paulrouget commented May 17, 2016

I'm wondering if I'm hitting the ssl issue of #11008

I'm not getting headers (at least, headers_available is not called in htmlscriptelement.rs) but still, this script is added to the loader. Any idea what else I could look at?

@tschneidereit
Copy link
Contributor

@tschneidereit tschneidereit commented May 17, 2016

This seems to only happen on slower machines, or with fewer CPU cores: on a 2012 MBP with 4 (physical) cores, I can't reproduce at all, whereas on a 2015 Macbook with 2 cores, it happens reliably.

@metajack
Copy link
Contributor

@metajack metajack commented May 17, 2016

@tschneidereit have you tried rr's random scheduler?

@nox This might be a good bug to take.

@nox
Copy link
Member

@nox nox commented May 17, 2016

Will look into that.

@paulrouget
Copy link
Contributor Author

@paulrouget paulrouget commented May 17, 2016

CPU usage hits ~100% while that happens.

I'll attempt to profile, that might help us understand if we get stuck somewhere.

@paulrouget
Copy link
Contributor Author

@paulrouget paulrouget commented May 17, 2016

Also - depending on time, reddit doesn't serve the same ads, so it might not happen all the time. At the moment, it sill happens, but with a different URL.

@paulrouget
Copy link
Contributor Author

@paulrouget paulrouget commented May 17, 2016

Result of the profile after the loadend got blocked: http://people.mozilla.org/~prouget/bugs/issue11223.svg (csv version: http://people.mozilla.org/~prouget/bugs/issue11223.csv).

@paulrouget
Copy link
Contributor Author

@paulrouget paulrouget commented May 17, 2016

@till / @Gozala can you guys check (or tell me how to check) why we have JS code running while the iframe is not sending event anymore?

PS: I'm disabling the progressbar like this, is that enough?

diff --git a/src/browser/web-view.js b/src/browser/web-view.js
index a20291d..5e400d0 100644
--- a/src/browser/web-view.js
+++ b/src/browser/web-view.js
@@ -810,7 +810,7 @@ export const view =
           )
         ]
       )
-    , Progress.view(model.progress, address)
+    // , Progress.view(model.progress, address)
     , html.div
       ( { className: 'webview-tab-icon'
         , style:
@paulrouget
Copy link
Contributor Author

@paulrouget paulrouget commented May 18, 2016

I think it's also necessary to remove ProgressAction(Progress.Start(time)) from startLoad to not have an JS running.

@paulrouget
Copy link
Contributor Author

@paulrouget paulrouget commented May 18, 2016

Commenting out ProgressAction(Progress.Start(time)) (code that updates the progressbar while the page is loading) in browserhtml makes the issue disappear.

Using setTimeout(16) instead of requestAnimationFrame also makes the issue disappear (we know that rAF has an overhead: #9844).

So basically, when CPU gets busy, a script might never be executed/downloaded (not sure yet) and blocks the document loader. That also explains why we can not reproduce this issue on a Macbook Pro (faster CPU).

@nox, is there anything I can do to help profiling/debugging this?

@nox
Copy link
Member

@nox nox commented May 18, 2016

@paulrouget Could we somehow list the blocking loads stored in DocumentLoader::blocking_loads?

@nox
Copy link
Member

@nox nox commented May 18, 2016

Do you think we can reproduce it on a better computer by using nice on Servo?

@nox
Copy link
Member

@nox nox commented May 18, 2016

Is the HTML sample in browserhtml/browserhtml#1037 still relevant? Seems like it happens 100% of the time when I try locally with it.

@nox
Copy link
Member

@nox nox commented May 18, 2016

Oh, not 100% of the time, but I can reproduce it on my fancy laptop at least.

@nox
Copy link
Member

@nox nox commented May 18, 2016

Actually I had just missed the end message the first few times, so I didn't notice I wasn't reproducing the never-ending load. :(

@paulrouget
Copy link
Contributor Author

@paulrouget paulrouget commented May 18, 2016

Could we somehow list the blocking loads stored in DocumentLoader::blocking_loads?

Not sure to understand the question. You want to println them?

Do you think we can reproduce it on a better computer by using nice on Servo?

I haven't tried, but I guess if you nice-up the the process or somehow manage to limit the number of available cores, that might help.

To reproduce, something "heavy" needs to happen on the side. browserhtml happens to have an expensive rAF loop. Maybe we can have a reduced test case if we re-use the example from browserhtml/browserhtml#1037 with a random busy script running at the same time.

@paulrouget
Copy link
Contributor Author

@paulrouget paulrouget commented May 18, 2016

To reproduce, something "heavy" needs to happen on the side. browserhtml happens to have an expensive rAF loop. Maybe we can have a reduced test case if we re-use the example from browserhtml/browserhtml#1037 with a random busy script running at the same time.

Just tried. Very expensive rAF. I can't reproduce outside of browserhtml.

@pcwalton
Copy link
Contributor

@pcwalton pcwalton commented May 18, 2016

@nox Mind if I assign you here?

@nox nox self-assigned this May 18, 2016
@nox
Copy link
Member

@nox nox commented May 18, 2016

@pcwalton Done.

@paulrouget
Copy link
Contributor Author

@paulrouget paulrouget commented May 19, 2016

So for the script mentioned in my 2nd comment, headers are being downloaded.

I can tell because the script go through this:

_ => target.invoke_with_listener(ResponseAction::HeadersAvailable(Ok(metadata))),
(start_sending_opt).

But I think the listener is not called. I added a println here

ResponseAction::HeadersAvailable(m) => listener.headers_available(m),
(ResponseAction::process) and I don't see anything for this specific script.

2 questions:

  1. Am I right to think that ResponseAction::process is supposed to be called after start_sending_opt?
  2. If so, that means the mechanism that call the listener doesn't work. I see that we use an IpcSender for that. So could that be an IPC issue? How do I debug that?
@paulrouget
Copy link
Contributor Author

@paulrouget paulrouget commented May 19, 2016

Ignore previous comment. I'm getting response_complete.

@paulrouget
Copy link
Contributor Author

@paulrouget paulrouget commented May 19, 2016

The script is being downloaded via http_loader. In ProgressSender::send(resource_thread.rs) eventually get the complete response. Calls invoke_with_listener (net_traits/lib.rs), which calls sender.send(action). But nothing ever happens after that.

sender is an IpcSender<>. So looking at ipc-channel, once the script is fully downloaded and sender.send(action) is called, the method IpcSender::send is called repeatedly forever.

I know nothing about IPC, but I guess that's not good.

@jdm
Copy link
Member

@jdm jdm commented May 30, 2016

Doing so leads me to https://www.redditstatic.com/ad-dependencies.5O7sMdAReBw.js but I don't know if I can trust anything about the line and column information, since Servo routinely fudges those.

@nox
Copy link
Member

@nox nox commented May 30, 2016

That file seems to be the only interesting one that adds a listener for DOMContentLoad.

@jdm
Copy link
Member

@jdm jdm commented May 30, 2016

My current theory is that we end up in an endless loop in JS, since we never return from JS::Interpret.

@jdm
Copy link
Member

@jdm jdm commented May 30, 2016

Here's a backtrace of the thread that doesn't return from the JS interpreter after killing the process:

(lldb) bt
* thread #103: tid = 0x9ef6d, 0x00007fff8e230746 libsystem_kernel.dylib`__psynch_mutexwait + 10
  * frame #0: 0x00007fff8e230746 libsystem_kernel.dylib`__psynch_mutexwait + 10
    frame #1: 0x00007fff84e38779 libsystem_pthread.dylib`_pthread_mutex_lock + 372
    frame #2: 0x0000000100dde852 servo`std::sys::mutex::{{impl}}::lock(self=0x000000011b06bb40) + 34 at mutex.rs:34
    frame #3: 0x0000000100dde825 servo`std::sys_common::mutex::{{impl}}::lock(self=0x000000011b06bb40) + 21 at mutex.rs:35
    frame #4: 0x0000000100fa3126 servo`std::sync::mutex::{{impl}}::lock<layout::layout_thread::LayoutThreadData>(self=0x000000011b091010) + 38 at mutex.rs:224
    frame #5: 0x0000000101040164 servo`layout::query::{{impl}}::offset_parent(self=0x000000011b014290) + 68 at query.rs:139
    frame #6: 0x0000000101eeac35 servo`script::dom::window::{{impl}}::offset_parent_query(self=0x0000000126832800, node=TrustedNodeAddress at 0x000000013b552828) + 117 at window.rs:1226
    frame #7: 0x00000001018e2aed servo`script::dom::htmlelement::{{impl}}::OffsetHeight(self=0x000000012689bc00) + 189 at htmlelement.rs:325
    frame #8: 0x00000001018e29e0 servo`script::dom::bindings::codegen::Bindings::HTMLElementBinding::get_offsetHeight(cx=0x000000010b0d5240, _obj=Handle<*mut js::jsapi::JSObject> at 0x000000013b552980, this=0x000000012689bc00, args=JSJitGetterCallArgs at 0x000000013b552970) + 48 at HTMLElementBinding.rs:546
    frame #9: 0x00000001023412e9 servo`CallJitGetterOp(info=0x0000000104e0ed70, cx=0x000000010b0d5240, thisObj=JS::HandleObject at 0x000000013b552a08, specializedThis=0x000000012689bc00, argc=0, vp=0x000000013b552f68) + 121 at jsglue.cpp:445
    frame #10: 0x000000010168f735 servo`script::dom::bindings::utils::generic_call(cx=0x000000010b0d5240, argc=0, vp=0x000000013b552f68, is_lenient=false, call=0x0000000102341270) + 1397 at utils.rs:482
    frame #11: 0x00000001016908dc servo`script::dom::bindings::utils::generic_getter(cx=0x000000010b0d5240, argc=0, vp=0x000000013b552f68) + 44 at utils.rs:498
    frame #12: 0x000000010337c24b servo`js::CallJSNative(cx=0x000000010b0d5240, native=0x00000001016908b0, args=0x000000013b552f10)(JSContext*, unsigned int, JS::Value*), JS::CallArgs const&) + 187 at jscntxtinlines.h:235
    frame #13: 0x000000010333b913 servo`js::Invoke(cx=0x000000010b0d5240, args=0x000000013b552f10, construct=NO_CONSTRUCT) + 1091 at Interpreter.cpp:476
    frame #14: 0x000000010336682d servo`js::Invoke(cx=0x000000010b0d5240, thisv=0x000000013b553550, fval=0x000000013b553000, argc=0, argv=0x0000000000000000, rval=JS::MutableHandleValue at 0x000000013b552f00) + 621 at Interpreter.cpp:528
    frame #15: 0x0000000103367235 servo`js::InvokeGetter(cx=0x000000010b0d5240, thisv=0x000000013b553550, fval=Value at 0x000000013b553000, rval=JS::MutableHandleValue at 0x000000013b552ff8) + 149 at Interpreter.cpp:640
    frame #16: 0x00000001033adbd6 servo`CallGetter(cx=0x000000010b0d5240, obj=JS::HandleObject at 0x000000013b5530b0, receiver=JS::HandleValue at 0x000000013b5530a8, shape=js::HandleShape at 0x000000013b5530a0, vp=JS::MutableHandleValue at 0x000000013b553098) + 246 at NativeObject.cpp:1735
    frame #17: 0x00000001033a146d servo`bool GetExistingProperty<(cx=0x000000010b0d5240, receiver=js::MaybeRooted<JS::Value, js::AllowGC>::HandleType at 0x000000013b5531b0, obj=js::MaybeRooted<js::NativeObject *, js::AllowGC>::HandleType at 0x000000013b5531a8, shape=js::MaybeRooted<js::Shape *, js::AllowGC>::HandleType at 0x000000013b5531a0, vp=js::MaybeRooted<JS::Value, js::AllowGC>::MutableHandleType at 0x000000013b553198)1>(JSContext*, js::MaybeRooted<JS::Value, (js::AllowGC)1>::HandleType, js::MaybeRooted<js::NativeObject*, (js::AllowGC)1>::HandleType, js::MaybeRooted<js::Shape*, (js::AllowGC)1>::HandleType, js::MaybeRooted<JS::Value, (js::AllowGC)1>::MutableHandleType) + 877 at NativeObject.cpp:1783
    frame #18: 0x00000001033a17ba servo`bool NativeGetPropertyInline<(cx=0x000000010b0d5240, obj=js::MaybeRooted<js::NativeObject *, js::AllowGC>::HandleType at 0x000000013b553320, receiver=js::MaybeRooted<JS::Value, js::AllowGC>::HandleType at 0x000000013b553318, id=js::MaybeRooted<jsid, js::AllowGC>::HandleType at 0x000000013b553310, nameLookup=NotNameLookup, vp=js::MaybeRooted<JS::Value, js::AllowGC>::MutableHandleType at 0x000000013b553308)1>(JSContext*, js::MaybeRooted<js::NativeObject*, (js::AllowGC)1>::HandleType, js::MaybeRooted<JS::Value, (js::AllowGC)1>::HandleType, js::MaybeRooted<jsid, (js::AllowGC)1>::HandleType, IsNameLookup, js::MaybeRooted<JS::Value, (js::AllowGC)1>::MutableHandleType) + 458 at NativeObject.cpp:2002
    frame #19: 0x00000001033a15dd servo`js::NativeGetProperty(cx=0x000000010b0d5240, obj=js::HandleNativeObject at 0x000000013b553388, receiver=JS::HandleValue at 0x000000013b553380, id=JS::HandleId at 0x000000013b553378, vp=JS::MutableHandleValue at 0x000000013b553370) + 93 at NativeObject.cpp:2036
    frame #20: 0x00000001030ff596 servo`js::GetProperty(cx=0x000000010b0d5240, obj=JS::HandleObject at 0x000000013b553410, receiver=JS::HandleValue at 0x000000013b553408, id=JS::HandleId at 0x000000013b553400, vp=JS::MutableHandleValue at 0x000000013b5533f8) + 214 at NativeObject.h:1477
    frame #21: 0x000000010314a328 servo`js::GetProperty(cx=0x000000010b0d5240, obj=JS::HandleObject at 0x000000013b5534a8, receiver=JS::HandleValue at 0x000000013b5534a0, name=0x000000013d181880, vp=JS::MutableHandleValue at 0x000000013b553498) + 136 at jsobj.h:822
    frame #22: 0x00000001033695d5 servo`js::GetProperty(cx=0x000000010b0d5240, v=JS::HandleValue at 0x000000013b5535b0, name=js::HandlePropertyName at 0x000000013b5535a8, vp=JS::MutableHandleValue at 0x000000013b5535a0) + 933 at Interpreter.cpp:4087
    frame #23: 0x0000000103372e67 servo`GetPropertyOperation(cx=0x000000010b0d5240, fp=0x000000010baa2a78, script=JS::HandleScript at 0x000000013b5536a0, pc=0x000000011005f539, lval=JS::MutableHandleValue at 0x000000013b553698, vp=JS::MutableHandleValue at 0x000000013b553690) + 535 at Interpreter.cpp:217
    frame #24: 0x0000000103354ce0 servo`Interpret(cx=0x000000010b0d5240, state=0x000000013b5567f8) + 47872 at Interpreter.cpp:2528
    frame #25: 0x00000001033490df servo`js::RunScript(cx=0x000000010b0d5240, state=0x000000013b5567f8) + 799 at Interpreter.cpp:426
    frame #26: 0x000000010333b9eb servo`js::Invoke(cx=0x000000010b0d5240, args=0x000000013b556e50, construct=NO_CONSTRUCT) + 1307 at Interpreter.cpp:494
    frame #27: 0x00000001031593a3 servo`js::fun_apply(cx=0x000000010b0d5240, argc=2, vp=0x000000010baa2a50) + 1667 at jsfun.cpp:1232
    frame #28: 0x000000010337c24b servo`js::CallJSNative(cx=0x000000010b0d5240, native=0x0000000103158d20, args=0x000000013b5590b0)(JSContext*, unsigned int, JS::Value*), JS::CallArgs const&) + 187 at jscntxtinlines.h:235
    frame #29: 0x000000010333b913 servo`js::Invoke(cx=0x000000010b0d5240, args=0x000000013b5590b0, construct=NO_CONSTRUCT) + 1091 at Interpreter.cpp:476
    frame #30: 0x0000000103357dc3 servo`Interpret(cx=0x000000010b0d5240, state=0x000000013b55a198) + 60387 at Interpreter.cpp:2809
    frame #31: 0x00000001033490df servo`js::RunScript(cx=0x000000010b0d5240, state=0x000000013b55a198) + 799 at Interpreter.cpp:426
    frame #32: 0x000000010333b9eb servo`js::Invoke(cx=0x000000010b0d5240, args=0x000000013b55a2d0, construct=NO_CONSTRUCT) + 1307 at Interpreter.cpp:494
    frame #33: 0x000000010336682d servo`js::Invoke(cx=0x000000010b0d5240, thisv=0x000000013b55a3d0, fval=0x000000013b55a6f0, argc=1, argv=0x000000012683c178, rval=JS::MutableHandleValue at 0x000000013b55a2c0) + 621 at Interpreter.cpp:528
    frame #34: 0x00000001030df88b servo`JS_CallFunctionValue(cx=0x000000010b0d5240, obj=JS::HandleObject at 0x000000013b55a418, fval=JS::HandleValue at 0x000000013b55a410, args=0x000000013b55a5c0, rval=JS::MutableHandleValue at 0x000000013b55a408) + 347 at jsapi.cpp:2852
    frame #35: 0x000000010185eaa6 servo`script::dom::bindings::codegen::Bindings::EventListenerBinding::{{impl}}::HandleEvent(self=0x0000000118a85370, cx=0x000000010b0d5240, aThisObj=Handle<*mut js::jsapi::JSObject> at 0x000000013b55a800, event=0x0000000118a12f00) + 2342 at EventListenerBinding.rs:155
    frame #36: 0x0000000101e916cf servo`script::dom::bindings::codegen::Bindings::EventListenerBinding::{{impl}}::HandleEvent_<script::dom::eventtarget::EventTarget>(self=0x0000000118a85370, thisObj=0x0000000126862000, event=0x0000000118a12f00, aExceptionHandling=Report) + 655 at EventListenerBinding.rs:125
    frame #37: 0x0000000101e903af servo`script::dom::eventtarget::{{impl}}::call_or_handle_event<script::dom::eventtarget::EventTarget>(self=0x0000000126810120, object=0x0000000126862000, event=0x0000000118a12f00, exception_handle=Report) + 399 at eventtarget.rs:151
    frame #38: 0x0000000101e9015f servo`script::dom::eventdispatcher::handle_event(window=Option<&script::dom::window::Window> at 0x000000013b55b360, listener=0x0000000126810120, current_target=0x0000000126862000, event=0x0000000118a12f00) + 255 at eventdispatcher.rs:47
    frame #39: 0x0000000101e968e8 servo`script::dom::eventdispatcher::inner_invoke(window=Option<&script::dom::window::Window> at 0x000000013b55b428, object=0x0000000126862000, event=0x0000000118a12f00, listeners=&[script::dom::eventtarget::CompiledEventListener] at 0x000000013b55b408) + 280 at eventdispatcher.rs:215
    frame #40: 0x0000000101e932a6 servo`script::dom::eventdispatcher::invoke(window=Option<&script::dom::window::Window> at 0x000000013b55b560, object=0x0000000126862000, event=0x0000000118a12f00, specific_listener_phase=Option<script::dom::eventtarget::ListenerPhase> at 0x000000013b55b548) + 598 at eventdispatcher.rs:190
    frame #41: 0x0000000101e92970 servo`script::dom::eventdispatcher::dispatch_to_listeners(event=0x0000000118a12f00, target=0x0000000126862000, event_path=&[&script::dom::eventtarget::EventTarget] at 0x000000013b55b838) + 1520 at eventdispatcher.rs:84
    frame #42: 0x0000000101e9412d servo`script::dom::eventdispatcher::dispatch_event(target=0x0000000126862000, target_override=Option<&script::dom::eventtarget::EventTarget> at 0x000000013b55be10, event=0x0000000118a12f00) + 3341 at eventdispatcher.rs:148
    frame #43: 0x000000010162b504 servo`script::dom::eventtarget::{{impl}}::dispatch_event(self=0x0000000126862000, event=0x0000000118a12f00) + 36 at eventtarget.rs:308
    frame #44: 0x0000000101da55fd servo`script::dom::event::{{impl}}::fire(self=0x0000000118a12f00, target=0x0000000126862000) + 45 at event.rs:297
    frame #45: 0x0000000101ea4907 servo`script::dom::eventtarget::{{impl}}::fire_event(self=0x0000000126862000, name=&str at 0x000000013b55bf60, bubbles=Bubbles, cancelable=NotCancelable) + 263 at eventtarget.rs:502
    frame #46: 0x00000001022395d1 servo`script::task_source::dom_manipulation::{{impl}}::handle_task(self=DOMManipulationTask at 0x000000013b55c1a8, script_thread=0x000000013b55ff80) + 1249 at dom_manipulation.rs:54
    frame #47: 0x00000001021a8080 servo`script::script_thread::{{impl}}::handle_msg_from_script(self=0x000000013b55ff80, msg=MainThreadScriptMsg at 0x000000013b55c4e8) + 688 at script_thread.rs:941
    frame #48: 0x0000000102230082 servo`script::script_thread::{{impl}}::handle_msgs::{{closure}} + 434 at script_thread.rs:771
    frame #49: 0x000000010222fbe1 servo`script::script_thread::{{impl}}::profile_event<closure,core::option::Option<bool>>(self=0x000000013b55ff80, category=ScriptEvent, f=closure at 0x000000013b55ce98) + 1009 at script_thread.rs:863
    frame #50: 0x0000000102201186 servo`script::script_thread::{{impl}}::handle_msgs(self=0x000000013b55ff80) + 7734 at script_thread.rs:763
    frame #51: 0x00000001021a5d5d servo`script::script_thread::{{impl}}::start(self=0x000000013b55ff80) + 29 at script_thread.rs:615
    frame #52: 0x00000001021a5d15 servo`script::script_thread::{{impl}}::create::{{closure}}::{{closure}} + 37 at script_thread.rs:462
    frame #53: 0x00000001021a5a62 servo`profile_traits::mem::{{impl}}::run_with_memory_reporting<closure,fn(self=0x000000013b5601d0, f=closure at 0x000000013b55f9e0, reporter_name=String at 0x000000013b55f9c8, channel_for_reporter=Sender<script::script_thread::MainThreadScriptMsg> at 0x000000013b55f9b0, msg=0x0000000000000015) -> script::script_runtime::CommonScriptMsg,script::script_runtime::CommonScriptMsg,std::sync::mpsc::Sender<script::script_thread::MainThreadScriptMsg>> + 674 at mem.rs:59
    frame #54: 0x0000000102192cba servo`script::script_thread::{{impl}}::create::{{closure}} + 1882 at script_thread.rs:461
    frame #55: 0x0000000102191251 servo`util::thread::spawn_named_with_send_on_panic::_$u7b$$u7b$closure$u7d$$u7d$::h51879a609c3205a6 + 561 at boxed.rs:234
    frame #56: 0x0000000102190fc8 servo`std::panic::{{impl}}::call_once<(self=AssertUnwindSafe<closure> at 0x000000013b560780, _args=<unavailable>),closure> + 136 at panic.rs:284
    frame #57: 0x0000000102190f1f servo`std::panicking::try::_$u7b$$u7b$closure$u7d$$u7d$::_$u7b$$u7b$closure$u7d$$u7d$::h89eb0322b68ea443 + 79
    frame #58: 0x00000001021917f5 servo`std::panicking::try::call<closure>(f=0x000000013b560ee0) + 21 at panicking.rs:272
    frame #59: 0x0000000103c64d3c servo`__rust_try + 12
    frame #60: 0x0000000103c64cd6 servo`__rust_maybe_catch_panic + 38
    frame #61: 0x0000000102190e6e servo`std::panicking::try::_$u7b$$u7b$closure$u7d$$u7d$::hb39ecbfd724b9507 + 174
    frame #62: 0x0000000102190db0 servo`std::thread::local::{{impl}}::with<core::cell::Cell<usize>,closure,core::result::Result<(self=0x000000010501b020, f=closure at 0x000000013b560f78), Box<Any>>> + 208 at local.rs:211
    frame #63: 0x0000000102190be0 servo`std::panicking::try<(f=AssertUnwindSafe<closure> at 0x000000013b561250),std::panic::AssertUnwindSafe<closure>> + 192 at panicking.rs:235
    frame #64: 0x0000000102190abf servo`std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,(f=AssertUnwindSafe<closure> at 0x000000013b5616e0)> + 143 at panic.rs:387
    frame #65: 0x000000010219092f servo`std::thread::Builder::spawn::_$u7b$$u7b$closure$u7d$$u7d$::h9c63aaed83bdcff4 + 383
    frame #66: 0x00000001021919d8 servo`alloc::boxed::{{impl}}::call_box<(self=0x000000011b63a780, args=<unavailable>),closure> + 104 at boxed.rs:543
    frame #67: 0x0000000103c609f9 servo`std::sys::thread::Thread::new::thread_start::h6f266e069bf4ec2b + 57
    frame #68: 0x00007fff84e35899 libsystem_pthread.dylib`_pthread_body + 138
    frame #69: 0x00007fff84e3572a libsystem_pthread.dylib`_pthread_start + 137
    frame #70: 0x00007fff84e39fc9 libsystem_pthread.dylib`thread_start + 13
@jdm
Copy link
Member

@jdm jdm commented May 30, 2016

I did it a second time after waiting for a lot longer and saw the same backtrace. We appear to be stuck waiting on a layout mutex.

@jdm
Copy link
Member

@jdm jdm commented May 30, 2016

Meanwhile, the layout thread for that page doesn't appear to be doing anything interesting:

(lldb) bt
error: need to add support for DW_TAG_base_type '()' encoded with DW_ATE = 0x7, bit_size = 0
* thread #102: tid = 0x9f589, 0x00007fff8e230716 libsystem_kernel.dylib`__psynch_cvwait + 10
  * frame #0: 0x00007fff8e230716 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff84e37c3b libsystem_pthread.dylib`_pthread_cond_wait + 727
    frame #2: 0x0000000103c47fa9 servo`std::thread::park::h73cb11855e7141e1 + 297
    frame #3: 0x0000000103c57f10 servo`std::sync::mpsc::select::Select::wait::h0b444db680dca85f + 288
    frame #4: 0x0000000100fdbee3 servo`layout::layout_thread::{{impl}}::handle_request(self=0x000000013b4f6a38, possibly_locked_rw_data=0x000000013b4f69c8) + 611 at <std macros>:6
    frame #5: 0x0000000100fa1a42 servo`layout::layout_thread::{{impl}}::start(self=LayoutThread at 0x000000013b4f6a38) + 370 at layout_thread.rs:494
    frame #6: 0x0000000100fa1888 servo`layout::layout_thread::{{impl}}::create::{{closure}}::{{closure}} + 104 at layout_thread.rs:287
    frame #7: 0x0000000100f9b7d0 servo`profile_traits::mem::{{impl}}::run_with_memory_reporting<closure,fn(self=0x000000013b4f7dd0, f=closure at 0x000000013b4f7278, reporter_name=String at 0x000000013b4f7260, channel_for_reporter=Sender<script::layout_interface::Msg> at 0x000000013b4f7248, msg=0x000000013b4f7280) -> script::layout_interface::Msg,script::layout_interface::Msg,std::sync::mpsc::Sender<script::layout_interface::Msg>> + 912 at mem.rs:59
    frame #8: 0x0000000100f7e9f3 servo`layout::layout_thread::{{impl}}::create::{{closure}} + 2323 at layout_thread.rs:286
    frame #9: 0x0000000100f7a7a1 servo`util::thread::spawn_named_with_send_on_panic::_$u7b$$u7b$closure$u7d$$u7d$::h34b295e330d3a42d + 561 at boxed.rs:234
    frame #10: 0x0000000100f7a518 servo`std::panic::{{impl}}::call_once<(self=AssertUnwindSafe<closure> at 0x000000013b4f7ff0, _args=<unavailable>),closure> + 136 at panic.rs:284
    frame #11: 0x0000000100f7a46f servo`std::panicking::try::_$u7b$$u7b$closure$u7d$$u7d$::_$u7b$$u7b$closure$u7d$$u7d$::h8d2fe62ffa2338ab + 79
    frame #12: 0x0000000100f7ad45 servo`std::panicking::try::call<closure>(f=0x000000013b4f8480) + 21 at panicking.rs:272
    frame #13: 0x0000000103c64d3c servo`__rust_try + 12
    frame #14: 0x0000000103c64cd6 servo`__rust_maybe_catch_panic + 38
    frame #15: 0x0000000100f7a15e servo`std::panicking::try::_$u7b$$u7b$closure$u7d$$u7d$::h0508309180bde640 + 174
    frame #16: 0x0000000100f7a030 servo`std::thread::local::{{impl}}::with<core::cell::Cell<usize>,closure,core::result::Result<(self=0x000000010501b020, f=closure at 0x000000013b4f8518), Box<Any>>> + 208 at local.rs:211
    frame #17: 0x0000000100f79e60 servo`std::panicking::try<(f=AssertUnwindSafe<closure> at 0x000000013b4f8700),std::panic::AssertUnwindSafe<closure>> + 192 at panicking.rs:235
    frame #18: 0x0000000100f79d3f servo`std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,(f=AssertUnwindSafe<closure> at 0x000000013b4f89b0)> + 143 at panic.rs:387
    frame #19: 0x0000000100f79baf servo`std::thread::Builder::spawn::_$u7b$$u7b$closure$u7d$$u7d$::h226a550ab4accc2b + 383
    frame #20: 0x0000000100f7af88 servo`alloc::boxed::{{impl}}::call_box<(self=0x000000011b035640, args=<unavailable>),closure> + 104 at boxed.rs:543
    frame #21: 0x0000000103c609f9 servo`std::sys::thread::Thread::new::thread_start::h6f266e069bf4ec2b + 57
    frame #22: 0x00007fff84e35899 libsystem_pthread.dylib`_pthread_body + 138
    frame #23: 0x00007fff84e3572a libsystem_pthread.dylib`_pthread_start + 137
    frame #24: 0x00007fff84e39fc9 libsystem_pthread.dylib`thread_start + 13
@jdm
Copy link
Member

@jdm jdm commented May 30, 2016

Interestingly, despite the script thread having returned from the reflow call (which is used to compute the query results), there does not appear to be any layout information stored in the layout data that's being locked. One theory being floated right now is that this is occurring before the first layout of the page, which causes the layout data to blocked.

@jdm
Copy link
Member

@jdm jdm commented May 30, 2016

The layout thread does have first_reflow set to true, which means that it has not executed perform_post_main_layout_passes.

@jdm
Copy link
Member

@jdm jdm commented May 31, 2016

The reflow doesn't happen because Window::window_size is None, so force_reflow bails early on and never sends a message to the layout thread.

@emilio
Copy link
Member

@emilio emilio commented May 31, 2016

Also, while trying to find a test for this (before knowing what @jdm said), I found out we deadlock in a very simple example:

<!doctype html>                                                                             
<script>                                                                                    
var frame;                                                                                                                                                                              
setTimeout(function f() {                                                                   
  if (frame)                                                                                
    frame.parentNode.removeChild(frame);                                                    

  frame = document.createElement('iframe');                                                 
  frame.src = "frame.html";                                                                 
  frame.style.display = "none";                                                             
  document.body.appendChild(frame);                                                         
  setTimeout(f, 150);                                                                       
}, 150)                                                                                     
</script>

(We never manage to remove the first frame, which is worrying)

@emilio
Copy link
Member

@emilio emilio commented May 31, 2016

@jdm: So it seems to reproduce the original error we need a chunked response, right?

@jdm
Copy link
Member

@jdm jdm commented May 31, 2016

Yeah, I assume there's a timing issue where small responses end up getting parsed too quickly or something? I've been having trouble figuring out how the window size messages would end up being delayed, though.

@emilio
Copy link
Member

@emilio emilio commented May 31, 2016

So the only moment when there can be no window_size is while there's an
incomplete load, or if for some reason when the event arrives the
browsing context isn't correctly set up and we can't find the correct
pipeline to deliver the event to...

Could it be the case that while the page is loading, a parent script is
trying to query the iframe contents via contentDocument or similar,
but the viewport is still not correctly setup in the child?

On Mon, May 30, 2016 at 08:34:29PM -0700, Josh Matthews wrote:

Yeah, I assume there's a timing issue where small responses end up
getting parsed too quickly or something? I've been having trouble
figuring out how the window size messages would end up being delayed,
though.


You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
#11223 (comment)

@nox
Copy link
Member

@nox nox commented Jun 1, 2016

Does it even make sense to do queries for offsets and whatnot when there is no window_size? How wrong would it be to return (None, Rect::zero()) in that case?

@emilio
Copy link
Member

@emilio emilio commented Jun 1, 2016

So I was able to reproduce it consistently:

Take the following test.html file:

<!doctype html>
<title></title>
<iframe src="http://localhost:5000"></iframe>
<div>test</div>

and put up a node server with this:

const http = require('http');                                                                                                                                                           
const PORT = 5000;

const server = http.createServer((_request, res) => {
  res.writeHead(200, {
    'Content-Type': 'text/html'
  });
  res.write("<!doctype html><script>console.log(document.documentElement.offsetHeight)</script>");

  setTimeout(() => {
    res.write("<div>Test</div>");
    res.end();
  }, 2000)
});

server.listen(PORT, () => console.log("Server listening on: http://localhost:%s", PORT));

if you run ./target/release/servo test.html, I get stuck consistently in the same way that @jdm discovered. Doesn't happen if you run ./target/release/servo http://localhost:5000 directly though (because we set the window size on startup).

emilio added a commit to emilio/servo that referenced this issue Jun 1, 2016
…to the viewport size not yet present.

This fixes servo#11223.

Note that this didn't happen in the root pipeline because we explicitly set the
window size in that case.
bors-servo added a commit that referenced this issue Jun 1, 2016
script: Ensure we don't ignore reflows for queries that bail out due to the viewport size not yet present

<!-- Please describe your changes on the following line: -->

---
<!-- Thank you for contributing to Servo! Please replace each `[ ]` by `[X]` when the step is complete, and replace `__` with appropriate data: -->
- [x] `./mach build -d` does not report any errors
- [x] `./mach test-tidy` does not report any errors
- [x] These changes fix #11223

<!-- Either: -->
- [ ] There are tests for these changes.

<!-- Pull requests that do not address these steps are welcome, but they will require additional verification as part of the review process. -->

This fixes #11223.

Note that this didn't happen in the root pipeline because we explicitly set the
window size in that case.

<!-- Reviewable:start -->
---
This change is [<img src="https://reviewable.io/review_button.svg" height="35" align="absmiddle" alt="Reviewable"/>](https://reviewable.io/reviews/servo/servo/11545)
<!-- Reviewable:end -->
emilio added a commit to emilio/servo that referenced this issue Jun 1, 2016
…to the viewport size not yet present.

This fixes servo#11223.

Note that this didn't happen in the root pipeline because we explicitly set the
window size in that case.
@nox nox assigned emilio and unassigned nox Jun 1, 2016
bors-servo added a commit that referenced this issue Jun 1, 2016
script: Ensure we don't ignore reflows for queries that bail out due to the viewport size not yet present

<!-- Please describe your changes on the following line: -->

---
<!-- Thank you for contributing to Servo! Please replace each `[ ]` by `[X]` when the step is complete, and replace `__` with appropriate data: -->
- [x] `./mach build -d` does not report any errors
- [x] `./mach test-tidy` does not report any errors
- [x] These changes fix #11223

<!-- Either: -->
- [ ] There are tests for these changes.

<!-- Pull requests that do not address these steps are welcome, but they will require additional verification as part of the review process. -->

This fixes #11223.

Note that this didn't happen in the root pipeline because we explicitly set the
window size in that case.

<!-- Reviewable:start -->
---
This change is [<img src="https://reviewable.io/review_button.svg" height="35" align="absmiddle" alt="Reviewable"/>](https://reviewable.io/reviews/servo/servo/11545)
<!-- Reviewable:end -->
@paulrouget
Copy link
Contributor Author

@paulrouget paulrouget commented Jun 2, 2016

Thank you all for figuring out what was going on! It now works perfectly.

avadacatavra added a commit to avadacatavra/servo that referenced this issue Jun 10, 2016
…to the viewport size not yet present.

This fixes servo#11223.

Note that this didn't happen in the root pipeline because we explicitly set the
window size in that case.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

8 participants
You can’t perform that action at this time.