454569 - TM: bitwise-and 6-10x slower on second and subsequent iterations in full suite

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect, P2)

Description

[Mike Shaver (:shaver emeritus)]

Running sunspider in-browser with the JIT on, I see the expected 6ms for the first run on my MBP under Vista, but then it jumps to 35-40.  If I then run the bitwise-and page itself in the same tab, I get 30-70(!) ms for it.  If I open the single-test page in a new tab and reload, I get consistent ~6-12ms results.  Opening the whole test suite in a new tab doesn't give me the 6ms result back (first iteration's bitwise-and most recently was 75ms!)  

This system seems to be a bit noisy (safari shows +/- 1.4%, with a few individual tests at around +/- 20%), but I see a lot more variability with the JIT on, on bitwise-and and other tests.  I'll try disabling some more vista services and see if I can get it to be generally calmer as well.

New tab means new context, give or take -- possibly some oracle interaction gone bad?

Comment 1

[Mike Shaver (:shaver emeritus)]

I should add: Gecko/20080909032504, packaged nightly.

Comment 2

[Brendan Eich [:brendan]]

Graydon kindly offered to look into this for b2, after the nanojit/tamarin-redux merge. This should block until we know it's not an issue (WFM, if not FIXED due to a known bug).

/be

Comment 3

[Graydon Hoare :graydon]

Can reproduce on the named build, but not on trunk. Will bisect down to a specific rev to work out why. I'm not sure if it's our policy to block a release waiting on an explanation for a vanished bug? Or can anyone else reproduce with newer revs?

Comment 4

[Robert Sayre]

No, we won't block on a WFM bug.

Comment 5

[Graydon Hoare :graydon]

No longer WFM; I can reproduce on TM tip now. Not sure why I wasn't able to before. Here's a reduced testcase that trips it in the JS shell:

function f()
{
  var d = Date.now();
  load('t/bitops-bitwise-and.js');
  print("bitwise-and time:" + (Date.now() - d));
}

f(); f(); f(); f(); f();
load('t/math-spectral-norm.js');
f(); f(); f(); f(); f();

IOW it's just spectral-norm interfering with the trace of bitwise-and. I don't quite see how yet. I'll dig into the traces tomorrow. (They both access a global index variable 'i', perhaps?)

Comment 6

[Andreas Gal :gal]

Good job on reproducing this. Maybe the oracle overflows and we demote something we shouldn't?

Comment 7

[Graydon Hoare :graydon]

Ok, worked it out. Problem is there are two quite independent bugs here and I was thinking each was causing half the symptoms of the other. Got confusing. They are unrelated.

The short answer is "it's behaving as designed". The first bug -- that's causing *most* of the slowness -- is simply that the oracle's "hashing" (ahem) scheme for global slots is really collision-happy, and a global in spectral-norm that is marked as undemotable winds up infecting the loop variable in bitwise-and, making *it* undemotable as well. This can be fixed by improving the hashing done, nothing too complex. I'll post a patch in a moment.

There is a second bug in here that I'll make note of in passing, which might surprise you: even when you *don't* run spectral-norm, we recompile bitwise-and every single time we load it, no exception. The reason is that bitwise-and does something odd: it has a global that changes type, from double to int, after exactly 1 loop-edge. The accumulator variable. So when we compile, we are on the 2nd loop-edge and we see an int, compile a specialized-int variant, run it, and are happy. But the next time we load the script, we hit the same ip on the *first* loop-edge and think we're seeing a global type mismatch. If we waited for one more iteration we'd see the old type return, but we're paranoid about global type mismatches so we immediately flush the cache and recompile, every time. So the speed of bitwise-and is, in fact, always the speed of compiling as well as the speed of running. You never get to recycle the fragment between loads.

Fixing this would be more work: the cache would need to not flush, and we'd need to build peers for different global typemaps, presumably flushing them out as they age, the same way we handle non-global typemaps. I asked dvander why we don't do this, and he said it seemed too difficult to get right when he was initially writing the multitree system. But it seems plausible, sometime in the future.

Comment 8

[Graydon Hoare :graydon]

Huh! It's easy to write a hash that fixes this *particular* bug, but any sensible hash seems to provoke a huge regression on fasta. So I'll have to look at this a bit more tomorrow.

Comment 9

[Graydon Hoare :graydon]

Attachment: patch correcting problem

Phew. There were a lot of weird symptoms here, but they all boil down to one thing: the existing hash was quite wrong. The simplest correction I made to it was also wrong, because it caused inconsistent views of the same global from different scripts (such as separate functions in a single enclosing file) to occur, which would cause a cache-flush. This is what was going wrong in fasta. But I've made a more complete correction that walks up to the root frame, uses its script, and incorporates the global object and its shape as well. Behaves fine now. 

There is still a way this can fail. If two different traces form based on the same stack slot, but referring to it from different scripts or with different stack-slot numbers (such as from two separate nested functions with a common parent), we may wind up doing too much compilation, but I think this will be a less-serious problem than in the global case, because we build peers when we get a stack slot mismatch, rather than destroying the entire fragment cache as with a global mismatch.

I also took the opportunity to improve a couple diagnostic printers, separate the global and stack oracle bitsets, and factor out the hashing function.

Comment 10

[Andreas Gal :gal]

Comment on attachment 349536 [details] [diff] [review]
patch correcting problem

Nice. The old oracle code was a left-over from the early days. The interface was meant to be complete enough to store the oracle state to disk and re-use it between browser runs. We still might want to look into that.

Comment 11

[Graydon Hoare :graydon]

Pushed to tracemonkey repository (with a change to void on the return type of the accumulate function, cl caught it) in revision 19ffa19b4697.

Comment 12

[Brendan Eich [:brendan]]

Comment on attachment 349536 [details] [diff] [review]
patch correcting problem

>+static inline unsigned 
>+hash_accum(unsigned & h, unsigned i)

Belated drive-by nits: in jstracer.{cpp,h} and other new code, and probably file-by-file as we go elsewhere (but not at smaller increments, making a mixed-style mess), we are using C++ declarator-mode-cuddles-type-not-declarator-name style. So unsigned& h.

Same goes for JSContext *cx => JSContext* cx, e.g., and other changed/added lines in the patch.

rs=me on followup fix for tracemonkey repo, no need for attach/request/review cycle.

>+    hash_accum(h, unsigned(cx->fp->script));
>+    hash_accum(h, unsigned(cx->fp->regs->pc));

Are these warning-free on 64-bit builds? See JS_PTR_TO_UINT32, or just use uintptr_t?

/be

Comment 13

[Graydon Hoare :graydon]

Pushed style fixes. To a point. Much of avmplus seems a bit loose about choice of int types, so for example the avmplus::BitSet interface is all in terms of 'int' indices. I may get around to filing bugs on this, at some point.

Comment 14

[Robert Sayre]

http://hg.mozilla.org/mozilla-central/rev/19ffa19b4697

Comment 15

[Robert Sayre]

er, that should be
http://hg.mozilla.org/releases/mozilla-1.9.1/rev/c1d5fd26a5f0

Comment 16

[Christian Holler (:decoder)]

Bug in removed tracer code, setting in-testsuite- flag.