620757 - TM: don't trace JSOP_TABLESWITCH

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Chris Nokleberg]

User-Agent:       Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.6; en-US; rv:1.9.2.13) Gecko/20101203 Firefox/3.6.13
Build Identifier: Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.6; en-US; rv:1.9.2.13) Gecko/20101203 Firefox/3.6.13

Open the attached html file. It runs a purely mathematical calculation 1000 times and prints the unique results. There should only be one unique result, but on FF when the jit is enabled there will usually be two or three.

Reloading the page will sometimes give different results.

Disabling javascript.options.jit.content will fix the problem.

Uncommenting the empty eval('') in the code will fix the problem.

Reproducible: Always

Steps to Reproduce:
1. Load the attached file
2. Compare with another browser or with jit disabled
3. Reload to see that the results can vary from run to run
Actual Results:  
Example buggy output:
50000 120000 46498 11625 46498 23249 258074 120000 55798 166490 11625 34874 27899 194389
50000 120000 46498 0 46498 23249 258074 120000 55798 166490 23249 23249 55797 222288
50000 120000 46498 0 46498 23249 258074 120000 55798 166490 73246 23249 817397796 817564287

Expected Results:  
50000 120000 46498 11625 46498 23249 258074 50000 23249 96751 11625 34874 11625 108375

Comment 1

[Chris Nokleberg]

Attachment: HTML page that demonstrates the bug

Comment 2

[Brendan Eich [:brendan]]

This WFM in 4.0b8-ish tracemonkey optimized self-build.

Chris, if you can confirm this is fixed in Firefox 4 betas, then we can bisect through the build archive to identify what fixed the bug.

/be

Comment 3

[Chris Nokleberg]

Yes, WFM in OS X 4.0b7

Comment 4

[Jan de Mooij [:jandem]]

Attachment: Shell test case

This still fails with -j, but works with -j -m.

Comment 5

[Andreas Gal :gal]

This works with trunk for me, but that might be due to the rebalancing of method JIT and trace JIT, so we need confirmation 2.0 isn't affected.

Comment 6

[Andreas Gal :gal]

Thanks Jan, that confirms #5.

Comment 7

[Andreas Gal :gal]

Setting blocking flag to get it on the radar.

Comment 8

[Nicholas Nethercote [inactive]]

I reduced Jan's test as much as I could.  The result is this:

function calc() {
  res = [];
  var fs = [[0, 0], [0, 0], [0, 1]];

  for (var i = 0; i < fs.length; i++) {
    var f = fs[i];
    var gf0 = g(f[0]);
    var gf1 = g(f[1]);
    res[i] = snd(gf0, gf1)
  } 
  return res
}       

function g(n) {
  switch (n) {
    case 0: return 88;
    case 1: return 1;
  } 
}   
        
var snd = function(x, y) { return y };
    
for (i = 0; i < 5; i++) {
  print(calc());
}


With -m I get this output:

88,88,1
88,88,1
88,88,1
88,88,1
88,88,1

With -j I get this output:

88,88,1
88,88,1
88,88,1
88,88,88
88,88,88

There are three trace fragments created.  The first two are for line 15 (the switch) and are identical except for differences in addresses, which is odd;  I guess it's because g() is called twice?  The last fragment is for line 5.  I suspect this is a trace tree construction issue.  I tried turning off all optimizations within Nanojit but that didn't change anything.

Comment 9

[Nicholas Nethercote [inactive]]

Attachment: diff

If I change the |f[0]| in comment 8 to |f[1]| the bug goes away.  I did a TMFLAGS=recorder,tracer run of the two variants, stripped out addresses, and have attached the diff of the results.

It gets interesting around line 114, where in the non-buggy run we see "synthesized shallow frame for a.js:15@0".  That doesn't occur in the buggy run.  It looks like the calldepth value is 0 in the buggy run and 1 in the non-buggy run.

Comment 10

[Nicholas Nethercote [inactive]]

I should add:  in the non-buggy run we end up attaching another branch to the trace tree.

