494864 - make nanojit debug output easier to follow

Status: VERIFIED FIXED

(Tamarin Graveyard :: Baseline JIT (CodegenLIR), defect)

Description

[Julian Seward [:jseward]]

User-Agent:       Mozilla/5.0 (X11; U; Linux x86_64; en-US; rv:1.9.0.10) Gecko/2009042700 SUSE/3.0.10-1.1 Firefox/3.0.10
Build Identifier: JS shell from http://hg.mozilla.org/tracemonkey


First pass at making TRACEMONKEY=debug Nanojit output nicer:

* print an obvious preamble-postamble bracketing in ::compile, so as
  to make obvious the units of translation

* print markers to important top-level events in ::compile, so as to
  make the sequence of actions (somewhat) clearer

* print the incoming LIR in ::compile

* change how the results of liveness analysis are printed, so as to
  not require such a wide window for viewing

* make it clear where the aggregated assembly output starts and ends

* fix space leak, in which all the strings in assm->asmOutput (viz,
  the entire assembly output) were never freed

* when printing assembly, left-align output nicely so as to make it
  prettier

* when printing i386 assembly, print the instruction name in a
  %-4s field, so as to make the operands of the majority of the
  instructions line up nicely

Known deficiencies:

* Because the reader pipeline avoids generating actual representations
  of the intermediate LIR stages, it is currently not possible to
  print out the LIR after mangling by each stage in the pipeline.
  (AFAIK ...)

* [pre-existing bug]
  TRACEMONKEY=verbose build/js -j trace-test.js 

  eventually segfaults somewhere around the 3200th call to ::compile,
  whilst printing LIR.  I believe this is due to a bogus entry in the
  LirNameMap associated with the buffer.

  An unmodified checkout of http://hg.mozilla.org/tracemonkey made
  090526, 0928 CEST, segfaults in the same place.


Reproducible: Always

Comment 1

[Julian Seward [:jseward]]

Includes various other small changes to make the output easier to
read, and to require a less-wide terminal.

Comment 2

[Julian Seward [:jseward]]

Attachment: Patch to tidy up debug printing

Depends on (and, in this case simply includes) the second patch in #494157.

Comment 3

[Julian Seward [:jseward]]

Attachment: Self contained version of previous patch that is suitable for review

Comment 4

[Julian Seward [:jseward]]

Re Comment #3, note that you first have to apply the patch in
#494157.

Comment 5

[Julian Seward [:jseward]]

Here's an example bit of output.  It literally only nice-fies stuff
printed from within js/src/nanojit, so in particular output from jstracer.cpp
et al is unchanged.


================================================================================
=== BEGIN [call number 1] LIR::compile(0x81cb778, 0x81d9f18)
===

=== Incoming LIR:
===
  00: start
  01: state = param 0 ecx
  02: 0
  03: sp = ld state[0]
  04: 4
  05: rp = ld state[4]
  06: 8
  07: cx = ld state[8]
  08: 12
  09: eos = ld state[12]
  10: 16
  11: eor = ld state[16]
  12: -32
  13: $callee0 = ld sp[-32]
  14: -24
  15: $this0 = ld sp[-24]
  16: -16
  17: ld1 = ld sp[-16]
  18: $foo.s = i2f ld1
  19: -8
  20: ld2 = ld sp[-8]
  21: $foo.i = i2f ld2
  22: ld3 = ld cx[0]
  23: eq1 = eq ld3, 0
  24: xf1: xf eq1 -> pc=0x81d9e1d imacpc=(nil) sp+0 rp+0
  25: sti sp[0] = ld1
  26: sti sp[8] = ld2
  27: add1 = add ld1, ld2
  28: ov1 = ov add1
  29: xt1: xt ov1 -> pc=0x81d9e24 imacpc=(nil) sp+16 rp+0
  30: i2f1 = i2f add1
  31: sti sp[0] = add1
  32: sti sp[-16] = add1
  33: sti sp[0] = add1
  34: sti sp[8] = ld2
  35: #40240000:0 /* 10 */
  36: 10
  37: sti sp[16] = 10
  38: sub1 = sub ld2, 10
  39: ov2 = ov sub1
  40: xt2: xt ov2 -> pc=0x81d9e31 imacpc=(nil) sp+24 rp+0
  41: i2f2 = i2f sub1
  42: sti sp[8] = sub1
  43: fmul1 = fmul i2f1, i2f2
  44: stqi sp[0] = fmul1
  45: stqi sp[-16] = fmul1
  46: stqi sp[0] = fmul1
  47: #3FF00000:0 /* 1 */
  48: 1
  49: sti sp[8] = 1
  50: js_DoubleToInt32_1 = js_DoubleToInt32 ( fmul1 )
  51: lsh1 = lsh js_DoubleToInt32_1, 1
  52: i2f3 = i2f lsh1
  53: sti sp[0] = lsh1
  54: sti sp[-16] = lsh1
  55: sti sp[0] = lsh1
  56: sti sp[8] = 1
  57: rsh1 = rsh lsh1, 1
  58: i2f4 = i2f rsh1
  59: sti sp[0] = rsh1
  60: sti sp[-16] = rsh1
  61: add2 = add ld2, 1
  62: ov3 = ov add2
  63: xt3: xt ov3 -> pc=0x81d9e49 imacpc=(nil) sp+0 rp+0
  64: i2f5 = i2f add2
  65: sti sp[0] = ld2
  66: sti sp[-8] = add2
  67: sti sp[0] = add2
  68: #408F4000:0 /* 1000 */
  69: 1000
  70: sti sp[8] = 1000
  71: lt1 = lt add2, 1000
  72: xf2: xf lt1 -> pc=0x81d9e53 imacpc=(nil) sp+16 rp+0
  73: sti sp[-16] = rsh1
  74: sti sp[-8] = add2
  75: loop

=== Results of liveness analysis:
===
  Live instruction count 35, total 65, max pressure 5
  Side exits 1
  Showing LIR instructions with live-after variables

  start                          start1
  state = param 0 ecx            state
  sp = ld state[0]               state sp
  rp = ld state[4]               state sp rp
  cx = ld state[8]               state sp cx
  eos = ld state[12]             state sp cx eos
  eor = ld state[16]             state sp cx eor
  $callee0 = ld sp[-32]          state sp cx $callee0
  $this0 = ld sp[-24]            state sp cx $this0
  ld1 = ld sp[-16]               state sp cx ld1
  ld2 = ld sp[-8]                state sp cx ld1 ld2
  ld3 = ld cx[0]                 state sp ld1 ld2 ld3
  sti sp[0] = ld1                state sp ld1 ld2
  sti sp[8] = ld2                state sp ld1 ld2
  add1 = add ld1, ld2            state sp ld2 add1
  i2f1 = i2f add1                state sp ld2 add1 i2f1
  sti sp[-16] = add1             state sp ld2 add1 i2f1
  sti sp[0] = add1               state sp ld2 i2f1
  sti sp[8] = ld2                state sp ld2 i2f1
  sti sp[16] = 10                state sp ld2 i2f1
  sub1 = sub ld2, 10             state sp ld2 i2f1 sub1
  i2f2 = i2f sub1                state sp ld2 i2f1 i2f2
  fmul1 = fmul i2f1, i2f2        state sp ld2 fmul1
  stqi sp[-16] = fmul1           state sp ld2 fmul1
  js_DoubleToInt32_1 = js_DoubleToInt32 ( fmul1 )
                                 state sp ld2 js_DoubleToInt32_1
  lsh1 = lsh js_DoubleToInt32_1, 1
                                 state sp ld2 lsh1
  rsh1 = rsh lsh1, 1             state sp ld2 rsh1
  sti sp[-16] = rsh1             state sp ld2 rsh1
  add2 = add ld2, 1              state sp rsh1 add2
  sti sp[-8] = add2              state sp rsh1 add2
  sti sp[0] = add2               state sp rsh1 add2
  sti sp[8] = 1000               state sp rsh1 add2
  sti sp[-16] = rsh1             state sp add2
  sti sp[-8] = add2              state
  loop                           state

