Closed Bug 810013 Opened 13 years ago Closed 11 years ago

Firefox OS: v8 benchmark stops printing scores just before regexp

Categories

(Core :: JavaScript Engine, defect, P1)

Product:
Core
Component:
JavaScript Engine
Platform:
ARM
Gonk (Firefox OS)
Type:
defect

Tracking

()

Status:
RESOLVED WORKSFORME
Milestone:
B2G C2 (20nov-10dec)
Project Flags:
blocking-kilimanjaro +
blocking-basecamp -

People

(Reporter: dmandelin, Assigned: mjrosenb)

Details

STR: Load http://v8.googlecode.com/svn/data/benchmarks/v7/run.html in Firefox in Firefox OS. Expected result: test finishes. Actual result: the test doesn't get past 62% or so. 'regexp' is the first thing it doesn't print out. Possible clue: when I try the same STR on Fennec, I get slow script dialog while regexp is running.
I'll look into this.
Assignee: general → mrosenberg
This bug has been called out as likely having risk to non-B2G platforms. Given that, marking as P1, and moving into the C2 milestone. We should prioritize this landing to mozilla-beta as soon as possible, to prevent late-breaking regressions to other platforms.
Priority: -- → P1
Target Milestone: --- → B2G C2 (20nov-10dec)
Marty, any news here?
Flags: needinfo?(mrosenberg)
Changing to basecamp-. If this issue is found to impact key sites or apps we should revisit/renom.
blocking-basecamp: + → -
blocking-kilimanjaro: --- → +
Updates! I finally got a debug build running on my phone, and reproduced this under gdb. The C++ backtrace when we hang is: #0 syscall () at bionic/libc/arch-arm/bionic/syscall.S:50 #1 0x411cb1b6 in epoll_wait (epfd=20, events=0xbee84498, maxevents=16, timeout=<value optimized out>) at /home/mrosenberg/src/B2G/B2G2/gecko/ipc/chromium/src/third_party/libevent/epoll_sub.c:51 #2 0x40ef745a in nsAppShell::ProcessNextNativeEvent (this=0x430efa00, mayWait=true) at /home/mrosenberg/src/B2G/B2G2/gecko/widget/gonk/nsAppShell.cpp:690 #3 0x40f19070 in nsBaseAppShell::DoProcessNextNativeEvent (this=0xfffffffc, mayWait=152, recursionDepth=16) at /home/mrosenberg/src/B2G/B2G2/gecko/widget/xpwidgets/nsBaseAppShell.cpp:139 #4 0x40f19290 in nsBaseAppShell::OnProcessNextEvent (this=0x430efa00, thr=0x42407240, mayWait=152, recursionDepth=1) at /home/mrosenberg/src/B2G/B2G2/gecko/widget/xpwidgets/nsBaseAppShell.cpp:298 #5 0x4119d88c in nsThread::ProcessNextEvent (this=0x42407240, mayWait=true, result=0xbee84998) at /home/mrosenberg/src/B2G/B2G2/gecko/xpcom/threads/nsThread.cpp:600 #6 0x411b749a in NS_InvokeByIndex_P (that=0x42407240, methodIndex=8, paramCount=<value optimized out>, params=<value optimized out>) at /home/mrosenberg/src/B2G/B2G2/gecko/xpcom/reflect/xptcall/src/md/unix/xptcinvoke_arm.cpp:160 #7 0x40d385fa in CallMethodHelper::Invoke (this=0xbee84960) at /home/mrosenberg/src/B2G/B2G2/gecko/js/xpconnect/src/XPCWrappedNative.cpp:3081 #8 CallMethodHelper::Call (this=0xbee84960) at /home/mrosenberg/src/B2G/B2G2/gecko/js/xpconnect/src/XPCWrappedNative.cpp:2415 #9 0x40d39ae4 in XPCWrappedNative::CallMethod (ccx=..., mode=<value optimized out>) at /home/mrosenberg/src/B2G/B2G2/gecko/js/xpconnect/src/XPCWrappedNative.cpp:2381 #10 0x40d40bce in XPC_WN_CallMethod (cx=0x4303c8c0, argc=1, vp=<value optimized out>) at /home/mrosenberg/src/B2G/B2G2/gecko/js/xpconnect/src/XPCWrappedNativeJSOps.cpp:1488 #11 0x416c314a in JaegerStubVeneer () from /home/mrosenberg/src/B2G/B2G2/objdir-gecko/dist/bin/libxul.so #12 0x416c314a in JaegerStubVeneer () from /home/mrosenberg/src/B2G/B2G2/objdir-gecko/dist/bin/libxul.so which looks like a fairly standard backtrace for waiting for user input. The problem is that v8/octane is *supposed* to be doing lots javascript computations, not waiting for user input. Slightly more interesting is the JS stack at this point: 0 anonymous() ["chrome://global/content/BrowserElementChild.js":273] this = [object Object] 1 anonymous() ["chrome://global/content/BrowserElementChild.js":215] this = [object Object] 2 anonymous() ["resource://gre/modules/BrowserElementPromptService.jsm":87] this = [object Object] 3 anonymous() ["http://octane-benchmark.googlecode.com/svn/latest/raytrace.js":36] this = Vector [0,0,0] 4 anonymous() ["http://octane-benchmark.googlecode.com/svn/latest/raytrace.js":261] this = Vector [0,0,0] 5 anonymous() ["http://octane-benchmark.googlecode.com/svn/latest/raytrace.js":430] this = Sphere [position=Vector [1,0.25,1], radius=0.5] 6 anonymous() ["http://octane-benchmark.googlecode.com/svn/latest/raytrace.js":689] this = [object Object] 7 anonymous() ["http://octane-benchmark.googlecode.com/svn/latest/raytrace.js":672] this = [object Object] 8 anonymous() ["http://octane-benchmark.googlecode.com/svn/latest/raytrace.js":661] this = [object Object] 9 renderScene() ["http://octane-benchmark.googlecode.com/svn/latest/raytrace.js":903] this = [object Object] 10 Measure() ["http://octane-benchmark.googlecode.com/svn/latest/base.js":211] this = [object Window] 11 anonymous() ["http://octane-benchmark.googlecode.com/svn/latest/base.js":226] this = [object Object] 12 RunNextBenchmark() ["http://octane-benchmark.googlecode.com/svn/latest/base.js":268] this = [object Window] 13 RunNextBenchmark() ["http://octane-benchmark.googlecode.com/svn/latest/base.js":274] this = [object Window] 14 RunNextBenchmark() ["http://octane-benchmark.googlecode.com/svn/latest/base.js":274] this = [object Window] 15 RunNextBenchmark() ["http://octane-benchmark.googlecode.com/svn/latest/base.js":274] this = [object Window] 16 RunNextBenchmark() ["http://octane-benchmark.googlecode.com/svn/latest/base.js":274] this = [object Window] 17 RunNextBenchmark() ["http://octane-benchmark.googlecode.com/svn/latest/base.js":274] this = [object Window] 18 RunStep() ["http://octane-benchmark.googlecode.com/svn/latest/base.js":119] this = [object Window] Namely, 3 anonymous() ["http://octane-benchmark.googlecode.com/svn/latest/raytrace.js":36], which "calls" 2 anonymous() ["resource://gre/modules/BrowserElementPromptService.jsm":87]. I've heard that that code is the generic "handle displaying a dialog box, which should include the slow script dialog. I'm kind of curious about the relation of the C++ stack and the JS stack, namely the fact that the last three JS stack frames are in chrome code, but there is no interpreter on the c++ stack, which would lead me to believe that we are actively running the chrome code in the methodjit, which is fine, since we default to running chrome under the methodjit, but I am concerned that we are jitting chrome code when this should theoretically be the first time that we are attempting to display the dialog. I was curious and tried to determine if this was being caused solely by running chrome in the jit, so I turned it off, and still observed the exact same call stack. I assume that I did something wrong in turning it off, or that I am wrong about this stack actually implying that we are running chrome code in the methodjit. Either way, I have a bit more investigation to do. Comments are welcome.
Flags: needinfo?(mrosenberg)
More digging has happened, I belive I accurately reproduced this bug with chrome jitting disabled, and I started print debugging the chrome code. Some of these lines were printed by just changing debug to dump, and others were added in just for this. I/Gecko ( 2167): running: confirmEx I/Gecko ( 2167): text is: 'A script on this page may be busy, or it may have stopped responding. You can stop the script now, open the script in the debugger, or let the script continue. I/Gecko ( 2167): I/Gecko ( 2167): Script: http://octane-benchmark.googlecode.com/svn/latest/raytrace.js:711' I/Gecko ( 2167): outer is: 1 I/Gecko ( 2167): inner is: 4 I/Gecko ( 2167): sending async message: I/Gecko ( 2167): async message sent! I/Gecko ( 2167): outerWindowID = 1 I/Gecko ( 2167): innerWindowID = 4 I/Gecko ( 1822): handleShowPrompt {"promptType":"custom-prompt","title":"Warning: Unresponsive script","message":"A script on this page may be busy, or it may have stopped responding. You can stop the script now, open the script in the debugger, or let the script continue.\n\nScript: http://octane-benchmark.googlecode.com/svn/latest/raytrace.js:711","defaultButton":1,"buttons":[{"messageType":"custom","message":"Continue"},{"messageType":"custom","message":"Stop script"},{"messageType":"custom","message":"Debug script"}],"showCheckbox":true,"checkboxMessage":"&Don't ask me again","checkboxCheckedByDefault":false,"returnValue":{"selectedButton":1,"checked":false},"windowID":{"outer":1,"inner":4}} I/Gecko ( 1822): Event will have detail: {"promptType":"custom-prompt","title":"Warning: Unresponsive script","message":"A script on this page may be busy, or it may have stopped responding. You can stop the script now, open the script in the debugger, or let the script continue.\n\nScript: http://octane-benchmark.googlecode.com/svn/latest/raytrace.js:711","defaultButton":1,"buttons":[{"messageType":"custom","message":"Continue"},{"messageType":"custom","message":"Stop script"},{"messageType":"custom","message":"Debug script"}],"showCheckbox":true,"checkboxMessage":"&Don't ask me again","checkboxCheckedByDefault":false,"returnValue":{"selectedButton":1,"checked":false}} I/Gecko ( 2167): Entering modal state (outerWindowID=1, innerWindowID=4) I/Gecko ( 2167): origModalDepth = 1 I/Gecko ( 2167): Nested event loop - begin I/Gecko ( 2167): calling thread.processNextEvent I/Gecko ( 2167): done calling thread.processNextEvent I/Gecko ( 2167): calling thread.processNextEvent I/Gecko ( 2167): done calling thread.processNextEvent I/Gecko ( 2167): calling thread.processNextEvent I/Gecko ( 2167): done calling thread.processNextEvent I/Gecko ( 2167): calling thread.processNextEvent I/Gecko ( 2167): [Child 2167] WARNING: NS_ENSURE_TRUE(IsChromeProcess()) failed: file /home/mrosenberg/src/B2G/B2G2/gecko/content/base/src/nsFrameMessageManager.cpp, line 687 I/Gecko ( 1822): dispatching event I/Gecko ( 2167): done calling thread.processNextEvent I/Gecko ( 1822): done dispatching event I/Gecko ( 1822): done with handleShowPrompt I/Gecko ( 2167): calling thread.processNextEvent I/Gecko ( 2167): done calling thread.processNextEvent I/Gecko ( 2167): calling thread.processNextEvent I/Gecko ( 2167): done calling thread.processNextEvent I/Gecko ( 2167): calling thread.processNextEvent I/Gecko ( 2167): done calling thread.processNextEvent I/Gecko ( 2167): calling thread.processNextEvent I/Gecko ( 2167): done calling thread.processNextEvent I/Gecko ( 2167): calling thread.processNextEvent I/Gecko ( 2167): done calling thread.processNextEvent I/Gecko ( 2167): calling thread.processNextEvent I/Gecko ( 2167): done calling thread.processNextEvent I/Gecko ( 2167): calling thread.processNextEvent I/Gecko ( 2167): done calling thread.processNextEvent I/Gecko ( 2167): calling thread.processNextEvent I/Gecko ( 2167): done calling thread.processNextEvent I/Gecko ( 2167): calling thread.processNextEvent I am totally unfamiliar with this code, so I'll just keep adding print statements to further nested calls. Bugzilla-pinging jlebar, since it looks like he initially wrote _handleShowModalPrompt, which gets called in the middle of this mess, and presumably at least knows where in the codebase something like this *could* go awry.
Flags: needinfo?(justin.lebar+bug)
Did you get a slow script warning? That's what's happening here.
Flags: needinfo?(justin.lebar+bug)
CC'ing people because :jlebar doesn't have a test device atm fwiw, it looks like the revision of gecko that I have checked out for this project is: https://hg.mozilla.org/mozilla-central/rev/85471409cbfb and I'm running this on a galaxy s2 (in case the hardware actually matters, I can't imagine that it does)
> CC'ing people because :jlebar doesn't have a test device atm To be specific, it looks like we're not handling the slow script warning here. But I saw us do so in a build from a week ago. Maybe we regressed this.
I just tried this page on a nightly build, and got several slow scripts dialogs. WFM here!
Closing as WFM as per Fabrice's comment 10. If the V8 benchmark was not running on Firefox OS today, I'm sure we would have heard about it. :)
Status: NEW → RESOLVED
Closed: 11 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.