469233 - TM: chrome crashed because switchmask didn't notice venkman had cleared its interrupt hook [@ js_MonitorRecording]

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[timeless]

this is windows, which means there's no threaded_interp.

vnk: OFF building response {++DOMWINDOW == 24 (08CD1E48) [serial = 29] [outer = 09BA5EB8]
} 0.243 sec

js3250!js_MonitorRecording(class TraceRecorder * tr = 0x00000000)+0x9
js3250!js_Interpret+0x1adad
0:000> dv
             cx = 0x07a134e0
             op = JSOP_NAME (59)
       switchOp = 0x13b
             rt = 0x00d69010
         script = 0x0798c0d8
     switchMask = 0
             tr = 0x00000000
             fp = 0x03d0fcb0
inlineCallCount = 1
            pc2 = 0x09b25e29 "???"
0:000> dt cx JSContext debugHooks
Local var @ 0x12e6b4 Type JSContext*
0x07a134e0 
   +0x1d4 debugHooks : 0x00d69168 JSDebugHooks
0:000> dt 0x00d69168 JSDebugHooks
js3250!JSDebugHooks
   +0x000 interruptHandler : (null) 
   +0x008 newScriptHook    : 0x01181ce4     void  jsd3250!ILT+3295(_jsd_NewScriptHookProc)+0
   +0x010 destroyScriptHook : 0x011810f0     void  jsd3250!ILT+235(_jsd_DestroyScriptHookProc)+0
   +0x018 debuggerHandler  : 0x011817da     JSTrapStatus  jsd3250!ILT+2005(_jsd_DebuggerHandler)+0
   +0x020 sourceHandler    : (null) 
   +0x028 executeHook      : 0x0118133e     void*  jsd3250!ILT+825(_jsd_TopLevelCallHook)+0
   +0x030 callHook         : 0x01181622     void*  jsd3250!ILT+1565(_jsd_FunctionCallHook)+0
   +0x038 objectHook       : 0x01181c1c     void  jsd3250!ILT+3095(_jsd_ObjectHook)+0
   +0x040 throwHook        : 0x011811c2     JSTrapStatus  jsd3250!ILT+445(_jsd_ThrowHandler)+0
   +0x048 debugErrorHook   : 0x01186260     int  jsd3250!jsd_DebugErrorHook+0
js3250!js_Invoke+0x8f2
js3250!js_InternalInvoke+0x6d
js3250!JS_CallFunctionValue+0x5d
gklayout!nsJSContext::CallEventHandler+0x2ec
gklayout!nsJSEventListener::HandleEvent+0x10d9
gklayout!nsEventListenerManager::HandleEventSubType+0x1ad
gklayout!nsEventListenerManager::HandleEvent+0x374
gklayout!nsEventTargetChainItem::HandleEvent+0x130
gklayout!nsEventTargetChainItem::HandleEventTargetChain+0x194
gklayout!nsEventDispatcher::Dispatch+0x58f
gklayout!DocumentViewerImpl::LoadComplete+0x1c5

I was in venkman and asked it to step through some chrome code. and then i clicked 'play' to continue (i have a breakpoint i want to hit)

Comment 1

[timeless]

fwiw
0:000> dt cx JSContext fp->script
Local var @ 0x12e6b4 Type JSContext*
0x07a134e0 
   +0x098 fp         : 
      +0x01c script     : 0x0798c0d8 JSScript
0:000> dt 0x0798c0d8 JSScript
js3250!JSScript
   +0x000 code             : 0x0798c1d4  ";"
   +0x004 length           : 0x235
   +0x014 main             : 0x0798c1d4  ";"
   +0x018 atomMap          : JSAtomMap
   +0x020 filename         : 0x05d09e59  "chrome://pippki/content/certManager.js"
   +0x024 lineno           : 0x44
0:000> dt $!regs
Local var @ 0x12e668 Type JSFrameRegs
   +0x000 pc               : 0x0798c2ae  ";"
   +0x004 sp               : 0x03d0fd38  -> 161094080

