506149 - jsdService should allow off/on/off/on

Status: NEW

(Core :: General, defect)

Description

[John J. Barton]

Here are some observations by boris concerning jsd overhead. (>my replies)

The synposis: jsd.on() cause 10% overhead 100% of the time js is running;
Firebug calls jsd.on() in common use cases.

--------
I was just profiling a testcase in a build that happened to have Firebug
installed (but not enabled on that page!), and noticed that 10% of the testcase
execution time was under jsd_ObjectHook.  It looks like it does
locking-and-stuff on every single object allocation.

I looked around, and the hook is installed if someone calls jsdService::On.

Is Firebug calling this during startup or something?  If so, why? 
-------
>
> No, in fact we try to turn object trace off. Of course that does not mean we succeed.
...
>            jsd.on();

OK, so you _are_ calling it during startup.  Is it possible to stop doing that?

>            jsd.flags |= DISABLE_OBJECT_TRACE;

All that does is keep us from walking the stack on every allocation looking for
the script and line number that caused it.  We still track every single object
allocation, create a new object representing it, mess with hashtables, lock
things, etc, etc.

See http://mxr.mozilla.org/mozilla-central/source/js/jsd/jsd_obj.c#114 and
http://mxr.mozilla.org/mozilla-central/source/js/jsd/jsd_obj.c#160

I have no idea whether all that work jsd does there is really needed if the
DISABLE_OBJECT_TRACE flag is set, and in particular whether other parts of jsd
depend on jsdc->objectsTable.  Looks like at least jsdValue::GetObjectValue
does.
--------

> and not disabled with pause() or the flag setting?

The flag setting just makes the hook less expensive; the time it takes would
presumably be even more than the 10% I saw if you didn't set the flag.

jsdService::On sets up all sorts of hooks that pause() does not remove. 
Specifically, everything that is set up by jsd_DebuggerOnForUser:

207     JS_SetNewScriptHookProc(jsdc->jsrt, jsd_NewScriptHookProc, jsdc);
208     JS_SetDestroyScriptHookProc(jsdc->jsrt, jsd_DestroyScriptHookProc,
jsdc);
209     JS_SetDebuggerHandler(jsdc->jsrt, jsd_DebuggerHandler, jsdc);
210     JS_SetExecuteHook(jsdc->jsrt, jsd_TopLevelCallHook, jsdc);
211     JS_SetCallHook(jsdc->jsrt, jsd_FunctionCallHook, jsdc);
212     JS_SetObjectHook(jsdc->jsrt, jsd_ObjectHook, jsdc);
213     JS_SetThrowHook(jsdc->jsrt, jsd_ThrowHandler, jsdc);
214     JS_SetDebugErrorHook(jsdc->jsrt, jsd_DebugErrorHook, jsdc);
-----

> Does pause/unpause affect this work?

No.


> We could experiment with replacing pause/unpause with off/on, but I assumed that the whole reason pause/unpause existed was because on/off was expensive or otherwise undesirable.

I would assume that off/on means you lose information about any
already-allocated objects, for example.  I have no idea whether that's ok in
your case.
----
> But as far as I understand these 'hooks' are just C shells for JS hooks. 

They're not.  For example, here's jsd_ObjectHook:

160 jsd_ObjectHook(JSContext *cx, JSObject *obj, JSBool isNew, void *closure)
161 {
162     JSDObject* jsdobj;
163     JSDContext* jsdc = (JSDContext*) closure;
164
165     if( ! jsdc || ! jsdc->inited )
166         return;
167
168     JSD_LOCK_OBJECTS(jsdc);
169     if(isNew)
170     {
171         jsdobj = _createJSDObject(jsdc, cx, obj);
172         TRACEOBJ(jsdc, jsdobj, 0);
173     }
174     else
175     {
176         jsdobj = jsd_GetJSDObjectForJSObject(jsdc, obj);
177         if( jsdobj )
178         {
179             TRACEOBJ(jsdc, jsdobj, 1);
180             _destroyJSDObject(jsdc, jsdobj);
181         }
182     }
183     JSD_UNLOCK_OBJECTS(jsdc);
184 }

There's no js hook here; this is all just bookkeeping work for use elsewhere.

Similarly, jsd_NewScriptHookProc will create a new JSDScript from tehe given
JSScript no matter what, even if there's no JS new script hook to call.  See
http://mxr.mozilla.org/mozilla-central/source/js/jsd/jsd_scpt.c#570