Comment 11

[Nicholas Nethercote [inactive]]

Since this is (a) not a regression, and (b) the test case from comment 0 now works because the methodjit executes it instead of the tracejit, I suggest it should be wanted2.0 but not blocking2.0.

Comment 12

[David Mandelin [:dmandelin]]

Minusing per comment 11.

Comment 13

[David Mandelin [:dmandelin]]

Blocking 2.x per njn and bz on IRC.

Comment 14

[Nicholas Nethercote [inactive]]

Here's a smaller reproducer, courtesy of h4writer on IRC:

function calc() {
  var b = 0;
  var fs = [0, 0, 1];
  var ret;

  for (var i = 0; i < fs.length; i++) {
    g(b);
    ret = g(fs[i]);
  } 

  return ret;
}       

function g(n) {
  switch (n) {
    case 0: return 88;
  } 
  return 1;
}

for (i = 0; i < 4; i++) {
  print(calc());
}


-m output:

1
1
1
1

-j output:

1
1
1
88

Comment 15

[Hannes Verschore [:h4writer]]

I could even reduce it even more, so it doesn't use the array fs:

function calc() {
  var blaat = 0;
  var ret;

  for (var i = -1; i != 2; i++) {
    g(blaat);
    ret = g(i);
  }
  return ret;
}       

function g(n) {
  switch (n) {
    case 0: return 88;
  } 
  return 1;
}

for (i = 0; i < 4; i++) {
  print(calc());
}

It gives the same output as listed in previous comment.
The problem arise when i becomes 1 in the 'for' loop, then g(1) is set in the return value and it get's matched with 0 due some strange error...

Comment 16

[Hannes Verschore [:h4writer]]

I adjusted to code even further and it gives some extra information.
So I adjusted the values so the loop goes from 0 to 3 now. (Not starting at -1 anymore).

function calc() {
  var b = 2;

  for (var i = 0; i != 3; i++) {
    g(b);
    g(i);
  }
  print("---");
}       

function g(n) {
  switch (n) {
    case 2: break;
    default: print(n);
  }
}

for (i = 0; i < 4; i++) {
  calc();
}

The output should be (-m):
0
1
---
0
1
---
0
1
---
0
1
---

the output with tracemonkey (-t):
0
1
---
0
1
---
0
1
---
0
1
2
---

The switch should make sure that only values get printed that ain't 2. But in this case the '2' get printed the fourth time. So the switch-case doesn't match the '2' properly the fourth time.

Comment 17

[Hannes Verschore [:h4writer]]

Attachment: Incompete patch solves mismatching?

(Cautious, I'm a n00b at everything I'm doing here)

So I worked myself through the code of tracing. Some bits were comprehensive, other (most) things totally not. But I noticed that this bug only occurs when a switch gets translated in a tableswitch. In jstracer there is a tracerecorder for the more specific tableswitch and also a tracerecorder for the general switchop. The split for a tableswitch (as the comments say) is to prepare a jump table if needed. From there the mostly the magic begins. I can say when the code does, but don't get the big picture clear (so why what happens).

To find this diff. I just looked to the code in switchop and compared it to the code in the tableswitch. I noticed that switchop (in the numberic variation) used the value itself to guard on. So I adjusted the tableswitch so it also used the value itself. Didn't help. I had to adjust it a bit lower in the code. And the problem disappeared. 

Now I have no idea if I'm just lucky, or if the tracing gets recorded, but never matched or if there are still some other parts in the code that must get adjusted. I'm just dropping this clue here for more skilled persons.

Comment 18

[Nicholas Nethercote [inactive]]

Comment on attachment 502831 [details] [diff] [review]
Incompete patch solves mismatching?

I don't understand the switch code, I think dmandelin wrote it.

Comment 19

[Hannes Verschore [:h4writer]]