=== Translating LIR fragments into assembly:
=== -- Compile trunk 0x81d9f18: begin
=== -- Compile trunk 0x81d9f18: end

=== Aggregated assembly output: BEGIN
===
  00f7fbff50   [prologue]
  00f7fbff50   push edi
  00f7fbff51   push esi
  00f7fbff52   push ebx
  00f7fbff53   push ebp
  00f7fbff54   push ebp
  00f7fbff55   mov  ebp,esp
  00f7fbff57   [frag entry]
  00f7fbff57   sub  esp,8
  ## patching branch at 00f7fbfff3 to 00f7fbff5a
  00f7fbff5a:
  ## compiling trunk 0x81d9f18
      state = param 0 ecx
      sp = ld state[0]
      cx = ld state[8]
      ld1 = ld sp[-16]
      ld2 = ld sp[-8]
      ld3 = ld cx[0]
      eq1 = eq ld3, 0
      xf1: xf eq1 -> pc=0x81d9e1d imacpc=(nil) sp+0 rp+0
  00f7fbff5a   mov  -4(ebp),ecx       ecx(state)
  00f7fbff5d   mov  edi,ecx           ecx(state)
  00f7fbff5f   mov  esi,0(edi)        edi(state)
  00f7fbff61   mov  ecx,8(edi)        esi(sp) edi(state)
  00f7fbff64   mov  eax,-16(esi)      ecx(cx) esi(sp) edi(state)
  00f7fbff67   mov  ebx,-8(esi)       eax(ld1) ecx(cx) esi(sp) edi(state)
  00f7fbff6a   mov  ecx,0(ecx)        eax(ld1) ecx(cx) ebx(ld2) esi(sp) edi(state)
  00f7fbff6c   test ecx,ecx           eax(ld1) ecx(ld3) ebx(ld2) esi(sp) edi(state)
  00f7fbff6e   jne  0xf7fb9fbb        eax(ld1) ebx(ld2) esi(sp) edi(state)
  ----------------------------------- ## BEGIN exit block (LIR_xt|LIR_xf)
  00f7fb9fbb:
  ## merging registers (intersect) with existing edge
  00f7fb9fbb   mov  ecx,-4(ebp)
  00f7fb9fbe   mov  eax,-134475308
  00f7fb9fc3   mov  esp,ebp
  00f7fb9fc5:
  00f7fb9fc5   jmp  0xf7fbfff8
  ----------------------------------- ## END exit block 0xf7fc11f4
      sti sp[0] = ld1
      sti sp[8] = ld2
      add1 = add ld1, ld2
      ov1 = ov add1
      xt1: xt ov1 -> pc=0x81d9e24 imacpc=(nil) sp+16 rp+0
  00f7fbff74   mov  0(esi),eax        eax(ld1) ebx(ld2) esi(sp) edi(state)
  00f7fbff76   mov  8(esi),ebx        eax(ld1) ebx(ld2) esi(sp) edi(state)
  00f7fbff79   add  eax,ebx           eax(ld1) ebx(ld2) esi(sp) edi(state)
  00f7fbff7b   jo   0xf7fb9fca        eax(add1) ebx(ld2) esi(sp) edi(state)
  ----------------------------------- ## BEGIN exit block (LIR_xt|LIR_xf)
  00f7fb9fca:
  ## merging registers (intersect) with existing edge
  00f7fb9fca   mov  ecx,-4(ebp)
  00f7fb9fcd   mov  eax,-134475116
  00f7fb9fd2   mov  esp,ebp
  00f7fb9fd4:
  00f7fb9fd4   jmp  0xf7fbfff8
  ----------------------------------- ## END exit block 0xf7fc12c4
      i2f1 = i2f add1
      sti sp[-16] = add1
      sti sp[0] = add1
      sti sp[8] = ld2
      sti sp[16] = 10
      sub1 = sub ld2, 10
      ov2 = ov sub1
      xt2: xt ov2 -> pc=0x81d9e31 imacpc=(nil) sp+24 rp+0
  00f7fbff81   cvtsi2sd xmm0,eax      eax(add1) ebx(ld2) esi(sp) edi(state)
  00f7fbff85   mov  -16(esi),eax      eax(add1) ebx(ld2) esi(sp) edi(state) xmm0(i2f1)
  00f7fbff88   mov  0(esi),eax        eax(add1) ebx(ld2) esi(sp) edi(state) xmm0(i2f1)
  00f7fbff8a   mov  8(esi),ebx        ebx(ld2) esi(sp) edi(state) xmm0(i2f1)
  00f7fbff8d   mov  16(esi),10        ebx(ld2) esi(sp) edi(state) xmm0(i2f1)
  00f7fbff94   mov  eax,ebx           ebx(ld2) esi(sp) edi(state) xmm0(i2f1)
  00f7fbff96   sub  eax,10            ebx(ld2) esi(sp) edi(state) xmm0(i2f1)
  00f7fbff99   jo   0xf7fb9fd9        eax(sub1) ebx(ld2) esi(sp) edi(state) xmm0(i2f1)
  ----------------------------------- ## BEGIN exit block (LIR_xt|LIR_xf)
  00f7fb9fd9:
  ## merging registers (intersect) with existing edge
  00f7fb9fd9   mov  ecx,-4(ebp)
  00f7fb9fdc   mov  eax,-134474812
  00f7fb9fe1   mov  esp,ebp
  00f7fb9fe3:
  00f7fb9fe3   jmp  0xf7fbfff8
  ----------------------------------- ## END exit block 0xf7fc13f4
      i2f2 = i2f sub1
      fmul1 = fmul i2f1, i2f2
      stqi sp[-16] = fmul1
      js_DoubleToInt32_1 = js_DoubleToInt32 ( fmul1 )
      lsh1 = lsh js_DoubleToInt32_1, 1
      rsh1 = rsh lsh1, 1
      sti sp[-16] = rsh1
      add2 = add ld2, 1
      ov3 = ov add2
      xt3: xt ov3 -> pc=0x81d9e49 imacpc=(nil) sp+0 rp+0
  00f7fbff9f   cvtsi2sd xmm1,eax      eax(sub1) ebx(ld2) esi(sp) edi(state) xmm0(i2f1)
  00f7fbffa3   mulsd xmm0,xmm1        ebx(ld2) esi(sp) edi(state) xmm0(i2f1) xmm1(i2f2)
  00f7fbffa7   movq -16(esi),xmm0     ebx(ld2) esi(sp) edi(state) xmm0(fmul1)
  00f7fbffac   sub  esp,8             ebx(ld2) esi(sp) edi(state) xmm0(fmul1)
  00f7fbffaf   sub  esp,8             ebx(ld2) esi(sp) edi(state) xmm0(fmul1)
  00f7fbffb2   movq 0(esp),xmm0       ebx(ld2) esi(sp) edi(state) xmm0(fmul1)
  00f7fbffb7   call js_DoubleToInt32  ebx(ld2) esi(sp) edi(state)
  00f7fbffbc   add  esp,8             ebx(ld2) esi(sp) edi(state)
  00f7fbffbf   mov  ecx,edi           ebx(ld2) esi(sp) edi(state)
  00f7fbffc1   mov  edi,eax           eax(js_DoubleToInt32_1) ecx(state) ebx(ld2) esi(sp)
  00f7fbffc3   shl  edi,1             ecx(state) ebx(ld2) esi(sp) edi(js_DoubleToInt32_1)
  00f7fbffc6   sar  edi,1             ecx(state) ebx(ld2) esi(sp) edi(lsh1)
  00f7fbffc9   mov  -16(esi),edi      ecx(state) ebx(ld2) esi(sp) edi(rsh1)
  00f7fbffcc   add  ebx,1             ecx(state) ebx(ld2) esi(sp) edi(rsh1)
  00f7fbffcf   jo   0xf7fb9fe8        ecx(state) ebx(add2) esi(sp) edi(rsh1)
  ----------------------------------- ## BEGIN exit block (LIR_xt|LIR_xf)
  00f7fb9fe8:
  00f7fb9fe8   mov  eax,-134474316
  00f7fb9fed   mov  esp,ebp
  00f7fb9fef:
  00f7fb9fef   jmp  0xf7fbfff8
  ----------------------------------- ## END exit block 0xf7fc15e4
      sti sp[-8] = add2
      sti sp[0] = add2
      sti sp[8] = 1000
      lt1 = lt add2, 1000
      xf2: xf lt1 -> pc=0x81d9e53 imacpc=(nil) sp+16 rp+0
  00f7fbffd5   mov  -8(esi),ebx       ecx(state) ebx(add2) esi(sp) edi(rsh1)
  00f7fbffd8   mov  0(esi),ebx        ecx(state) ebx(add2) esi(sp) edi(rsh1)
  00f7fbffda   mov  8(esi),1000       ecx(state) ebx(add2) esi(sp) edi(rsh1)
  00f7fbffe1   cmp  ebx,1000          ecx(state) ebx(add2) esi(sp) edi(rsh1)
  00f7fbffe7   jnl  0xf7fb9ff4        ecx(state) ebx(add2) esi(sp) edi(rsh1)
  ----------------------------------- ## BEGIN exit block (LIR_xt|LIR_xf)
  00f7fb9ff4:
  00f7fb9ff4   mov  eax,-134474028
  00f7fb9ff9   mov  esp,ebp
  00f7fb9ffb:
  00f7fb9ffb   jmp  0xf7fbfff8
  ----------------------------------- ## END exit block 0xf7fc16f4
      sti sp[-16] = rsh1
      sti sp[-8] = add2
      1
      loop
  00f7fbffed   mov  -16(esi),edi      ecx(state) ebx(add2) esi(sp) edi(rsh1)
  00f7fbfff0   mov  -8(esi),ebx       ecx(state) ebx(add2) esi(sp)
  00f7fbfff3:
  00f7fbfff3   jmp  (nil)
  00f7fbfff8   [epilogue]
  00f7fbfff8   mov  esp,ebp
  00f7fbfffa   pop  ebp
  00f7fbfffb   pop  ebp
  00f7fbfffc   pop  ebx
  00f7fbfffd   pop  esi
  00f7fbfffe   pop  edi
  00f7fbffff   ret
