497999 - Add context-specific output to TraceVis

Status: RESOLVED FIXED

(Core :: JavaScript Engine, enhancement)

Description

[Mark Steele]

TraceVis pokes the hole, this bug is about adding valves and spigots.
The goal is to turn on trace monitoring independently for specific (sets of) scripts and direct it to the right place.

Comment 1

[David Mandelin [:dmandelin]]

Excellent idea. Browser runs are very hard to understand without this--I've been using ad hoc filtering techniques but never made anything particularly reusable, or usable, for that matter.

Comment 2

[Mark Steele]

Attachment: per-script tracevis object wrapper

Experiment to expose live tracevis data (to an about:jit extension, for example).

An Ethogram is created per page.
For all scripts in a page, call addScript.
getNextEvent will return oldest unread event for all matching scripts, otherwise null.

Comment 3

[Mark Steele]

Attachment: tracevis wrapper WIP 2. cleans up properly now.

Added code to clean out added scripts on finalize.
Just realized this may cause problems with multiple instances monitoring the same script URL.

Comment 4

[Jason Orendorff [:jorendorff]]

Comment on attachment 385935 [details] [diff] [review]
tracevis wrapper WIP 2. cleans up properly now.

>+/* Collect states here and distribute to matching buffers, if any */

Singular "buffer", right?

>+inline uintN
>+jstv_Lineno(JSContext *cx, JSStackFrame *fp)

This doesn't seem to be used anywhere, and the event object gets .lineno=0.

>+    p = (EthogramEventBuffer *) malloc(sizeof(EthogramEventBuffer));

Need a null check after this. If you use JS_malloc instead, it'll call JS_ReportOutOfMemory for you in case of error.

>+    jsval filenames = OBJECT_TO_JSVAL(p->filenames);
>+    if (!JS_SetProperty(cx, obj, "filenames", &filenames))
>+        return JS_FALSE;

I think you should use JS_DefineProperty and the JSPROP_READONLY|JSPROP_PERMANENT flags to prevent this from being dislodged: you're relying on it to keep the array from being GC'd.