(In reply to comment #18)
> Comment on attachment 502831 [details] [diff] [review]
> Incompete patch solves mismatching?
> 
> I don't understand the switch code, I think dmandelin wrote it.

Well, I'm not to sure about the code either and this patch just let it work, but I'm not sure if there are other consequences. Also in bug #625494 I rewrote everything of the switchcase. So this patch is actually obsolete?

Comment 20

[Hannes Verschore [:h4writer]]

Ah I finally found the real problem in the code.

So in the code a tableswitch will add a guard.
This guard will always get taken. So we will always exit here.

On the guard a new trace is recorded (according to the actual case).
So the tableswitch gets traced again (intended) and in the code there is a corresponding if that just let the recording go further (so this time the tableswitch doesn't add code to the trace)

This is the corresponding code:
    jsbytecode* pc = cx->regs->pc;
    /* Starting a new trace after exiting a trace via switch. */
    if (anchor &&
        (anchor->exitType == CASE_EXIT || anchor->exitType == DEFAULT_EXIT) &&
        fragment->ip == pc) {
        return ARECORD_CONTINUE;
    }

Now condition isn't specific enough. It should also check if the tableswitch instruction is the first instruction in the traced code.


I will now explain how this testcase could trigger this bug (just as extra information)

1) V the for-loop in the calc function eventually starts tracing
2) V the function g(b) gets called
3) V the tableswitch get's parsed and the necessary guard is added
4) V the tableswitch forces the current trace to stop
5) V the following code just get run in the interpreter
6) V the tracecode of the for-loop in the calc function runs
7) V guards on 2 (g(b) and b equals 2)
8) V a new trace starts (on the tableswitch's guard)
9) V the tableswitch just returns ARECORD_CONTINUE without adding code to the trace
10) V g(i) gets called
11) X the tableswitch just returns ARECORD_CONTINUE
12) ...

11 -> it returns ARECORD_CONTINUE, because:
- anchor exists (from previous switch: g(b))
- anchor->exitType equals CASE_EXIT (from previous switch: g(b))
- ip equals pc, because it is the same code so on the same ip.

Expected result:
11 -> writes the guard for the tableswitch and stops the recorder

Comment 21

[Jason Orendorff [:jorendorff]]

In other words, tableswitch() is assuming that we won't trace the same JSOP_TABLESWITCH again in the new trace. But in this case, we do, because

    function g(n) {
        switch (n) {
          case 1: break;
          default: assertEq(n, 0);
        }
    }

    var b = 1;
    for (j = 0; j < 20; j++) {
        g(b);
        g(j % 2);
    }

there are two calls to g in the loop. We start at the JSOP_TABLESWTICH in g. We trace out of the first call and into the second. When we hit the same JSOP_TABLESWITCH a second time, we erroneously fail to emit any code.

Comment 22

[Hannes Verschore [:h4writer]]

There are 2 solutions:

1) Easy fix:

Add a number to TraceRecorder counting how many instructions are already recorded in that trace.

Then in the tableswitch it get's checked if the side-exit is CASE_EXIT. If there are no instructions recorded yet then just RECORD_CONTINUE, else write the lir instructions.

2) Harder fix:

When a new trace is started on the side-exit CASE_EXIT, somehow don't start the trace on the switch but on the next instruction.(Advance pc somehow)

Comment 23

[Hannes Verschore [:h4writer]]

I'm willing to solve this bug,
but I have no idea what the best way would be to fix it.
So can one of the TM-guys have a look and tell his findings?

Comment 24

[Nicholas Nethercote [inactive]]

3) Really easy fix:  

Get rid of tableswitch().  If I do that this problem is fixed, as is the one in bug 635657 (which is very likely a dupe of this bug).

Reason to get rid of it:
- Is tableswitch() necessary now that we have JM?  
- It's only implemented on i386.
- This isn't the first bug in it.
- Tracing switch statements feels like a losing proposition.  
- Getting rid of it didn't hurt Sunspider with either '-j -m -p' or just '-j'.

Reasons to keep it:
- Bug 475115, the original implementation, mentions that it helps the JSSpeccy and jsMSX demos, whatever they are.

Comment 25