===
=== Aggregated assembly output: END

===
=== END [call number 1] LIR::compile(0x81cb778, 0x81d9f18)
================================================================================

Comment 6

[Rick Reitmaier]

The output looks nice.

Is there a way to retain outputAddr?  I think the consensus a while back was not to print out addresses by default but instead set outputAddr=true in Native.h if you wanted it.  I'm not married to either approach but I liked the flexibility.

Also is nj_printf unique to SM?  I think the latest tamarin is using VMPI_printf or somesuch.

Finally, in the 'Incoming LIR' section, do the leading numbers 'n:' have any relevance?  If each instruction is on a unique line no references are made to the numbers further down does it make sense to print them?

Comment 7

[Julian Seward [:jseward]]

> Is there a way to retain outputAddr?

I like seeing the addresses, not only to see the advancement in IPs,
but also because they form a neat left margin, somehow.  So it's partly
an aesthetic thing.  Can reinstate if you want.

> Also is nj_printf unique to SM?

Yes, was introduced in #494157.

> Finally, in the 'Incoming LIR' section, do the leading numbers 'n:' have any
> relevance?  

No relevance; but I find it makes it easier to navigate when scrolling
up/down through large blocks (gives some approximate idea of where
I am).  I am planning to extend the printing to print the LIR after each
stage in a LirReader pipeline, which will make it more verbose, in which
case the extra navigational help becomes more important.

Comment 8

[Julian Seward [:jseward]]

Another observation / query, really: the x86 assembly output 
uses the AT&T syntax conventions for amodes etc, eg const(reg).
However, when it comes to the question of whether the destination
is on the left or the right, it appears to use the Intel convention
(on the left).  This is a confusing hybrid, for people used to the
AT&T syntax.

But it doesn't even seem to be consistent about dst-on-the-left.
Consider this:

      state = param 0 ecx
      sp = ld state[0]
      cx = ld state[8]

which must compile to three loads.  What is shown is:

  00f7fbdf5a   mov  -4(ebp),ecx  ecx(state)         // DST on right
  00f7fbdf5d   mov  edi,ecx      ecx(state)         // DST on left
  00f7fbdf5f   mov  esi,0(edi)   edi(state)         // DST on left
  00f7fbdf61   mov  ecx,8(edi)   esi(sp) edi(state) // DST on left

Did I miss something?

Comment 9

[Rick Reitmaier]

Actually i think dest is on left for the first instruction; its storing ecx to mem.

Comment 10

[Julian Seward [:jseward]]

Here's a revised version of the patch, which introduces a new
LirFilter -- ReverseLister.  When debug printing, a ReverseLister
is inserted between each stage of the reader pipeline.  As a 
result it's possible to print the LIR after each transformation
stage.

Patch also reinstates outputAddr switching as per Comment #6.

Comment 11

[Julian Seward [:jseward]]

Attachment: Revised version of patch, capable of printing LIR after each reader pipe stage

Comment 12

[Julian Seward [:jseward]]

Example output from new patch attached as Comment #11,
with outputAddr = true:

================================================================================
=== BEGIN [call number 1] LIR::compile(0x81ce778, 0x81dcf18)
===
=== Translating LIR fragments into assembly:
=== -- Compile trunk 0x81dcf18: begin

=== BEGIN Initial LIR ===
  00: start
  01: state = param 0 ecx
  02: 0
  03: sp = ld state[0]
  04: 4
  05: rp = ld state[4]
  06: 8
  07: cx = ld state[8]
  08: 12
  09: eos = ld state[12]
  10: 16
  11: eor = ld state[16]
  12: -32
  13: $callee0 = ld sp[-32]
  14: -24
  15: $this0 = ld sp[-24]
  16: -16
  17: ld1 = ld sp[-16]
  18: $foo.s = i2f ld1
  19: -8
  20: ld2 = ld sp[-8]
  21: $foo.i = i2f ld2
  22: ld3 = ld cx[0]
  23: eq1 = eq ld3, 0
  24: xf1: xf eq1 -> pc=0x81dce1d imacpc=(nil) sp+0 rp+0
  25: sti sp[0] = ld1
  26: sti sp[8] = ld2
  27: add1 = add ld1, ld2
  28: ov1 = ov add1
  29: xt1: xt ov1 -> pc=0x81dce24 imacpc=(nil) sp+16 rp+0
  30: i2f1 = i2f add1
  31: sti sp[0] = add1
  32: sti sp[-16] = add1
  33: sti sp[0] = add1
  34: sti sp[8] = ld2
  35: #40240000:0 /* 10 */
  36: 10
  37: sti sp[16] = 10
  38: sub1 = sub ld2, 10
  39: ov2 = ov sub1
  40: xt2: xt ov2 -> pc=0x81dce31 imacpc=(nil) sp+24 rp+0
  41: i2f2 = i2f sub1
  42: sti sp[8] = sub1
  43: fmul1 = fmul i2f1, i2f2
  44: stqi sp[0] = fmul1
  45: stqi sp[-16] = fmul1
  46: stqi sp[0] = fmul1
  47: #3FF00000:0 /* 1 */
  48: 1
  49: sti sp[8] = 1
  50: js_DoubleToInt32_1 = js_DoubleToInt32 ( fmul1 )
  51: lsh1 = lsh js_DoubleToInt32_1, 1
  52: i2f3 = i2f lsh1
  53: sti sp[0] = lsh1
  54: sti sp[-16] = lsh1
  55: sti sp[0] = lsh1
  56: sti sp[8] = 1
  57: rsh1 = rsh lsh1, 1
  58: i2f4 = i2f rsh1
  59: sti sp[0] = rsh1
  60: sti sp[-16] = rsh1
  61: add2 = add ld2, 1
  62: ov3 = ov add2
  63: xt3: xt ov3 -> pc=0x81dce49 imacpc=(nil) sp+0 rp+0
  64: i2f5 = i2f add2
  65: sti sp[0] = ld2
  66: sti sp[-8] = add2
  67: sti sp[0] = add2
  68: #408F4000:0 /* 1000 */
  69: 1000
  70: sti sp[8] = 1000
  71: lt1 = lt add2, 1000
  72: xf2: xf lt1 -> pc=0x81dce53 imacpc=(nil) sp+16 rp+0
  73: sti sp[-16] = rsh1
  74: sti sp[-8] = add2
  75: loop