>+    char * script_file;
>+
>+    if(traceVisScriptTable) {

Style nits: no space after the *, but a space after `if`.

Comment 5

[Jason Orendorff [:jorendorff]]

Comment on attachment 385935 [details] [diff] [review]
tracevis wrapper WIP 2. cleans up properly now.

Sorry, I didn't mean to r+ this yet.  Patch looks good, but I have more comments, and I'd like to review it again with fixes.

Stay tuned.

Comment 6

[Mark Steele]

Attachment: updated per comments

Should reflect comments now.
Also got rid of per-event lineno AND filename.

Comment 7

[David Mandelin [:dmandelin]]

Drive-by comments:

- The Ethogram* structs are C-style. Even JSString is now a C++-style class with members and everything, so I'd recommend doing that here, too.

- A hash table lookup per log record is potentially expensive. In TraceVis, I strove to make recording cheap to minimize perturbation of overall performance. It might be better to add an ethogram pointer to JSScript, and then move it to a global list when the script is destroyed. 

- Clever name, "ethogram". But please define it in a comment for non-ethologists like me.

Comment 8

[Jason Orendorff [:jorendorff]]

>+/* XXX could use defaults here */

Yep! Please do use the defaults...

js_InitEthogram
>+        traceVisScriptTable = JS_NewHashTable(8, JS_HashString, js_compare_strings,
>+                                         NULL, &egtbl_alloc_ops, NULL);

...by passing NULL instead of &egtbl_alloc_ops here.

In ethogram_getNextEvent:
>+    if (p->readpos == p->writepos)
>+        *rval = JSVAL_NULL;

Need to `return JS_TRUE;` here.

In js_InitEthogram:
+    if (!traceVisScriptTable) {
+        traceVisScriptTable = JS_NewHashTable(8, JS_HashString, js_compare_strings,
+                                         NULL, &egtbl_alloc_ops, NULL);
+   
+    ethogram_prototype = JS_InitClass(cx, JS_GetGlobalObject(cx), NULL, &ethogram_class,
+                                      ethogram_construct, 0, ethogram_props, ethogram_methods,
+                                      NULL, NULL);
+    }

I think the indentation is correct--JS_InitClass should be outside the if
block--but the braces are wrong!

ethogram_prototype is not used again, so just remove it.  (We initialize many
"global" objects, so a global ethogram_prototype would be meaningless.)

Instead of declaring an empty ethogram_props, you can just pass NULL here.

>+static int
>+js_compare_strings(const void *k1, const void *k2)

Believe it or not, static functions aren't supposed to get the js_ prefix
according to house style.  There are several mistakes in jstracer.cpp.

>+static JSClass ethogram_class = {
>+    "Ethogram",
>+    JSCLASS_HAS_PRIVATE,
>+    JS_PropertyStub, JS_PropertyStub, /* add/del */
>+    JS_PropertyStub, JS_PropertyStub, /* get/set */

Those comments are superfluous; format it like js_ObjectClass in jsobj.cpp.

>+    JS_EnumerateStub, JS_ResolveStub, JS_ConvertStub,
>+    ethogram_finalize,
>+    NULL, NULL, NULL,
>+    NULL, /* ethogram_construct, */

Maybe one reason this is such a common false start, apart from the misleading
field name `JSClass.construct`, is that it was misdocumented, with a bogus
example and everything. Fixed now:
  https://developer.mozilla.org/En/SpiderMonkey/JSAPI_Reference/JSClass

Please remove this comment and use JSCLASS_NO_OPTIONAL_MEMBERS here.

In ethogram_addScript:
>+    if (!filename)
>+        return JS_FALSE;

A C++ callback generally should not return JS_FALSE unless an error has been
reported. Here an error may or may not have been reported.

>+JS_FRIEND_API(void)
>+js_StoreTraceVisState(JSStackFrame *fp, TraceVisState s, TraceVisExitReason r)
>+{
>+    JSHashEntry *he, **hep;
>+    JSHashNumber hash;
>+    char * script_file;
>+
>+    if(traceVisScriptTable) {
>+        script_file = jstv_Filename(fp);
>+        hash = JS_HashString(script_file);
>+        hep = JS_HashTableRawLookup(traceVisScriptTable, hash, script_file);
>+        /* update event buffer, flag if overflowed */
>+        he = *hep;

To save a few lines, I think you can instead just
  JS_ASSERT(traceVisScriptTable);
and then initialize all these variables as you declare them.

>+            p->buf[p->writepos].s = (TraceVisState) s;
>+            p->buf[p->writepos].r = (TraceVisExitReason) r;

There's no need for these casts, right?

>+            p->buf[p->writepos].t = 0;

Is this intended to be a timestamp?

Comment 9

[Jason Orendorff [:jorendorff]]

The firebug guys (or at least robcee) seemed interested in getting this kind of information, but of course it would have to be cheap enough that we could turn it on in normal builds.  I'm not sure what the right approach is.

Comment 10

[Mark Steele]

Attachment: update per comment #7 and comment #8

re: comment #7
The JSString change happened while I was working on this patch. I didn't see that coming. I was trying to follow house style. If that's the new way forward I can do that. I left them alone for this patch.

I WAS expecting the hash lookup to be quite a bit more expensive than the carefully crafted inlines, but I was gambling that it would be fast enough for now.
Early on, I did think about adding something to JSScript like you suggest, but my goal was to get something minimally invasive working with the general functionality first. The thought of augmenting core structs/classes without proving out the idea scared me.
That said, the calls and hash lookups don't happen until |initEthogram| is called at *runtime* (by an extension). Overhead should be minimal until then.
That suggests there should also be a matching "unhook" call to destroy the hash table and let the conditional fail (in js_LogTraceVisState).
Added a comment with the definition at the top of the block. :)

re: comment #8
Updated per comments. Thanks for the doc update. As you could tell, I *was* confused by the optional constructor callback in the docs. My years-old memory of JS_InitClass was foggy.

Silently return on empty addScript now.

Updated per style and other comments, but I remembered that 
if (traceVisScriptTable)
already happens in the caller. ASSERT would be bad because the table doesn't exist until |initEthogram| turns things on (avoid lookups completely when not even using the extension, see above). 

Cleaned up the vestigial casts/brace weirdness.
rdtsc was missing because I thought I needed an extra step there on Linux.

Comment 11

[Mark Steele]

Attachment: convert to C++-style structs per comment #7 and add shutdownEthogram

Comment 12

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

(In reply to comment #9)
> The firebug guys (or at least robcee) seemed interested in getting this kind of
> information, but of course it would have to be cheap enough that we could turn
> it on in normal builds.  I'm not sure what the right approach is.

yeah, very-much interested. Having the ability to instrument optimized code would be interesting and potentially give JS coders insight into what's happening under the covers. Hopefully giving them the ability to write better code.

thanks for the CC!

the idea I mentioned to jorendorff last time I saw him was just getting line numbers for JS script that ran under optimization. Presumably, these would be updated overtime as the application runs and tracing runs over different sections of the code.

If these structs lived someplace associated with a page context so Firebug could look them up and highlight the optimized lines on debugger activation, that would be very neat.

Maybe a tracevis service?

Comment 13

[David Mandelin [:dmandelin]]

(In reply to comment #12)
> the idea I mentioned to jorendorff last time I saw him was just getting line
> numbers for JS script that ran under optimization. Presumably, these would be
> updated overtime as the application runs and tracing runs over different
> sections of the code.

Recording line numbers of traces that are recorded would be cheap. I expect it could be enabled in release builds with no significant cost.

But it's more useful to know line numbers of traces that are run. And that's potentially more expensive, especially because ideally you'd want to know the number of times each trace run. Recording that exactly would have a noticeable cost. A sampling approach could do it without cost when turned off, but would be more work to implement.

I should also mention that the sampling approach can more-or-less be done right now using VTune, but I don't suppose most web developers use VTune.

Comment 14

[Mark Steele]

Attachment: fix timestamps, add event filename & lineno

Comment 15

[Mark Steele]

Attachment: add |getAllEvents| to make things less painful

return an array with all events.
polling was just too brutal, though I was surprised how long I could get by without this.

Comment 16

[Mark Steele]

Attachment: port patch (and tracevis) to windows

port to windows. I'm not sure this works.

Comment 17

[Leandro Lameiro]

If this patch works for windows, we can close https://bugzilla.mozilla.org/show_bug.cgi?id=499509

Comment 18

[Mark Steele]

Attachment: fix windows port

Fix for dumb omission, found by Leandro Lameiro. was causing a crash on windows only.
Unrelated to that, I confirmed the ported patch fixes bug 499509.
The timing resolution is pretty bad on Ethogram on windows, but it works.

Comment 19

[Jason Orendorff [:jorendorff]]

Mostly tiny tiny nits:

>+struct EthogramEventBuffer {

Please change this to:

    class EthogramEventBuffer {
    private:

(JSString is a struct because it's exposed in C headers as a struct, and some compilers don't like mixing, but it's really not idiomatic C++.)

>+    inline bool isEmpty() {

`inline` is redundant here. Please delete it.

>-            js_EnterTraceVisState(S_RECORD, R_NONE);                          \
>-    JS_END_MACRO
>+            js_EnterTraceVisState(cx, S_RECORD, R_NONE);                 \
>+    JS_END_MACRO
>+#else /* !JS_THREADED_INTERP */
>+#define MONITOR_BRANCH_TRACEVIS                                               \
>+    JS_BEGIN_MACRO                                                            \
>+        js_EnterTraceVisState(cx, S_RECORD, R_NONE);                     \
>+    JS_END_MACRO

Line up the backslashes!

Non-nit: why bother with initEthogram and shutdownEthogram?  The reason we have those functions for e.g. Shark is so that either C++ or JS code can start and stop profiling.  But it seems like here we could just go ahead and call JS_InitClass for ethogram_class in nsJSContext::InitClasses.

Actually the duplication of code among shell/js.cpp, nsJSContext, and mozJSComponentLoader in this regard could easily be fixed by adding a new JS_InitInstrumentationClasses(cx, obj) API to go along with JS_InitStandardClasses. If you don't want to do that in this patch, a followup bug would be fine.

This leaves all the TraceVis stuff in place. Do we really want both?

Comment 20

[David Mandelin [:dmandelin]]

(In reply to comment #19)
> This leaves all the TraceVis stuff in place. Do we really want both?

I'm not sure exactly what this means. We definitely want the ability to create log files for offline processing at minimal cost, especially for shell usage. As long as that requirement is satisfied, I think we would not be losing anything.

Comment 21

[Mark Steele]

(In reply to comment #19)

Yeah, I wouldn't say this replaces the offline TraceVis stuff. This stuff alone doesn't even do as much as TraceVis does without bits to consume it and make a log file. At that point the extra machinery is a bit wasteful unless you're going to do something more with the data.
Different goals. (That's also why I was calling it something other than TraceVis.)

The separate init/shutdown calls were to push the decision to participate to the extension. Maybe the overhead of scanning the empty table doesn't matter, but that's what it's for. If this thing gels, I guess it'd be fine to put it in the centralized setup stuff. The JS_InitInstrumentationClasses way might be better.

Comment 22

[Mark Steele]

Attachment: nit whacked

Comment 23

[Jason Orendorff [:jorendorff]]

Comment on attachment 390292 [details] [diff] [review]
nit whacked

Thanks. Looks good.

Comment 24

[David Mandelin [:dmandelin]]

Attachment: Rebased version of 'nit whacked'

Comment 25

[David Mandelin [:dmandelin]]

Pushed to TM as a294d0c376bc.

Comment 26

[David Mandelin [:dmandelin]]

Mark, is there a bug filed for that cool about:jit feature, or are you packaging that in some other way?

Comment 27

[Mark Steele]

(In reply to comment #26)
> Mark, is there a bug filed for that cool about:jit feature, or are you
> packaging that in some other way?

There's no bug filed for the UI side of this. I put what I had up at http://code.google.com/p/ethogram/ while waiting for the patch to settle & land, but I've had to catch up on other things.
Also needed to better understand exactly what it needed to show and how.