js> 0x0798c2ae  - 0x0798c1d4
218
js> 0x44
68
js> Components={classes:{},interfaces:{}}; load("c:\\home\\mozilla.org\\mozilla-central\\security\\manager\\pki\\resources\\content\\certManager.js")
js> dissrc(LoadCerts)
;-------------------------  69:   window.crypto.enableSmartCardEvents = true;
...
;-------------------------  85:   if (x) {
00183:  85  getlocal 2
00186:  85  ifeq 231 (45)
;-------------------------  86:     window.myFilterCA = new TreeFilter(caTreeView, treeBoxObject);
00189:  86  name "window"
00192:  86  callname "TreeFilter"
00195:  86  name "caTreeView"
00198:  86  getlocal 1
00201:  86  new 2
00204:  86  setprop "myFilterCA"
00207:  86  pop
;-------------------------  87:     treeBoxObject.view = myFilterCA;
00208:  87  getlocal 1
00211:  87  name "myFilterCA"
00214:  87  setprop "view"
00217:  87  pop
;-------------------------  88:     myFilterCA.search("ime");
00218:  88  name "myFilterCA"
00221:  88  callprop "search"
00224:  88  string "ime"
00227:  88  call 1
00230:  88  pop
;-------------------------  89:   }

sadly, this code doesn't exist upstream, i'm working on it.

After tracing past the crash, switchMask is reset to 0xff and the program continues happily.

So this is just a matter of some interaction for the short period where something returns to normal operation after jsd disables its hook.

Comment 2

[timeless]

fwiw, venkman and friends use 'pause' a lot, and it does stuff like this:

js3250!JS_ClearInterrupt
jsd3250!jsd_ClearInterruptHook+0x5c
jsd3250!JSD_ClearInterruptHook+0x18
jsd3250!jsdService::Pause+0x5c
jsd3250!jsds_ExecutionHookProc+0x299
jsd3250!jsd_CallExecutionHook+0x71
jsd3250!jsd_TrapHandler+0x1d2
js3250!JS_HandleTrap+0xfc
js3250!js_Interpret+0xfbc7
js3250!js_Invoke+0x8f7
js3250!js_InternalInvoke+0x6d
js3250!JS_CallFunctionValue+0x5d
gklayout!nsJSContext::CallEventHandler+0x2ec

Comment 3

[timeless]

so, among other things, js_GetPropertyHelper (JSOP_GETPROP) can call out, and the debugger can decide to twiddle the interp hook inside it.

when this happens, i can easily reach
      advance_pc:
without going through LOAD_INTERRUPT_HANDLER

Comment 4

[timeless]

the general stack looks like this, but note that the behavior of the debugger is legally arbitrary.
jsd3250!jsdService::Pause
jsd3250!jsds_ScriptHookProc+0xa3
jsd3250!jsd_NewScriptHookProc+0x11a
js3250!js_CallNewScriptHook+0x59
js3250!js_NewScriptFromCG+0x6ab
js3250!js_CompileScript+0x500
js3250!JS_EvaluateUCScriptForPrincipals+0x77
gklayout!nsJSContext::EvaluateStringWithValue+0x293
gklayout!nsXBLProtoImplField::InstallField+0x181
gklayout!XBLResolve+0x321
js3250!js_LookupPropertyWithFlags+0x3bf
js3250!js_GetPropertyHelper+0x1ad
js3250!js_Interpret+0xa001

Comment 5

[Brendan Eich [:brendan]]

     * Load the debugger's interrupt hook here and after calling out to native
     * functions (but not to getters, setters, or other native hooks), so we do
     * not have to reload it each time through the interpreter loop -- we hope
     * the compiler can keep it in a register when it is non-null.

Why is venkman changing the hook from a getter or setter? What is the stack that goes through js_[GS]etPropertyHelper?

/be

Comment 6

[timeless]

comment 4 provides the stack asked for in comment 5.

* getters and setters (see comment 4) are arbitrary code
* i believe your hope is futile
* the debugger like any proper debugger lets the user step into code, this includes getters and setters, if the user clicks 'continue', then the debugger wants to *not* listen for certain things, even if the debugger was tracing a getter/setter. also, if the debugger is 'busy', it doesn't want to be called back.

in fact, the implementation of the debugger today is such that it will typically call pause constantly while stepping, because each time it needs to breath it doesn't want any other js context to call it (especially not a js implemented debugger).

Yes, I should take advantage of the new debug hooks, but that won't help anyone today (it's on my list, but you need to fix js(dbg)api first).