=== END Initial LIR ===


=== BEGIN After Storefilter(sp) ===
  00: start
  01: state = param 0 ecx
  02: 0
  03: sp = ld state[0]
  04: 4
  05: rp = ld state[4]
  06: 8
  07: cx = ld state[8]
  08: 12
  09: eos = ld state[12]
  10: 16
  11: eor = ld state[16]
  12: -32
  13: $callee0 = ld sp[-32]
  14: -24
  15: $this0 = ld sp[-24]
  16: -16
  17: ld1 = ld sp[-16]
  18: $foo.s = i2f ld1
  19: -8
  20: ld2 = ld sp[-8]
  21: $foo.i = i2f ld2
  22: ld3 = ld cx[0]
  23: eq1 = eq ld3, 0
  24: xf1: xf eq1 -> pc=0x81dce1d imacpc=(nil) sp+0 rp+0
  25: sti sp[0] = ld1
  26: sti sp[8] = ld2
  27: add1 = add ld1, ld2
  28: ov1 = ov add1
  29: xt1: xt ov1 -> pc=0x81dce24 imacpc=(nil) sp+16 rp+0
  30: i2f1 = i2f add1
  31: sti sp[-16] = add1
  32: sti sp[0] = add1
  33: sti sp[8] = ld2
  34: #40240000:0 /* 10 */
  35: 10
  36: sti sp[16] = 10
  37: sub1 = sub ld2, 10
  38: ov2 = ov sub1
  39: xt2: xt ov2 -> pc=0x81dce31 imacpc=(nil) sp+24 rp+0
  40: i2f2 = i2f sub1
  41: fmul1 = fmul i2f1, i2f2
  42: stqi sp[-16] = fmul1
  43: #3FF00000:0 /* 1 */
  44: 1
  45: js_DoubleToInt32_1 = js_DoubleToInt32 ( fmul1 )
  46: lsh1 = lsh js_DoubleToInt32_1, 1
  47: i2f3 = i2f lsh1
  48: rsh1 = rsh lsh1, 1
  49: i2f4 = i2f rsh1
  50: sti sp[-16] = rsh1
  51: add2 = add ld2, 1
  52: ov3 = ov add2
  53: xt3: xt ov3 -> pc=0x81dce49 imacpc=(nil) sp+0 rp+0
  54: i2f5 = i2f add2
  55: sti sp[-8] = add2
  56: sti sp[0] = add2
  57: #408F4000:0 /* 1000 */
  58: 1000
  59: sti sp[8] = 1000
  60: lt1 = lt add2, 1000
  61: xf2: xf lt1 -> pc=0x81dce53 imacpc=(nil) sp+16 rp+0
  62: sti sp[-16] = rsh1
  63: sti sp[-8] = add2
  64: loop
=== END After Storefilter(sp) ===


=== BEGIN After StoreFilter(rp) ===
  00: start
  01: state = param 0 ecx
  02: 0
  03: sp = ld state[0]
  04: 4
  05: rp = ld state[4]
  06: 8
  07: cx = ld state[8]
  08: 12
  09: eos = ld state[12]
  10: 16
  11: eor = ld state[16]
  12: -32
  13: $callee0 = ld sp[-32]
  14: -24
  15: $this0 = ld sp[-24]
  16: -16
  17: ld1 = ld sp[-16]
  18: $foo.s = i2f ld1
  19: -8
  20: ld2 = ld sp[-8]
  21: $foo.i = i2f ld2
  22: ld3 = ld cx[0]
  23: eq1 = eq ld3, 0
  24: xf1: xf eq1 -> pc=0x81dce1d imacpc=(nil) sp+0 rp+0
  25: sti sp[0] = ld1
  26: sti sp[8] = ld2
  27: add1 = add ld1, ld2
  28: ov1 = ov add1
  29: xt1: xt ov1 -> pc=0x81dce24 imacpc=(nil) sp+16 rp+0
  30: i2f1 = i2f add1
  31: sti sp[-16] = add1
  32: sti sp[0] = add1
  33: sti sp[8] = ld2
  34: #40240000:0 /* 10 */
  35: 10
  36: sti sp[16] = 10
  37: sub1 = sub ld2, 10
  38: ov2 = ov sub1
  39: xt2: xt ov2 -> pc=0x81dce31 imacpc=(nil) sp+24 rp+0
  40: i2f2 = i2f sub1
  41: fmul1 = fmul i2f1, i2f2
  42: stqi sp[-16] = fmul1
  43: #3FF00000:0 /* 1 */
  44: 1
  45: js_DoubleToInt32_1 = js_DoubleToInt32 ( fmul1 )
  46: lsh1 = lsh js_DoubleToInt32_1, 1
  47: i2f3 = i2f lsh1
  48: rsh1 = rsh lsh1, 1
  49: i2f4 = i2f rsh1
  50: sti sp[-16] = rsh1
  51: add2 = add ld2, 1
  52: ov3 = ov add2
  53: xt3: xt ov3 -> pc=0x81dce49 imacpc=(nil) sp+0 rp+0
  54: i2f5 = i2f add2
  55: sti sp[-8] = add2
  56: sti sp[0] = add2
  57: #408F4000:0 /* 1000 */
  58: 1000
  59: sti sp[8] = 1000
  60: lt1 = lt add2, 1000
  61: xf2: xf lt1 -> pc=0x81dce53 imacpc=(nil) sp+16 rp+0
  62: sti sp[-16] = rsh1
  63: sti sp[-8] = add2
  64: loop
=== END After StoreFilter(rp) ===


=== BEGIN After DeadFilter == Final LIR ===
  00: state = param 0 ecx
  01: sp = ld state[0]
  02: cx = ld state[8]
  03: ld1 = ld sp[-16]
  04: ld2 = ld sp[-8]
  05: ld3 = ld cx[0]
  06: xf1: xf eq1 -> pc=0x81dce1d imacpc=(nil) sp+0 rp+0
  07: sti sp[0] = ld1
  08: sti sp[8] = ld2
  09: add1 = add ld1, ld2
  10: xt1: xt ov1 -> pc=0x81dce24 imacpc=(nil) sp+16 rp+0
  11: i2f1 = i2f add1
  12: sti sp[-16] = add1
  13: sti sp[0] = add1
  14: sti sp[8] = ld2
  15: sti sp[16] = 10
  16: sub1 = sub ld2, 10
  17: xt2: xt ov2 -> pc=0x81dce31 imacpc=(nil) sp+24 rp+0
  18: i2f2 = i2f sub1
  19: fmul1 = fmul i2f1, i2f2
  20: stqi sp[-16] = fmul1
  21: js_DoubleToInt32_1 = js_DoubleToInt32 ( fmul1 )
  22: lsh1 = lsh js_DoubleToInt32_1, 1
  23: rsh1 = rsh lsh1, 1
  24: sti sp[-16] = rsh1
  25: add2 = add ld2, 1
  26: xt3: xt ov3 -> pc=0x81dce49 imacpc=(nil) sp+0 rp+0
  27: sti sp[-8] = add2
  28: sti sp[0] = add2
  29: sti sp[8] = 1000
  30: xf2: xf lt1 -> pc=0x81dce53 imacpc=(nil) sp+16 rp+0
  31: sti sp[-16] = rsh1
  32: sti sp[-8] = add2
  33: loop