[David Anderson [:dvander] - inactive, e-mail if emergency]

I'm all for removing switch-support from the tracer. As you said, it only works on one platform. Tableswitch is inlined in JM thanks to Jan de Mooij, and bug 475115 was measured back when the interpreter dominated.

Dave should weigh in too.

Comment 26

[David Mandelin [:dmandelin]]

(In reply to comment #24)
> 3) Really easy fix:  
> 
> Get rid of tableswitch().  If I do that this problem is fixed, as is the one in
> bug 635657 (which is very likely a dupe of this bug).
> 
> Reason to get rid of it:
> - Is tableswitch() necessary now that we have JM? 

Maybe not; see below.

> - It's only implemented on i386.
> - This isn't the first bug in it.
> - Tracing switch statements feels like a losing proposition.  

I think it's a reasonable thing to do. The bug here seems to relate to the difficulty of communicating information about exactly what state we're in and what we have to compile. Unfortunately, it may be hard to make that code simple without substantial refactoring.

> - Getting rid of it didn't hurt Sunspider with either '-j -m -p' or just '-j'.
> 
> Reasons to keep it:
> - Bug 475115, the original implementation, mentions that it helps the JSSpeccy
> and jsMSX demos, whatever they are.

http://matt.west.co.tt/spectrum/jsspeccy/
http://jsmsx.sourceforge.net/

If those don't regress without tracing tableswitch, I'd be down with removing it.

Comment 27

[Hannes Verschore [:h4writer]]

Here I add some data to make a better decision. I wouldn't make a decision on this data only, but it's a start.

I've run JSNES (is inspired by jsspeccy)

I ran the benchmark code in the JSNES suite in a browser build.
(Build myself from mozilla-central today (--enable-optimize and -j4))

With Tableswitch (clean profile):
Average of 100 runs: 73.97ms, sd: 63.1691
Average of 100 runs: 74.25ms, sd: 63.0075
Average of 100 runs: 73.56ms, sd: 69.18639999999999
Average of 100 runs: 74.40ms, sd: 96.42000000000007

Without Tableswitch (clean profile)::
Average of 100 runs: 74.02ms, sd: 75.81959999999994
Average of 100 runs: 74.13ms, sd: 73.13309999999997

With Tableswitch (clean profile, disabled methodjit):
Run 0, 383ms
Run 1, 390ms
Run 2, 383ms
Run 3, 382ms
Run 4, 386ms
Run 5, 385ms
Run 6, 364ms
Run 7, 319ms
Run 8, 854ms
Run 9, 840ms

Without Tableswitch (clean profile, disabled methodjit):
Run 0, 409ms
Run 1, 409ms
Run 2, 408ms
Run 3, 407ms
Run 4, 404ms
Run 5, 409ms
Run 6, 403ms
Run 7, 410ms
Run 8, 872ms
Run 9, 850ms

I also ran the testcase in bug 475115 in a shell build
(Build myself from tracemonkey that is 1 a 2 weeks old (--disable-optimize and --enable-debug) and adjusted MAX_BRANCHES to 64)

With Tableswitch: -j
47 ms
47 ms
48 ms
47 ms

Without Tableswitch: -j
107 ms
128 ms
126 ms
134 ms

With Tableswitch: -j -m -p
15 ms
15 ms
14 ms
16 ms

Without Tableswitch: -j -m -p
12 ms
11 ms
12 ms
12 ms


So in both cases there is indeed a difference when tableswitch is used or not. At least when only tracemonkey is running. When methodjit is enabled the differences are negligible. In the second case it is even faster. No idea why???

Comment 28

[David Mandelin [:dmandelin]]

(In reply to comment #27)
> When methodjit is enabled the
> differences are negligible. In the second case it is even faster. No idea
> why???

Hey, thanks for doing those experiments!

My first guess as to why we would be faster w/o tableswitch with -m -j -p is that having tableswitch allows us to trace something that runs faster in the methodjit (which may or may not be the switch itself). That seems like evidence for Nick's claim that "Tracing switch statements feels like a losing proposition" (which I previously questioned).

Comment 29

[Nicholas Nethercote [inactive]]

dmandelin, I looked briefly at jsMSX and JSSpeccy, both were non-obvious how to run... if you're think haytjes' data is sufficient to remove tableswitch I am too! :)