> It sounds like no matter what JS value the ObjectHook had, the overhead would be in place?

There's no JS ObjectHook that I can see (which makes sense, since the
jsd_ObjectHook is called at a point at which calling JS is unsafe).

Comment 1

[John J. Barton]

Attachment: Hacked version of Firebug with off/on appled at pause/unpause

Comment 2

[John J. Barton]

The attached version of firebug attempts to use jsd.off()/jsd.on() to control jsd. As far as I can tell, the jsd.on() does not re-instate the scriptHook that Firebug relies on. 

1. Install the XPI, 
2. open firefox, 
3. http://www.google.com/firefox?client=firefox-a&rls=org.mozilla:en-US:official, 
4. open firebug.
5. open the Firebug Tracing console from Firebug Icon menu (upper left).
6. option ACTIVATION
Reload the page from #3.
The trace should show jsd off and then later on. But the script panel has no scripts.  FBS_CREATION will show that no calls to onScriptCreated occur.

Comment 3

[John J. Barton]

Attachment: log from sequence in comment #2

Comment 4

[John J. Barton]

So I just discovered that jsd.pause() does not deactive onScriptCreated/onScriptDestroyed. 

Since Firebug 1.4 relies on pause() to "suspend" when the user moves to a page where they *do not* want Firebug, this means that Firebug continues to run its script analysis even when suspended. I guess it only builds its tables of functions and sets breakpoints on outer functions. But in at least on case it breaks web pages, the yahoo home page in http://code.google.com/p/fbug/issues/detail?id=2110

Comment 5

[Boris Zbarsky [:bzbarsky]]

Yeah, sounds about right.

Comment 6

[Boris Zbarsky [:bzbarsky]]

Note that I still mean to dig into why off/on doesn't work unless robcee gets there first.

Comment 7

[Rob Campbell [:rc] (:robcee)]

haven't had a chance to do any digging here. Was looking at some other stuff, but am bumping priority on this.

Comment 8

[Boris Zbarsky [:bzbarsky]]

OK, so there are a few things going on here:

1)  jsdservice doesn't deal correctly with the script hook being set before on() is called.  This is just a bug.  Firebug seems to work around it by doing on(), then setting the script hook, but it's pretty simple to fix this.  Patch will do that.

2)  With that fixed, things don't work for a simple reason.  The sequence of calls jsd service sees is:

  Pause()
  SetScriptHook(NULL)
  Off()
  On()
  SetScriptHook(something)
  UnPause()

But SetScriptHook does nothing other than just storing the hook if the debugger is paused.  So we never set up the hook correctly.  I have no idea whether the right fix is to make pause/unpause take down and reinstate the script hook, like the various other hooks, or whether SetScriptHook should not be checking mPauseLevel.  I'm going to assume the latter in the patch I attach, but someone who actually understands the "right" behavior of the script hook should make that call.

Comment 9

[Boris Zbarsky [:bzbarsky]]

That said, if I make those changes I see jsd calling firebug's onScriptCreated.  I do NOT see scripts in the script panel; I don't know why.

Comment 10

[Boris Zbarsky [:bzbarsky]]

Attachment: Patch to try

Comment 11

[John J. Barton]