=== END After DeadFilter == Final LIR ===

=== -- Compile trunk 0x81dcf18: end

=== Aggregated assembly output: BEGIN
===
  00f7f1af50   [prologue]
  00f7f1af50   push edi
  00f7f1af51   push esi
  00f7f1af52   push ebx
  00f7f1af53   push ebp
  00f7f1af54   push ebp
  00f7f1af55   mov  ebp,esp
  00f7f1af57   [frag entry]
  00f7f1af57   sub  esp,8
  ## patching branch at 00f7f1aff3 to 00f7f1af5a
  00f7f1af5a:
  ## compiling trunk 0x81dcf18
      state = param 0 ecx
      sp = ld state[0]
      cx = ld state[8]
      ld1 = ld sp[-16]
      ld2 = ld sp[-8]
      ld3 = ld cx[0]
      eq1 = eq ld3, 0
      xf1: xf eq1 -> pc=0x81dce1d imacpc=(nil) sp+0 rp+0
  00f7f1af5a   mov  -4(ebp),ecx       ecx(state)
  00f7f1af5d   mov  edi,ecx           ecx(state)
  00f7f1af5f   mov  esi,0(edi)        edi(state)
  00f7f1af61   mov  ecx,8(edi)        esi(sp) edi(state)
  00f7f1af64   mov  eax,-16(esi)      ecx(cx) esi(sp) edi(state)
  00f7f1af67   mov  ebx,-8(esi)       eax(ld1) ecx(cx) esi(sp) edi(state)
  00f7f1af6a   mov  ecx,0(ecx)        eax(ld1) ecx(cx) ebx(ld2) esi(sp) edi(state)
  00f7f1af6c   test ecx,ecx           eax(ld1) ecx(ld3) ebx(ld2) esi(sp) edi(state)
  00f7f1af6e   jne  0xf7f14fbb        eax(ld1) ebx(ld2) esi(sp) edi(state)
  ----------------------------------- ## BEGIN exit block (LIR_xt|LIR_xf)
  00f7f14fbb:
  ## merging registers (intersect) with existing edge
  00f7f14fbb   mov  ecx,-4(ebp)
  00f7f14fbe   mov  eax,-135151148
  00f7f14fc3   mov  esp,ebp
  00f7f14fc5:
  00f7f14fc5   jmp  0xf7f1aff8
  ----------------------------------- ## END exit block 0xf7f1c1f4
      sti sp[0] = ld1
      sti sp[8] = ld2
      add1 = add ld1, ld2
      ov1 = ov add1
      xt1: xt ov1 -> pc=0x81dce24 imacpc=(nil) sp+16 rp+0
  00f7f1af74   mov  0(esi),eax        eax(ld1) ebx(ld2) esi(sp) edi(state)
  00f7f1af76   mov  8(esi),ebx        eax(ld1) ebx(ld2) esi(sp) edi(state)
  00f7f1af79   add  eax,ebx           eax(ld1) ebx(ld2) esi(sp) edi(state)
  00f7f1af7b   jo   0xf7f14fca        eax(add1) ebx(ld2) esi(sp) edi(state)
  ----------------------------------- ## BEGIN exit block (LIR_xt|LIR_xf)
  00f7f14fca:
  ## merging registers (intersect) with existing edge
  00f7f14fca   mov  ecx,-4(ebp)
  00f7f14fcd   mov  eax,-135150956
  00f7f14fd2   mov  esp,ebp
  00f7f14fd4:
  00f7f14fd4   jmp  0xf7f1aff8
  ----------------------------------- ## END exit block 0xf7f1c2c4
      i2f1 = i2f add1
      sti sp[-16] = add1
      sti sp[0] = add1
      sti sp[8] = ld2
      sti sp[16] = 10
      sub1 = sub ld2, 10
      ov2 = ov sub1
      xt2: xt ov2 -> pc=0x81dce31 imacpc=(nil) sp+24 rp+0
  00f7f1af81   cvtsi2sd xmm0,eax      eax(add1) ebx(ld2) esi(sp) edi(state)
  00f7f1af85   mov  -16(esi),eax      eax(add1) ebx(ld2) esi(sp) edi(state) xmm0(i2f1)
  00f7f1af88   mov  0(esi),eax        eax(add1) ebx(ld2) esi(sp) edi(state) xmm0(i2f1)
  00f7f1af8a   mov  8(esi),ebx        ebx(ld2) esi(sp) edi(state) xmm0(i2f1)
  00f7f1af8d   mov  16(esi),10        ebx(ld2) esi(sp) edi(state) xmm0(i2f1)
  00f7f1af94   mov  eax,ebx           ebx(ld2) esi(sp) edi(state) xmm0(i2f1)
  00f7f1af96   sub  eax,10            ebx(ld2) esi(sp) edi(state) xmm0(i2f1)
  00f7f1af99   jo   0xf7f14fd9        eax(sub1) ebx(ld2) esi(sp) edi(state) xmm0(i2f1)
  ----------------------------------- ## BEGIN exit block (LIR_xt|LIR_xf)
  00f7f14fd9:
  ## merging registers (intersect) with existing edge
  00f7f14fd9   mov  ecx,-4(ebp)
  00f7f14fdc   mov  eax,-135150652
  00f7f14fe1   mov  esp,ebp
  00f7f14fe3:
  00f7f14fe3   jmp  0xf7f1aff8
  ----------------------------------- ## END exit block 0xf7f1c3f4
      i2f2 = i2f sub1
      fmul1 = fmul i2f1, i2f2
      stqi sp[-16] = fmul1
      js_DoubleToInt32_1 = js_DoubleToInt32 ( fmul1 )
      lsh1 = lsh js_DoubleToInt32_1, 1
      rsh1 = rsh lsh1, 1
      sti sp[-16] = rsh1
      add2 = add ld2, 1
      ov3 = ov add2
      xt3: xt ov3 -> pc=0x81dce49 imacpc=(nil) sp+0 rp+0
  00f7f1af9f   cvtsi2sd xmm1,eax      eax(sub1) ebx(ld2) esi(sp) edi(state) xmm0(i2f1)
  00f7f1afa3   mulsd xmm0,xmm1        ebx(ld2) esi(sp) edi(state) xmm0(i2f1) xmm1(i2f2)
  00f7f1afa7   movq -16(esi),xmm0     ebx(ld2) esi(sp) edi(state) xmm0(fmul1)
  00f7f1afac   sub  esp,8             ebx(ld2) esi(sp) edi(state) xmm0(fmul1)
  00f7f1afaf   sub  esp,8             ebx(ld2) esi(sp) edi(state) xmm0(fmul1)
  00f7f1afb2   movq 0(esp),xmm0       ebx(ld2) esi(sp) edi(state) xmm0(fmul1)
  00f7f1afb7   call js_DoubleToInt32  ebx(ld2) esi(sp) edi(state)
  00f7f1afbc   add  esp,8             ebx(ld2) esi(sp) edi(state)
  00f7f1afbf   mov  ecx,edi           ebx(ld2) esi(sp) edi(state)
  00f7f1afc1   mov  edi,eax           eax(js_DoubleToInt32_1) ecx(state) ebx(ld2) esi(sp)
  00f7f1afc3   shl  edi,1             ecx(state) ebx(ld2) esi(sp) edi(js_DoubleToInt32_1)
  00f7f1afc6   sar  edi,1             ecx(state) ebx(ld2) esi(sp) edi(lsh1)
  00f7f1afc9   mov  -16(esi),edi      ecx(state) ebx(ld2) esi(sp) edi(rsh1)
  00f7f1afcc   add  ebx,1             ecx(state) ebx(ld2) esi(sp) edi(rsh1)
  00f7f1afcf   jo   0xf7f14fe8        ecx(state) ebx(add2) esi(sp) edi(rsh1)
  ----------------------------------- ## BEGIN exit block (LIR_xt|LIR_xf)
  00f7f14fe8:
  00f7f14fe8   mov  eax,-135150156
  00f7f14fed   mov  esp,ebp
  00f7f14fef:
  00f7f14fef   jmp  0xf7f1aff8
  ----------------------------------- ## END exit block 0xf7f1c5e4
      sti sp[-8] = add2
      sti sp[0] = add2
      sti sp[8] = 1000
      lt1 = lt add2, 1000
      xf2: xf lt1 -> pc=0x81dce53 imacpc=(nil) sp+16 rp+0
  00f7f1afd5   mov  -8(esi),ebx       ecx(state) ebx(add2) esi(sp) edi(rsh1)
  00f7f1afd8   mov  0(esi),ebx        ecx(state) ebx(add2) esi(sp) edi(rsh1)
  00f7f1afda   mov  8(esi),1000       ecx(state) ebx(add2) esi(sp) edi(rsh1)
  00f7f1afe1   cmp  ebx,1000          ecx(state) ebx(add2) esi(sp) edi(rsh1)
  00f7f1afe7   jnl  0xf7f14ff4        ecx(state) ebx(add2) esi(sp) edi(rsh1)
  ----------------------------------- ## BEGIN exit block (LIR_xt|LIR_xf)
  00f7f14ff4:
  00f7f14ff4   mov  eax,-135149868
  00f7f14ff9   mov  esp,ebp
  00f7f14ffb:
  00f7f14ffb   jmp  0xf7f1aff8
  ----------------------------------- ## END exit block 0xf7f1c6f4
      sti sp[-16] = rsh1
      sti sp[-8] = add2
      1
      loop
  00f7f1afed   mov  -16(esi),edi      ecx(state) ebx(add2) esi(sp) edi(rsh1)
  00f7f1aff0   mov  -8(esi),ebx       ecx(state) ebx(add2) esi(sp)
  00f7f1aff3:
  00f7f1aff3   jmp  (nil)
  00f7f1aff8   [epilogue]
  00f7f1aff8   mov  esp,ebp
  00f7f1affa   pop  ebp
  00f7f1affb   pop  ebp
  00f7f1affc   pop  ebx
  00f7f1affd   pop  esi
  00f7f1affe   pop  edi
               ret