Comment 7

[Brendan Eich [:brendan]]

Timeless: you're right, it's a vain hope that scripted getters and setters won't run debugger API-hooked code and change the interruptHandler. Yet we would like to avoid reloading that hook after every get or set that calls a scripted function -- and maybe even after every get or set that calls a native getter or setter (native function or JSPropertyOp), which might end up wandering into code that changes the hook.

If we could reach down into the interpreter(s) active on the stack and change switchMask on the fly, that would be best. Igor, any thoughts?

/be

Comment 8

[timeless]

i'm not sure i understand the suggestion from your second paragraph.

consider a stupid approach:

jsd has two threads, the proxy thread which runs on main, and the engine thread

main| initializes jsd-debugging-engine-thread
jsde| creates an event loop
main| enters js
main| js trips on a jsd proxy hook
main| jsd proxies to the engine thread
jsde| clears the hook because it knows that spidermonkey isn't busy
jsde| returns for proxy call
main| jsd proxy returns
main| js resumes

keep in mind that jsd today using per runtime hooks (i'd like to research fixing this about a week after i get all of the jsd related crashes resolved).

I believe that the corba jsd impl might actually work something like what i've described above, although I haven't really looked at that code seriously.

assuming my example above is legal (and i'm fairly certain it is) [and yes, i've already complained to you about the fact that you can't atomically set/clear a debug hook/data pair, we'll ignore that for now],

can your proposal work given that i've changed a runtime hook from a thread which isn't really running much js?

I suppose you could try to lock each running context and update switchMask, but the locking alone is bad, ignoring the fact that there are dozens of cx's in the runtime that you'd have to iterate over. you could cheat and iterate over threads and then loop through each thread's cx list, but that's still lots of locking and iterating.

Comment 9

[timeless]

Attachment: lazy approach

please just commit this as "[e-mail]" (no real name).

i haven't been able to push any patches into the tree in a couple of weeks, the colors are too complicated.

i think we need to put this into place for the time being.

we should do this with enough spacing so we can see the perf penalty on all trees. and i believe that for the time being we should accept that we must live with whatever that penalty is.

you're welcome to try to fix it some other way, but until something better is conceived, i believe i've managed to convince jorendorff and some others that correctness [= not crashing] is important for the time being.

my goal atm is to get jsapi/jsdapi stable enough that i can try to chase the two-three regressions which have caused venkman to be very hard to use on trunk.

note that i'm on sick leave this week and need to rest, so arguing over things really isn't something i should be doing.

thanks for listening.

Comment 10

[Brendan Eich [:brendan]]

Comment on attachment 353311 [details] [diff] [review]
lazy approach

Absolutely not.

/be

Comment 11

[Brendan Eich [:brendan]]

Timeless, you don't get to demand any patch gets in just because you can't do a better patch. Don't worry about arguing, just get better.

Igor, could you take this, please?

/be

Comment 12

[Igor Bukanov]

(In reply to comment #10)
> (From update of attachment 353311 [details] [diff] [review])
> Absolutely not.

Why "absolutely"? What if the performance impact is essentially 0?

Comment 13

[Igor Bukanov]

(In reply to comment #7)
> If we could reach down into the interpreter(s) active on the stack and change
> switchMask on the fly, that would be best.

That would require moving switchMask into JSStackFrame and taking a lock on any change of JSContext.fp which maybe even more expensive then checking for the interrupt flag.

Comment 14

[Igor Bukanov]

Attachment: fix

The reason for the bug is that the code assumes in the interpreter that switchMask == 0 and !cx->debugHooks->interruptHandler means that we recording. This is wrong. 

To fix that the patch adds a separated check for the recorder. To compensate for that extra check I added a separated switch for the tracer to avoid bloating the primary switch with unused bytecodes and to avoid useless jumps. I also removed JSOP_INTERRUPT as this pseudobytecode just bloats various jump tables with unused entries.

Comment 15

[Brendan Eich [:brendan]]

(In reply to comment #12)
> (In reply to comment #10)
> > (From update of attachment 353311 [details] [diff] [review] [details])
> > Absolutely not.
> 
> Why "absolutely"? What if the performance impact is essentially 0?

It's not zero (you have evidence to the contrary), and it's wrong in principle to add overhead to all the thin opcodes that do not call anything that might change the hook.

But thanks to your analysis, we don't have to debate this more. Comments on the patch after another response to a bug comment:

(In reply to comment #13)
> (In reply to comment #7)
> > If we could reach down into the interpreter(s) active on the stack and change
> > switchMask on the fly, that would be best.
> 
> That would require moving switchMask into JSStackFrame and taking a lock on any
> change of JSContext.fp which maybe even more expensive then checking for the
> interrupt flag.

On IA32 there are too few registers for switchMask to not be in stack memory. It's not obvious moving it to be addressed by fp (or regs?) is worse.

I do not agree that a lock would be needed, however. The debugger API has never been synchronized in the interpreter. If a debugger wants to use a separate thread it has to do its own locking "behind" the debugger hook APIs.

/be

Comment 16

[Brendan Eich [:brendan]]

Comment on attachment 353705 [details] [diff] [review]
fix

jsopcode.tbl must be dense and zero-based, there are many consumers of it who should not now be obligated to pad an initial entry in any initialized array derived from it.

Can we move JSOP_NOP back down to opcode 0 and do something else to avoid interrupt overhead on Windows?

/be

Comment 17

[Igor Bukanov]

(In reply to comment #15)
> I do not agree that a lock would be needed, however. The debugger API has never
> been synchronized in the interpreter. If a debugger wants to use a separate
> thread it has to do its own locking "behind" the debugger hook APIs.

The interpreter and the rest of the runtime changes JSContext.fp freely without any locking with the memory backing fp allocated/freed as necessary. Some of those cases the debugger may track via the call hooks and do parallel locking to make sure that accessing JSContext.fp from another thread is OK but in general it is not feasible with the current code.

Comment 18

[Igor Bukanov]

Attachment: fix v2

The new fix uses -1 for the interrupt case avoiding the need to have 1-based opcodes.

Comment 19

[Igor Bukanov]

Attachment: fix v3

The last version of the patch would not link due to missing UNUSED(135) in jstracer.cpp

Comment 20

[Igor Bukanov]

Attachment: fix v3b

The new version of the patch removes stalled comments and fixes indentation.

Comment 21

[Igor Bukanov]

Attachment: fix v4

The new version of the patch fixes GCC warning about the incomplete switch that handles recording calls.

Comment 22

[Brendan Eich [:brendan]]

Comment on attachment 353849 [details] [diff] [review]
fix v4

>       do_op:
>-        switchOp = op & switchMask;
>+        switchOp = intN(op) | switchMask;
>       do_switch:
>         switch (switchOp) {
>-#endif /* !JS_THREADED_INTERP */
>+          case -1:
>+# ifdef JS_TRACER
>+            /* Check if this is a synthetic interrupt for recording. */
>+            if (TRACE_RECORDER(cx)) {
>+                switch (op) {
>+                  default: break;
>+#  define OPDEF(x,val,name,token,length,nuses,ndefs,prec,format)               \
>+    case x: RECORD(x); break;

Nit: would read a bit better in spite of the # hair if the case x: ... line were indented to start in the same column as the default: break.

>+#  include "jsopcode.tbl"
>+#  undef OPDEF
>+                }
>+            }
>+# endif /* !JS_TRACER */
> 
>-          BEGIN_CASE(JSOP_INTERRUPT)
>+#endif /* !JS_THREADED_INTERP */
>           {
>             JSTrapHandler handler;
> 
>@@ -2865,20 +2872,13 @@ js_Interpret(JSContext *cx)

So now we optionally record, then dispatch the interrupt handler if set, then do the op -- this is different from the old !JS_THREADED_INTERP code, and from any version of JS_THREADED_INTERP code. When recording we aren't debugging -- only one jumpTable at a time. So this seems wrong -- what am I missing?

Looks good otherwise, I'll r+ with a fix to record/redispatch instead of record/interrupt/redispatch.

/be

Comment 23

[Igor Bukanov]

(In reply to comment #22)
> When recording we aren't debugging -- only one jumpTable at a time. So this seems wrong -- what am I missing?

What is wrong with calling the interrupt hook during recording? And if this is wrong then the tracing must be abandoned before calling the interrupt hook.

Comment 24

[Igor Bukanov]

After looking at this I realized that the recording jump table leads to useless code bloat given the amount of code in the RECORD macro. Since that is completely dominated by js_MonitorRecording, the performance gains during the recording to avoid 2-3 extra ifs is not worth the extra code bloat caused by repeated expansion of the RECORD macro.

Comment 25

[Igor Bukanov]

Attachment: fix v5

The new patch avoids code bloat through the RECORD macro by using the interrupt table/switchMask both for interrupts and the tracer. This shrinks the optimized build of jsinterp.cpp from 87756 down to 63976 bytes with no influence on SunSpider benchmarks. 

With the patch a set interrupt handler aborts recording.

Comment 26

[Brendan Eich [:brendan]]

(In reply to comment #23)
> (In reply to comment #22)
> > When recording we aren't debugging -- only one jumpTable at a time. So this seems wrong -- what am I missing?
> 
> What is wrong with calling the interrupt hook during recording?

The JS_THREADED_INTERP target platforms simply do not do that. We don't want different behavior for !JS_THREADED_INTERP.

If you mean why aren't we willing to let someone debug while the recorder is on, we do not support debugging traced code. The trace recorder models trace execution. Therefore we shouldn't debug while recording.

Debugging could use a dedicated interpreter if we could generate one without any trace-recording hooks, and if code size were not a concern. Since we do not want such bloat, we have to share -- but we don't want recording and debugging at the same time.

> And if this is
> wrong then the tracing must be abandoned before calling the interrupt hook.

Timeless and graydon had some experience that showed debugging would keep tracing from being attempted, but that may have been only for JS_THREADED_INTERP.

/be

Comment 27

[Brendan Eich [:brendan]]

(In reply to comment #24)
> After looking at this I realized that the recording jump table leads to useless
> code bloat given the amount of code in the RECORD macro. Since that is
> completely dominated by js_MonitorRecording, the performance gains during the
> recording to avoid 2-3 extra ifs is not worth the extra code bloat caused by
> repeated expansion of the RECORD macro.

Have you verified this? Jesse is testing -j vs. no -j performance using fuzzing and recording time hurts. Others have filed bugs on thin loops still showing the cost.

It's true the js_MonitorRecording overhead is more than the inline costs, but maybe that's a bug to fix, not compound.

I don't see js_AbortRecordingImpl in the latest patch -- does it compile? Also it would be best to rebase off of tracemonkey tip, to sync up to the apply and imacro changes.

/be

Comment 28

[Brendan Eich [:brendan]]

Now that we are generating imacros from imacros.jsasm, the last two places that need hand-coding should be automated if it's not too hard. One of these is the RECORD_ARGS compile-time-constant if (x == JSOP_...) big bad condition. Making that a runtime condition would allow us to use table lookup. Probably the right thing, but I'm still leery of using js_MonitorRecording costs to justify yet more recording overhead.

We're more willing to burn code size (which also should be measured -- how bad was it, really?) than runtime, in general.

/be

Comment 29

[Brendan Eich [:brendan]]

I shouldn't have asked in a parenthetical: be great to see code size savings from doing away with RECORD* macrology.

/be

Comment 30

[Igor Bukanov]

Attachment: fix v6

In the newer patch I moved the detection of imacro opcodes into the opcode switch so the flag detection code becomes the compiler-time constant. I also moved the switch itself into js_MonitorRecording so the compiler can inline all those one-liner record methods. In total this decreased the size of js executable by 25K (about 3%) without any influence on sunspider results.

Comment 31

[Igor Bukanov]

(In reply to comment #27)
> I don't see js_AbortRecordingImpl in the latest patch -- does it compile?

js_AbortRecordingImpl is implemented where js_AbortRecording is in the code without the patch. With the patch depending on DEBUG

  js_AbortRecording(JSContext* cx, const char* reason) 

expans either to

  js_AbortRecordingImpl(JSContext* cx) 

or

  js_AbortRecordingImpl(JSContext* cx, const char* reason)

Comment 32

[Brendan Eich [:brendan]]

Comment on attachment 353907 [details] [diff] [review]
fix v6

I like it -- thanks for rolling with the comments here. Nits below.

>+JS_REQUIRES_STACK JSMonitorRecordStatus

May as well burn three more chars and spell the enum JSMonitorRecordingStatus.

>+    /* We set endIMacro inside switch to resolve it at compile time either to
>+       include imacro support, or exclude it altogether for this particular x. */
>+    bool flag, endIMacro;

s/endIMacro/callingIMacro/g

>+    if (endIMacro && cx->fp->flags & JSFRAME_IMACRO_START) {

Overparenthesize bitwise & against && (GCC precplaint may not apply here, but it's house style and avoids similar combos that do get you a precplaint).

Curious to get gal's thoughts, but he is on a 12 hour flight. I'll let him catch up by bugmail. r=me with nits picked. Thanks again,

/be

Comment 33

[Igor Bukanov]

Attachment: fix v7

Here is a patch update to address the nits and to sync with the TM trunk.

Comment 34

[Igor Bukanov]

Attachment: fix v8

Apparently GCC is not smart enough to optimize the recording switch on its own so the new version changes monitorRecording to use explicit gotos inside the switch. It saves additional 400 bytes and one if check per imacro at runtime.

I also made monitorRecording a class member for lesser source complexity.

Comment 35

[Brendan Eich [:brendan]]

Comment on attachment 353971 [details] [diff] [review]
fix v8

Looks good. How's it test on the thin loops? See bug 449524 and others.

/be

Comment 36

[Igor Bukanov]

(In reply to comment #35)
> (From update of attachment 353971 [details] [diff] [review])
> Looks good. How's it test on the thin loops? See bug 449524 and others.

The patch does not affect the branch monitoring code: the same TRACING_ENABLED(cx) && js_MonitorLoopEdge sequence is called. Only recording is affected. There, given that the patch saves there 25K of code for the price effective price of the extra switch, on CPU's without much TLB/code cache it could be a win. But it is really hard to measure since the rest of monitorLoop complexity hides any performance differences.

Comment 37

[Igor Bukanov]

landed in tm - http://hg.mozilla.org/tracemonkey/rev/f13e2a2a5d66

Comment 38

[Igor Bukanov]

Nominating for 1.9.1 as the bug crashes the browser with JS debugger enabled.

Comment 39

[Igor Bukanov]

Attachment: fix v8

I made bad typo when merging the patch with unary imacro support changes. Here is the diff against the previous version:

@@ -3897,7 +3897,7 @@ TraceRecorder::monitorRecording(JSOp op)
         case x:                                                               \
           flag = record_##x();                                                \
           if (x == JSOP_ITER || x == JSOP_NEXTITER || x == JSOP_APPLY ||      \
-              JSOP_IS_BINARY(x) || x == JSOP_IS_UNARY(op)) {                  \
+              JSOP_IS_BINARY(x) || JSOP_IS_UNARY(op)) {                       \
               goto imacro;                                                    \
           }                                                                   \
         break;
-

Comment 40

[Igor Bukanov]

I ralanded the fixed patch to tm - http://hg.mozilla.org/tracemonkey/rev/605fd1985d05


Now 
  for (var x = 0; x < 2; ++x) { +[]; }} 
no longer crashes.

Comment 41

[Igor Bukanov]

Attachment: fix v9

Fixing yet another (this time harmless typo as op is x in the code below):

@@ -3897,7 +3897,7 @@ TraceRecorder::monitorRecording(JSOp op)
         case x:                                                               \
           flag = record_##x();                                                \
           if (x == JSOP_ITER || x == JSOP_NEXTITER || x == JSOP_APPLY ||      \
-              JSOP_IS_BINARY(x) || JSOP_IS_UNARY(op)) {                       \
+              JSOP_IS_BINARY(x) || JSOP_IS_UNARY(x)) {                       \
               goto imacro;                                                    \
           }                                                                   \

Comment 42

[Igor Bukanov]

relanded again in tm - http://hg.mozilla.org/tracemonkey/rev/7dd3e4a4ceff

Comment 43

[Robert Sayre]

Thank you for the quick patch. merged to mc.

Comment 44

[Igor Bukanov]

Recording the regression dependancy

Comment 45

[Igor Bukanov]

Attachment: fix for 191 (inclusiding the fix for bug 472049)

The patch is the original fix landed in TM plus the patch from bug 472049 fixing the regression.

Comment 46

[Robert Sayre]

http://hg.mozilla.org/releases/mozilla-1.9.1/rev/68a5bb8c0e9f