(In reply to comment #9)
> That said, if I make those changes I see jsd calling firebug's onScriptCreated.
>  I do NOT see scripts in the script panel; I don't know why.

Could be a lot of reasons. If you set FBTrace :
FBS_CREATION: will tell you if the url was filtered out
FBS_SRCUNITS: will tell if the scripts were routed correctly in fbs
FBS_FINDDEBUGGER: will tell if the jsdIScript was assigned to the Firebug context
FBS_BP: will tell you if the BP for analysis was hit
SOURCEFILES: will tell how the scripts are grouped for display

Beware FBS_CREATION: if you forget to turn it off before exit, you will have a nice wait the next restart.

(or you can wait for me to succeed at building trunk again)

Comment 12

[Boris Zbarsky [:bzbarsky]]

> FBS_CREATION: will tell you if the url was filtered out

I really can't make sense of the output of this stuff.

Please catch me on irc if you're having trouble building m-c.  It really shouldn't be a problem to build it!

Comment 13

[John J. Barton]

(In reply to comment #12)
> > FBS_CREATION: will tell you if the url was filtered out
> 
> I really can't make sense of the output of this stuff.

Yes, I was thinking my post did not make sense.

> Please catch me on irc if you're having trouble building m-c.  It really
> shouldn't be a problem to build it!

 I'll try again today.

Comment 14

[Rob Campbell [:rc] (:robcee)]

I have a build and am just setting up a test environment for it. I'll report back...

Comment 15

[Rob Campbell [:rc] (:robcee)]

I'd love to see a diff of what was changed in the attached and modified Firebug so I could apply this to svn.

I applied the changes from a19-off/on/components/firebug-service.js to svn/firebug1.5 and this seems to work. Script dropdown is getting populated and filled up on reload. Maybe john fixed some of the other outlying stuff in debugger.js?

so, should we land these patches and give it a try?

Comment 16

[Rob Campbell [:rc] (:robcee)]

anything more to add than this?

Index: components/firebug-service.js
===================================================================
--- components/firebug-service.js	(revision 3882)
+++ components/firebug-service.js	(working copy)
@@ -978,11 +978,10 @@
             if (jsd.pauseDepth == 0)  // marker only UI in debugger.js
             {
                 jsd.pause();
-                 fbs.unhookScripts();
-                 /* jsd.off();
+                fbs.unhookScripts();
+                jsd.off();
                 if (FBTrace.DBG_ACTIVATION)
                     FBTrace.sysout("fbs.pause turned jsd OFF,  depth "+jsd.pauseDepth);
-                    */
             }
             dispatch(clients, "onJSDDeactivate", [jsd, "pause depth "+jsd.pauseDepth]);
         }
@@ -1010,7 +1009,6 @@
                 if (FBTrace.DBG_ACTIVATION)
                     FBTrace.sysout("fbs.unpause turned on jsd and hooked scripts pauseDepth:"+jsd.pauseDepth);
             }
-            fbs.hookScripts();
             var depth = jsd.unPause();
             if (FBTrace.DBG_ACTIVATION)
                 FBTrace.sysout("fbs.unPause depth "+depth+" jsd.isOn: "+jsd.isOn);

Comment 17

[John J. Barton]

(In reply to comment #15)
> so, should we land these patches and give it a try?

I'd say no because 1) I think the primary problem here, the 10% overhead, is explained by the onScriptCreated calls, and 2) we are doing a lot of guessing.

I think it makes more sense to repeat the profiling with a version of Firebug that unhooks the onScriptCreated so we know if we still have a problem. Then wait on the on/off until we know a bit more.

Comment 18

[Boris Zbarsky [:bzbarsky]]

Just to be clear, at the moment there's no way to unhook onScriptCreated without calling jsdservice.off().

Comment 19

[John J. Barton]

Ok, there are two layers then, one is in jsd and requires jsd.off(). If we've called jsd.on() we have some overhead. 

But there is a second layer, the code for our onScriptCreated handler. It can be disconnected. That is what I did in 1.5a20. I believe this second layer, our handler, will account for most of the overhead.

Comment 20

[Rob Campbell [:rc] (:robcee)]

repeating my above tests with a hacked version of Firebug that removes calls to pause and unpause, removes the hookScripts call in fbs.enableDebugger() and replaces sends to pause and unpause with enable/disableDebugger seems to work, albeit with some strange performance characteristics when debugging. Could have just been the site. This is probably overkill, but I wanted to get us down to simple on and off for the purposes of testing disabled performance.

I'm going to rebuild an optimized build and rerun my talos test on it to see if this helps performance at all.

Comment 21

[Boris Zbarsky [:bzbarsky]]

> I believe this second layer, our handler, will account for most of the overhead.

Oh, that's quite possible, yes.  But we should be aiming for no overhead at all, if possible.  Imo.  Even just 0.5% overhead when not running is not really called for if we can avoid it.

Comment 22

[Rob Campbell [:rc] (:robcee)]

I tried running some comparisons with patched and unpatched versions of this but ran into an unexpected inconsistency: Optimization levels were, I think, the cause of some fairly divergent numbers. I used Namoroka a1 for my unpatched version and a home-built Minefield for the patched version. My hacked version of Firebug with senders of pause() and hookScripts() removed looked like it was far more expensive than the actual version.

I need to retest with saner builds, i.e., builds from the same machine and settings.