===
=== Aggregated assembly output: END

===
=== END [call number 1] LIR::compile(0x81ce778, 0x81dcf18)
================================================================================

Comment 13

[Jason Orendorff [:jorendorff]]

Comment on attachment 381194 [details] [diff] [review]
Revised version of patch, capable of printing LIR after each reader pipe stage

Hey, this is good stuff.  I worry (and Graydon agrees) that it will generate a really huge amount of verbose output though.  Let's add some way of controlling the amount and type of spew generated first.

If you want to split the simple formatting changes into a separate patch, I think we could land that stuff right away.  Totally up to you.

Other comments:

Can you squeeze some of the redundancy out of Assembler::assemble?

%010lx would be buggy on 64-bit Windows, especially in places where the pointer argument isn't being to (unsigned long); you suggested "%10p" and I think that's fine -- though perhaps "%12p" since %p writes "0x" (a good thing when gdb-ing).

Use tabs or spaces consistently -- whatever the surrounding code does.

Comment 14

[Nicholas Nethercote [inactive]]

A minor comment about this line:

=== BEGIN After DeadFilter == Final LIR ===

I see the "==" is meant to mean "equals", but it looks weird after the "===";  for a second I thought there was an output bug and two lines had been concatenated or something.

How about this?

=== BEGIN After DeadFilter (Final LIR) ===

and likewise for the END line.

Comment 15

[Julian Seward [:jseward]]

