482743 - Bytecode execution tracing broken for JS_THREADED_INTERP

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Jim Blandy :jimb]

In js/src/shell/js.cpp, the 'Tracing' function gives an error message when JS_THREADED_INTERP is defined, but this isn't really necessary --- most of the changes needed to make it work on threaded interpreters are there already.

Also, it would be nice if we could send traces to somewhere other than stderr.

Comment 1

[Jim Blandy :jimb]

Attachment: Bug 482743: Fix up bytecode execution tracing. Allow tracing to file.

Comment 2

[Igor Bukanov]

Comment on attachment 366835 [details] [diff] [review]
Bug 482743: Fix up bytecode execution tracing.  Allow tracing to file.

>diff --git a/js/src/jscntxt.cpp b/js/src/jscntxt.cpp

>@@ -2534,7 +2543,7 @@ js_Interpret(JSContext *cx)
> # ifdef DEBUG
> #  define TRACE_OPCODE(OP)  JS_BEGIN_MACRO                                    \
>                                 if (cx->tracefp)                              \
>-                                    js_TraceOpcode(cx, len);                  \
>+                                    js_TraceOpcode(cx);                       \
>                             JS_END_MACRO

Preexisting nit: drop OP argument from the macro.

Also currently for threaded interpreter js_TraceOpcode is executed for each JS_BEGIN_CASE while for the non-threaded interpreter it is executed on each advance of regs.pc. This is not the same as the code uses in few places DO_OP(op) with op != *pc to share the code. It would be nice to fix this. My preference is that tracing only on pc changes removes unnecessary noise. 

>diff --git a/js/src/shell/js.cpp b/js/src/shell/js.cpp