Comment 30

[Hannes Verschore [:h4writer]]

Ok, I also tried JSSpeccy in the browser build I have.
I measured the time it took to run the first 100 frames of wotef.sna

With tableswitch:
Total time of 100 frames: 1656.00ms
Total time of 100 frames: 1685.00ms
Total time of 100 frames: 1682.00ms
Total time of 100 frames: 1672.00ms

With tableswitch - disable methodJIT
Total time of 100 frames: 1673.00ms
Total time of 100 frames: 1668.00ms
Total time of 100 frames: 1634.00ms
Total time of 100 frames: 1642.00ms

Without tableswitch:
Total time of 100 frames: 1622.00ms
Total time of 100 frames: 1626.00ms
Total time of 100 frames: 1592.00ms
Total time of 100 frames: 1631.00ms

Without tableswitch - disable methodJIT
Total time of 100 frames: 1633.00ms
Total time of 100 frames: 1633.00ms
Total time of 100 frames: 1638.00ms
Total time of 100 frames: 1619.00ms

So here I saw the same trend. When I removed the tableswitch JSSpeccy was faster then with the tableswitch. But I do wonder why disabling methodJIT didn't give a speed regression?

Comment 31

[David Mandelin [:dmandelin]]

(In reply to comment #29)
> dmandelin, I looked briefly at jsMSX and JSSpeccy, both were non-obvious how to
> run... if you're think haytjes' data is sufficient to remove tableswitch I am
> too! :)

We might end up having to reverse that decision after getting some future bug report, but, yes, I think haytjes' data is sufficient to remove it and see.

Comment 32

[Nicholas Nethercote [inactive]]

Attachment: patch (against TM 62537:335dbb9502e0)

This patch excises tableswitch() and related pieces.

Comment 33

[David Mandelin [:dmandelin]]

The patch looks good but I'm wondering if we want to abort when we hit a tableswitch.

Comment 34

[Nicholas Nethercote [inactive]]

(In reply to comment #33)
> The patch looks good but I'm wondering if we want to abort when we hit a
> tableswitch.

You mean JSOP_TABLESWITCH, ie. get rid of TraceRecorder::switchop()?  Yeah, I was wondering about that too.  That would also affect JSOP_LOOKUPSWITCH and JSOP_LOOKUPSWITCHX.

Do you think any of this is suitable for 4.0?

Comment 35

[David Anderson [:dvander] - inactive, e-mail if emergency]

(In reply to comment #34)
> Do you think any of this is suitable for 4.0?

The reward/risk payoff doesn't seem extremely high: the perf gains are low, and the actual correctness issue goes back to, probably, 3.5 so it's not a recent regression. I'm only saying this because touching either JIT gives you a 10-yard risk penalty :)

Comment 36

[David Mandelin [:dmandelin]]

(In reply to comment #34)
> (In reply to comment #33)
> > The patch looks good but I'm wondering if we want to abort when we hit a
> > tableswitch.
> 
> You mean JSOP_TABLESWITCH, ie. get rid of TraceRecorder::switchop()?  Yeah, I
> was wondering about that too.  That would also affect JSOP_LOOKUPSWITCH and
> JSOP_LOOKUPSWITCHX.

No, I just meant aborting on tableswitch only. Anyway, I tried JSNES Super Mario with and without this patch, and it doesn't regress, so maybe that's good enough for now. We should still wait until after 4 to land.

Comment 37

[Nicholas Nethercote [inactive]]

http://hg.mozilla.org/tracemonkey/rev/53a3258235a1

Comment 39

[Chris Leary [:cdleary] (not checking bugmail)]

http://hg.mozilla.org/mozilla-central/rev/53a3258235a1