(in reply to Comment #13)

> Let's add some way of controlling the amount and type of spew generated first.

Sure.  So here's what I'm working on.  If it doesn't sound like what you 
want, can you yell sooner rather than later?

* TRACEMONKEY=foo,bar,xyzzy is renamed TMFLAGS=foo,bar,xyzzy

* When TMFLAGS includes "verbose", it prints just 2 lines per
  recording now, and nothing else, like this:

  === recording starting from ./trace-test.js:496@138
  === recording completed at  ./trace-test.js:496@138 via closeLoop

* if you want to see the details for that particular recording
  (fragment? trace? what's the right word?) then you specify it with
  TMDETAILS=, viz

  TMFLAGS=verbose TMDETAILS=trace-test.js:496@138

  The matching between what's specified in TMDETAILS and the actual
  (filename, number, number) triple that apparently characterises each
  recording, is done using a crude strstr() check.  Hence you could
  ask to see details of two traces with eg

  TMDETAILS=foo.js:123@456,bar.js:987@654

  etc and TMDETAILS= (nothing) shows details of all traces.  Of course
  we could wheel in regexp matching etc if required later.

That's all easy enough.  The most pressing problem is that there's a
bunch of output which is not associated with any particular 
record-translate episode, but rather to do with monitoring (eg, of
types, entering trace, leaving trace) and I'm not sure how to filter
that yet.

One code change that does seem to be necessary is to pass to Nanojit
details of the verbosity level for each translation, so that it can
be properly controlled by its caller (TM or Tamarin).  Up till now both
Nanojit and jstracer.cpp independently examine TRACEMONKEY, which is
bizarre.

Comment 16

[Jason Orendorff [:jorendorff]]

Graydon, Julian, and I discussed this on IRC.

We want to be able to specify e.g. "just fragment/monitor/recorder activity" rather than (or, in addition to) "just this particular loop".  In other words, you should be able to filter the spew based on what part of the code you're debugging.

(That filtering could be done with grep if all debug output carries a "category" prefix -- but associating a category with every line of debug output is the tedious part. Given that, a little getenv niceness is easy enough.)

Comment 17

[Julian Seward [:jseward]]

> We want to be able to specify e.g. "just fragment/monitor/recorder activity"
> rather than (or, in addition to) "just this particular loop".

In progress (the "in addition to" version).

> but associating a category with every line of debug output is the 
> tedious part.

That will have to be done whether or not the filtering is done
with grep.  If it is, we have to print categories so they are 
greppable.  If it isn't, then each message print statement needs
to "know" what category it is in so it can check the relevant 
category-enablement bit in some control word somewhere.  Either way
we have to examine and categorise each print statement.  No big 
deal, there's only about 100 of them in jstracer.cpp.

Comment 18

[Julian Seward [:jseward]]

Attachment: patch extended to allow selection of the output-kind

Comment 19

[Julian Seward [:jseward]]

(re the patch in Comment #18)

This patch allows selection of the kind of output in some detail,
as discussed in Comment #16.  It also removes the ability to
follow specific translations in extra detail, as discussed in
Comment #15.  The latter turns out to be more complex than I had
expected, and so is omitted for the time being.

The currently supported categories are:

   ------ options for jstracer & jsregexp ------
   minimal     ultra-minimalist output; try this first
   tracer      tracer lifetime (FIXME:better description)
   recorder    trace recording stuff (FIXME:better description)
   patcher     patching stuff (FIXME:better description)
   abort       show trace recording aborts
   stats       show trace recording stats
   regexp      show compilation & entry for regexps
   ------ options for Nanojit ------
   readlir     show LIR as it enters the reader pipeline
   aftersf_sp  show LIR after StackFilter(sp)
   aftersf_rp  show LIR after StackFilter(rp)
   afterdeadf  show LIR after DeadCodeFilter
   regalloc    show regalloc details
   assembly    show final aggregated assembly code

Any combination is supported.  

This patch is much more convincingly integrated into jstracer.cpp
than the previous version; it can control jstracer and nanojit
equally.

This is implemented by adding a new class LogControl, exported by
nanojit.h.  LogControl contains a sink-function which subsumes
nj_dprintf, and a bitmask indicating which message categories to
print.  jstracer.cpp has single global object of this type, which
is used to control all its (and Nanojit's) output.

Each message to be printed now "knows" its message category.
Many of the assignments are guesses and need refinement.  In
particular the "patcher" and "regalloc" categories currently have
no messages assigned to them.

New categories can easily be added, up to 16 for jstracer et al
and 16 for Nanojit.

Comment 20

[Julian Seward [:jseward]]

Attachment: same as previous patch but made with "-p -U 8"

Comment 21

[Graydon Hoare :graydon]

Comment on attachment 383571 [details] [diff] [review]
same as previous patch but made with "-p -U 8"

The good news is I think I have no substantial complaints with the patch;
it's pretty much what I had in mind. There are a few stylistic nits though,
and you should probably run it by some Adobe people as well. r+ with these
fixed though.

>--- a/js/src/jsregexp.cpp
>+++ b/js/src/jsregexp.cpp
>@@ -3919,36 +3928,38 @@ MatchRegExp(REGlobalData *gData, REMatch
>     NativeRegExp native;
> 
>     /* Run with native regexp if possible. */
>     if (TRACING_ENABLED(gData->cx) && 
>         (native = GetNativeRegExp(gData->cx, gData->regexp))) {
>         gData->skipped = (ptrdiff_t) x->cp;
> 
> #ifdef JS_JIT_SPEW
>-        debug_only_v({
>+        debug_only_stmt({
>             VOUCH_DOES_NOT_REQUIRE_STACK();
>             JSStackFrame *caller = (JS_ON_TRACE(gData->cx))
>                                    ? NULL
>                                    : js_GetScriptedCaller(gData->cx, NULL);
>-            printf("entering REGEXP trace at %s:%u@%u, code: %p\n",
>+            debug_only_printf(
>+                   LC_TMRegexp,
>+                   "entering REGEXP trace at %s:%u@%u, code: %p\n",

I think house style is to have "debug_only_printf(LC_TMRegexp," on the
first line and wrap args after there. Likewise several instances of
debug_only_stmt are wrapped in non-house style (but see comments at bottom
re: debug_only_stmt).

>-        debug_only_v(printf("leaving REGEXP trace\n"));
>+        debug_only_print0(LC_TMRegexp, "leaving  REGEXP trace\n");

Remove extra space before REGEXP. 

Also un-capitalize all instances of 'REGEXP'. Too shouty.

>--- a/js/src/jstracer.cpp
>+++ b/js/src/jstracer.cpp
>+/* ------ Debug logging control ------ */
>+
>+/* All the logging control stuff lives in here.  It is shared between
>+   all threads, but I think that's OK. */

I got the impression earlier that you were going to store this in the
TraceMonitor object. Too much fuss? I suppose it's safe so long as it's
set on startup.

>+LogControl js_LogController;
>+
>+#ifdef JS_JIT_SPEW

I think you can move js_LogController inside the JS_JIT_SPEW guard, no?

>+
>+static void js_InitJITLogController ( void )
>+{

Style nit: should be

static void
js_InitJITLogController() {

>--- a/js/src/nanojit/LIR.cpp
>+++ b/js/src/nanojit/LIR.cpp
>@@ -1512,17 +1500,17 @@ namespace nanojit
>             live.remove(i);
>             retired.add(e);
> 		}
> 		bool contains(LInsp i) {
> 			return live.containsKey(i);
> 		}
> 	};
> 
>-    void live(GC *gc, LirBuffer *lirbuf)
>+    void live(GC *gc, LirBuffer *lirbuf, LogControl* logc)

Style nit: should be 'LogControl *logc' (though nj is inconsistent on this).

>@@ -1564,43 +1552,75 @@ namespace nanojit
>+	void show_LirBuffer(const char* prefix, LirBuffer* lirbuf, GC* gc,
>+						LogControl* logc)

Style nit: should be showLirBuffer.

>+	{
>+		StringList  strs(gc);
>+        LirReader   br(lirbuf);
>+		LirNameMap* names = lirbuf->names;
>+		// put all stuff into STRS, so we can print it out backwards

Style nit: 'strs' not STRS.

>@@ -2001,91 +2021,176 @@ namespace nanojit
>     void compile(Assembler* assm, Fragment* triggerFrag)
>     {
>-        Fragmento *frago = triggerFrag->lirbuf->_frago;
>-        AvmCore *core = frago->core();
>-        GC *gc = core->gc;
>+        Fragmento  *frago  = triggerFrag->lirbuf->_frago;
>+        AvmCore    *core   = frago->core();
>+        GC         *gc     = core->gc;
> 

Style nit: neither sm or nj does vertical alignment of variable decls, you
do this in a variety of places.

>+		verbose_only(
>+		LogControl *logc   = assm->_logc;
>+		bool       anyVerb = (logc->lcbits & 0xFFFF) > 0;
>+		bool       asmVerb = (logc->lcbits & 0xFFFF & LC_Assembly) > 0;
>+		)
>+
>+		/* BEGIN decorative preamble */
>+		verbose_only( 
>+		static int entry_count = 0;
>+        if (anyVerb) {
>+			entry_count++; /* not thread safe */

Non-threadsafe indeed. Not a fan of static locals. Maybe make this a
member variable?

>+		verbose_only( if (0 && anyVerb) {

I'm guessing the '0 &&' isn't supposed to be here.

Two further style points / questions, aside from the obvious / expected
future churn of category bits which we'll just do as needed: 

  1. Can we move debug_stmt(s) into a do { ... } while(0) form, say using
     JS_BEGIN_MACRO / JS_END_MACRO? I'm worried about dangling elses and 
     whatnot.

  2. LC_TMFoo doesn't read well. Existing jstracer enums are all caps and
     have fewer prefix characters (R_ABORT or S_MONITOR), I think L_FOO
     might be better. Or ... we have C++ namespaces. Should we start using
     them? Log::Foo doesn't necessarily read better. Hmm. Thoughts?

Comment 22

[Edwin Smith]

Comment on attachment 383571 [details] [diff] [review]
same as previous patch but made with "-p -U 8"

style nits:

- suggest %-6s or more for x86 code.  a) handles common long names, b) easier to read with more ws before operands

- lir pretty-printing, include the LIR instruction name when printing constant instructions but not references.  for example


   short 6
   add2 = add something, 6

rather than

   6
   add2 = add something, 6

- if it's not already in there, please preserve the option to suppress addresses in the assembly output.  they are handy when reading, and great for debugging in-process when you have to isolate a heisenbug.  but we also often use a workflow of diffing output from different builds (tweaks, etc) and in that case the code addresses are a big pain.

this workflow is also why there's a facility for assigning labels to addresses and always using the labels in verbose output.

Comment 23

[Nicholas Nethercote [inactive]]

It's late to be chiming in with a request, but if it doesn't already have it, could the --help message be updated to include a brief coverage of the new env vars and how they are used?  That would be *extremely* helpful.  (Eg. I just discovered the old TRACEMONKEY flag has "status" and "stats" and "abort" options, I didn't know that before.)

Comment 24

[Julian Seward [:jseward]]

(in reply to Comment #23)

I think it already does what you want.  The help text is below.  It is
printed if you start with TRACEMONKEY set to anything at all, so that people
know the env var has changed, and is also printed if you have TMFLAGS=help.

---------

Debug output control help summary for TraceMonkey:

TRACEMONKEY= is no longer used; use TMFLAGS= instead.

usage: TMFLAGS=option,option,option,... where options can be:
   help        show this message
   ------ options for jstracer & jsregexp ------
   minimal     ultra-minimalist output; try this first
   tracer      tracer lifetime (FIXME:better description)
   recorder    trace recording stuff (FIXME:better description)
   patcher     patching stuff (FIXME:better description)
   abort       show trace recording aborts
   stats       show trace recording stats
   regexp      show compilation & entry for regexps
   ------ options for Nanojit ------
   readlir     show LIR as it enters the reader pipeline
   aftersf_sp  show LIR after StackFilter(sp)
   aftersf_rp  show LIR after StackFilter(rp)
   afterdeadf  show LIR after DeadCodeFilter
   regalloc    show regalloc details
   assembly    show final aggregated assembly code

Exiting now.  Bye.

Comment 25

[Julian Seward [:jseward]]

(In reply to comment #21)

Most stuff fixed.  Some comments:

> >-        debug_only_v(printf("leaving REGEXP trace\n"));
> >+        debug_only_print0(LC_TMRegexp, "leaving  REGEXP trace\n");
> 
> Remove extra space before REGEXP. 
> Also un-capitalize all instances of 'REGEXP'. Too shouty.

The extra space makes the entry and exit messages line up more
nicely.  The capitals were there to begin with (perhaps grep
fodder?) and I haven't tried to reword any of the messages in
jstracer.cpp.

> >+/* ------ Debug logging control ------ */
> >+
> >+/* All the logging control stuff lives in here.  It is shared between
> >+   all threads, but I think that's OK. */
> 
> I got the impression earlier that you were going to store this in the
> TraceMonitor object. Too much fuss?

Yes.  It only really needs to be thread-local if we're doing extra
levels of logging on selected traces, but that's not implemented.

> >+		/* BEGIN decorative preamble */
> >+		verbose_only( 
> >+		static int entry_count = 0;
> >+        if (anyVerb) {
> >+			entry_count++; /* not thread safe */
> 
> Non-threadsafe indeed. Not a fan of static locals. Maybe make this a
> member variable?

Too difficult.  The variable and the numbered printing it drove, have
been removed.

> Two further style points / questions, aside from the obvious / expected
> future churn of category bits which we'll just do as needed: 
> 
>   1. Can we move debug_stmt(s) into a do { ... } while(0) form, say using
>      JS_BEGIN_MACRO / JS_END_MACRO? I'm worried about dangling elses and 
>      whatnot.

Yeh .. that seems reasonable and I did try it originally.  Problem is
that debug_stmt is sometimes wrapped around declarations, in which case
the do- formulation limits the scope to the {...} bit, which isn't what
is wanted.  Hence the current formulation (which pre-exists anyway,
for the same reason, I guess).

>   2. LC_TMFoo doesn't read well. Existing jstracer enums are all caps and
>      have fewer prefix characters (R_ABORT or S_MONITOR), I think L_FOO
>      might be better. Or ... we have C++ namespaces. Should we start using
>      them? Log::Foo doesn't necessarily read better. Hmm. Thoughts?

Unchanged.  I was trying to make it clear from the TM prefix which flags
are nanojit-specific and which weren't.

> - if it's not already in there, please preserve the option to suppress
> addresses in the assembly output

fixed; new option "nocodeaddrs" added, so is selectable at runtime.

Patch to follow.

Comment 26

[Jeff Walden [:Waldo]]

I haven't been following this bug as closely as I should for the last several weeks, but if comment 11's formatting is substantially what the latest patch here implements, I suggest printing a line number only every five lines, say, to reduce the excess of visual clutter.

Comment 27

[Julian Seward [:jseward]]

Attachment: revised patch as per Comment #25

Comment 28

[Graydon Hoare :graydon]

Comment on attachment 384661 [details] [diff] [review]
revised patch as per Comment #25

Run it through the try servers to be sure, as this much change inevitably makes msvc or OSX or *someone* issue a compiler error ... but otherwise looks good. 

Thanks for the patient amendments..

Comment 29

[Julian Seward [:jseward]]

Attachment: identical to patch in comment #27 but rebased to 24jun09 7am pdt

This patch was also pushed to the try servers, with the identifying
string "tidy-up-debug-output-8"

Comment 30

[Graydon Hoare :graydon]

Great. Considering that you're trying to land on a very churny tree and IIRC you don't have commit access yet, the post/review/pull/commit lag will continue to bite you. I'll ferry it in from here. It's already decayed against Jacob's work and my own from today. Don't sweat it, it's done, move on to other stuff :)

Comment 31

[Graydon Hoare :graydon]

http://hg.mozilla.org/tracemonkey/rev/f694ffd22e6c

Comment 32

[Mike Beltzner [:beltzner, not reading bugmail]]

FYI:

http://graphs-new.mozilla.org/graph.html#tests=[{%22machine%22:80,%22test%22:9,%22branch%22:4},{%22machine%22:81,%22test%22:9,%22branch%22:4},{%22machine%22:82,%22test%22:9,%22branch%22:4},{%22machine%22:108,%22test%22:9,%22branch%22:4},{%22machine%22:109,%22test%22:9,%22branch%22:4},{%22machine%22:110,%22test%22:9,%22branch%22:4},{%22machine%22:111,%22test%22:9,%22branch%22:4},{%22machine%22:112,%22test%22:9,%22branch%22:4},{%22machine%22:113,%22test%22:9,%22branch%22:4},{%22machine%22:114,%22test%22:9,%22branch%22:4},{%22machine%22:116,%22test%22:9,%22branch%22:4},{%22machine%22:117,%22test%22:9,%22branch%22:4},{%22machine%22:118,%22test%22:9,%22branch%22:4},{%22machine%22:119,%22test%22:9,%22branch%22:4},{%22machine%22:120,%22test%22:9,%22branch%22:4},{%22machine%22:122,%22test%22:9,%22branch%22:4}]&sel=1245815520,1245988320

shows a 3% increase in working memory set after this patch.

Comment 33

[Wesley W. Garland]

Attachment: Trivial supplemental patch to fix NativeSparc.cpp

This patch supplements Julian's (attachment 384899 [details] [diff] [review]), making the necessary changes in NativeSparc.cpp.

Disclosure: Adding Gal's patch in bug 501072 and this patch allows recent tracemonkey to compile on sparc again, but it still raises SIGBUS || SIGSEGV as soon as it starts tracing (at least with my gcc3.4.3 toolchain).  I don't think the crashing is related to this patch, though.

Comment 34

[Robert Sayre]

http://hg.mozilla.org/mozilla-central/rev/f694ffd22e6c

Comment 35

[Graydon Hoare :graydon]

Comment on attachment 386586 [details] [diff] [review]
Trivial supplemental patch to fix NativeSparc.cpp

Looks good, thanks.

Comment 36

[Leon Sha]

The Garland's patch.
http://hg.mozilla.org/tracemonkey/rev/748f7902544a
http://hg.mozilla.org/mozilla-central/rev/3b2798bb35f7

Comment 37

[Robert Sayre]

http://hg.mozilla.org/mozilla-central/rev/748f7902544a

Comment 38

[Chris Peyer]

Resolved fixed engineering / work item that has been pushed.  Setting status to verified.