> static JSBool
> Tracing(JSContext *cx, JSObject *obj, uintN argc, jsval *argv, jsval *rval)
> {
>     switch (JS_TypeOfValue(cx, argv[0])) {
...
>+      case JSTYPE_NUMBER: {
>+        JSBool bval = (JSVAL_IS_INT(argv[0])
>+                       ? JSVAL_TO_INT(argv[0])
>+                       : (jsint) *JSVAL_TO_DOUBLE(argv[0]));
>+        if (bval)
>+            file = stderr;
>+        else
>+            file = NULL;
...
>+      case JSTYPE_BOOLEAN: {
>+        JSBool bval = JSVAL_TO_BOOLEAN(argv[0]);
>+        if (bval)
>+            file = stderr;
>+        else
>+            file = NULL;
>         break;

Either merge the code for NUMBER and BOOLEN cases into single block using JS_ValueToBoolean, or remove the NUMBER case altogether so in future the number could be used for something sensible.

Comment 3

[Brendan Eich [:brendan]]

Comment on attachment 366835 [details] [diff] [review]
Bug 482743: Fix up bytecode execution tracing.  Allow tracing to file.

>+      case JSTYPE_NUMBER: {
>+        JSBool bval = (JSVAL_IS_INT(argv[0])
>+                       ? JSVAL_TO_INT(argv[0])
>+                       : (jsint) *JSVAL_TO_DOUBLE(argv[0]));

No need to parenthesize ?: against = in house style. C's operator precedence is right in this case.

/be

Comment 4

[Jim Blandy :jimb]

(In reply to comment #3)
> No need to parenthesize ?: against = in house style. C's operator precedence is
> right in this case.

Emacs doesn't know how to indent the subsequent lines unless the parens are there.  Could we relax house style on this point?

Comment 5

[Brendan Eich [:brendan]]

(In reply to comment #4)
> (In reply to comment #3)
> > No need to parenthesize ?: against = in house style. C's operator precedence is
> > right in this case.
> 
> Emacs doesn't know how to indent the subsequent lines unless the parens are
> there.  Could we relax house style on this point?

Sure, although vim weakness never stopped house style from prevailing... ;-)

/be

Comment 6

[Igor Bukanov]

Comment on attachment 366835 [details] [diff] [review]
Bug 482743: Fix up bytecode execution tracing.  Allow tracing to file.

a patch update is needed

Comment 7

[Jim Blandy :jimb]

Attachment: Bug 482743: Fix up bytecode execution tracing. Allow tracing to file.

Revised per Igor's suggestions.  I kept the 'op' argument to TRACE_OPCODE, because I found I needed it to make traces accurate.  I compared traces from threaded and non-threaded interpreters (running SunSpider's tagcloud): they are the same.

---

js_TraceOpcode: Remember the last bytecode we traced explicitly,
instead of subtracting 'len' from regs.pc, which isn't reliable.
Decline to trace values in script prologues (between 'code' and
'main').  Decline to walk off the bottom of the stack when the 'last
bytecode' is misleading.  Flush the stream after each bytecode.

Use the TRACE_OPCODE macro in both threaded and non-threaded
interpreters.  Take care to make threaded and non-threaded
interpreters produce the same traces.

In the shell's 'tracing' function, use JS_ValueToBoolean to recognize
all sorts of booleans, and treat a string as the name of a file to
write the trace to.

Comment 8

[Brendan Eich [:brendan]]

I added tracing of this kind so long ago, who knew there'd be a trace-based JIT? Could we rename this to something else without much trouble? Not sure what name to use, though. Probably not logging (too low-level/generic). Thoughts?

/be

Comment 9

[Jim Blandy :jimb]

That collision irked me, too.  Opcode dribble file?  tap?  journal?  trail?  chronicle?

Comment 10

[Mike Shaver (:shaver emeritus)]

OPCODE_DISPATCH_MONITOR? OPCODE_DISPATCH_LOG?

Comment 11

[Igor Bukanov]

Comment on attachment 370027 [details] [diff] [review]
Bug 482743: Fix up bytecode execution tracing.  Allow tracing to file.

>Bug 482743: Fix up bytecode execution tracing.  Allow tracing to file.
>
>js_TraceOpcode: Remember the last bytecode we traced explicitly,
>instead of subtracting 'len' from regs.pc, which isn't reliable.
>Decline to trace values in script prologues (between 'code' and
>'main').  Decline to walk off the bottom of the stack when the 'last
>bytecode' is misleading.  Flush the stream after each bytecode.
>
>Use the TRACE_OPCODE macro in both threaded and non-threaded
>interpreters.  Take care to make threaded and non-threaded
>interpreters produce the same traces.
>
>In the shell's 'tracing' function, use JS_ValueToBoolean to recognize
>all sorts of booleans, and treat a string as the name of a file to
>write the trace to.
>
>diff --git a/js/src/jscntxt.cpp b/js/src/jscntxt.cpp
>--- a/js/src/jscntxt.cpp
>+++ b/js/src/jscntxt.cpp
>@@ -1557,7 +1557,7 @@ js_ReportValueErrorFlags(JSContext *cx, 
> 
> #if defined DEBUG && defined XP_UNIX
> /* For gdb usage. */
>-void js_traceon(JSContext *cx)  { cx->tracefp = stderr; }
>+void js_traceon(JSContext *cx)  { cx->tracefp = stderr; cx->tracePrevOp = JSOP_LIMIT; }
> void js_traceoff(JSContext *cx) { cx->tracefp = NULL; }
> #endif
> 
>diff --git a/js/src/jscntxt.h b/js/src/jscntxt.h
>--- a/js/src/jscntxt.h
>+++ b/js/src/jscntxt.h
>@@ -921,6 +921,7 @@ struct JSContext {
>     char                *lastMessage;
> #ifdef DEBUG
>     void                *tracefp;
>+    JSOp                tracePrevOp;
> #endif
> 
>     /* Per-context optional error reporter. */
>diff --git a/js/src/jsinterp.cpp b/js/src/jsinterp.cpp
>--- a/js/src/jsinterp.cpp
>+++ b/js/src/jsinterp.cpp
>@@ -2045,12 +2045,11 @@ js_DoIncDec(JSContext *cx, const JSCodeS
> #ifdef DEBUG
> 
> JS_STATIC_INTERPRET JS_REQUIRES_STACK void
>-js_TraceOpcode(JSContext *cx, jsint len)
>+js_TraceOpcode(JSContext *cx)
> {
>     FILE *tracefp;
>     JSStackFrame *fp;
>     JSFrameRegs *regs;
>-    JSOp prevop;
>     intN ndefs, n, nuses;
>     jsval *siter;
>     JSString *str;
>@@ -2060,10 +2059,16 @@ js_TraceOpcode(JSContext *cx, jsint len)
>     JS_ASSERT(tracefp);
>     fp = cx->fp;
>     regs = fp->regs;
>-    if (len != 0) {
>-        prevop = (JSOp) regs->pc[-len];
>-        ndefs = js_CodeSpec[prevop].ndefs;
>-        if (ndefs != 0) {
>+
>+    /* Operations in prologues don't produce interesting values, and
>+       js_DecompileValueGenerator isn't set up to handle them anyway.  */

Nit: SM comment multi-line style is:

/*
 * foo
 * bar
 */

>+    if (cx->tracePrevOp != JSOP_LIMIT && regs->pc >= fp->script->main) {
>+        ndefs = js_CodeSpec[cx->tracePrevOp].ndefs;

Use the very recently introduced js_GetStackDefs to properly deal with opcodes defining variable number of stack slots like JSOP_ENTERBLOCK (for them JSCodeSpec.ndefs is -1).

>+        /* If there aren't that many elements on the stack, then 
>+           we have probably entered a new frame, and printing output
>+           would just be misleading.  */

Nit: comment style + blank line before comment. Or put the comments before ndefs.

>+        if (ndefs != 0 &&
>+            ndefs < regs->sp - fp->slots) {
>             for (n = -ndefs; n < 0; n++) {
>                 char *bytes = js_DecompileValueGenerator(cx, n, regs->sp[n],
>                                                          NULL);
>@@ -2108,6 +2113,10 @@ js_TraceOpcode(JSContext *cx, jsint len)
>         }
>         fprintf(tracefp, " @ %u\n", (uintN) (regs->sp - StackBase(fp)));
>     }
>+    cx->tracePrevOp = op;
>+
>+    /* It's nice to have complete traces when debugging a crash.  */
>+    fflush(tracefp);
> }
> 
> #endif /* DEBUG */
>@@ -2534,6 +2543,30 @@ js_Interpret(JSContext *cx)
> # define JS_EXTENSION_(s) s
> #endif
> 
>+# ifdef DEBUG
>+    /*
>+     * We call this macro from BEGIN_CASE in threaded interpreters,
>+     * and before entering the switch in non-threaded interpreters.
>+     * However, reaching such points doesn't mean we've actually
>+     * fetched an OP from the instruction stream: some opcodes use
>+     * 'op=x; DO_OP()' to let another opcode's implementation finish
>+     * their work, and many opcodes share entry points with a run of
>+     * consecutive BEGIN_CASEs.
>+     * 
>+     * Take care to trace OP only when it is the opcode fetched from
>+     * the instruction stream, so the trace matches what one would
>+     * expect from looking at the code.  (We do omit POPs after SETs;
>+     * unfortunate, but not worth fixing.)
>+     */
>+#  define TRACE_OPCODE(OP)  JS_BEGIN_MACRO                                    \
>+                                if (JS_UNLIKELY(cx->tracefp != NULL) &&       \
>+                                    (OP) == *regs.pc)                         \
>+                                    js_TraceOpcode(cx);                       \
>+                            JS_END_MACRO
>+# else
>+#  define TRACE_OPCODE(OP)  (void)0

Pre-existing nit: blank between the cast and zero.

>@@ -1859,13 +1859,8 @@ DisassWithSrc(JSContext *cx, JSObject *o
> static JSBool
> Tracing(JSContext *cx, JSObject *obj, uintN argc, jsval *argv, jsval *rval)
>+      case JSTYPE_BOOLEAN: {
>+        JSBool bval;
>+        if (! JS_ValueToBoolean(cx, argv[0], &bval))

Nit: no blank between ! and the condition.

>+            goto bad_argument;
>+        if (bval)
>+            file = stderr;
>+        else
>+            file = NULL;

Nit: use ?, not if, for dense code.

>         break;
>-      case JSTYPE_BOOLEAN:
>-        bval = JSVAL_TO_BOOLEAN(argv[0]);
>+      }
>+      case JSTYPE_STRING: {
>+        char *name = JS_GetStringBytes(JSVAL_TO_STRING(argv[0]));
>+        file = fopen(name, "w");
>+        if (! file) {

Nit: no blank between ! and the condition.

Comment 12

[Jim Blandy :jimb]

Attachment: Bug 482743: Fix up bytecode execution tracing. Allow tracing to file.

Comment 13

[Igor Bukanov]

Comment on attachment 370279 [details] [diff] [review]
Bug 482743: Fix up bytecode execution tracing.  Allow tracing to file.

nice!

Comment 14

[Jim Blandy :jimb]

http://hg.mozilla.org/tracemonkey/rev/777e5882b1c3

Comment 15

[Jim Blandy :jimb]

Attachment: Bug 482743: Compute opcode stack usage correctly.

If we have js_GetStackDefs, then obviously we should be using js_GetStackUses as well.

Comment 16

[Igor Bukanov]

Comment on attachment 370441 [details] [diff] [review]
Bug 482743: Compute opcode stack usage correctly.

>Bug 482743: Compute opcode stack usage correctly.
>
>diff --git a/js/src/jsinterp.cpp b/js/src/jsinterp.cpp
>--- a/js/src/jsinterp.cpp
>+++ b/js/src/jsinterp.cpp
>@@ -2105,7 +2105,7 @@ js_TraceOpcode(JSContext *cx)
>                     regs->pc - fp->script->code,
>                     JS_FALSE, tracefp);
>     op = (JSOp) *regs->pc;
>-    nuses = js_CodeSpec[op].nuses;
>+    nuses = js_GetStackUses(&js_CodeSpec[op], op, regs->pc);
>     if (nuses != 0) {
>         for (n = -nuses; n < 0; n++) {
>             char *bytes = js_DecompileValueGenerator(cx, n, regs->sp[n],

Note to self: we should also have a form of js_GetStackUses that would get cs from js_CodeSpec like in:

inline js_GetStackUses(op, pc) { return js_GetStackUses(&js_CodeSpec[op], op, pc); }

taking advantage of function overloading. But this is for another bug.

Comment 17

[Jim Blandy :jimb]

http://hg.mozilla.org/tracemonkey/rev/189632a20253

Comment 18

[Jeff Walden [:Waldo]]

(In reply to comment #16)

Fodder for bug 475091.

Comment 19

[Robert Sayre]

http://hg.mozilla.org/releases/mozilla-1.9.1/rev/98e8a59deb72