1252228 - Wrong function is inlined (but not executed) in kraken stanford-crypto-pbkdf2 benchmark.

Status: RESOLVED FIXED

(Core :: JavaScript Engine: JIT, defect)

Description

[Tooru Fujisawa [:arai]]

While executing stanford-crypto-ccm and stanford-crypto-pbkdf2 sequentially in kraken benchmark in arewefastyet, like following command:

js \
    --ion-offthread-compile=off \
    -e "var tests = ['stanford-crypto-ccm', 'stanford-crypto-pbkdf2'], suitePath = 'test/kraken-1.1'; suiteName='kraken-1.1';" \
    -f resources/sunspider-standalone-driver.js


A function defined in stanford-crypto-ccm-data.js is inlined into a function defined in stanford-crypto-pbkdf2-data.js. they don't share any code, but use same global variable name and similar object structure, and same function body for some functions.


https://dxr.mozilla.org/mozilla-central/rev/5e0140b6d11821e0c2a2de25bc5431783f03380a/js/src/jit/IonBuilder.cpp#6611
> bool
> IonBuilder::jsop_call(uint32_t argc, bool constructing)
> {
> ...
>     // Acquire known call target if existent.
>     ObjectVector targets(alloc());
>     TemporaryTypeSet* calleeTypes = current->peek(calleeDepth)->resultTypeSet();
>     if (calleeTypes && !getPolyCallTargets(calleeTypes, constructing, targets, 4))
>         return false;
> 
>     CallInfo callInfo(alloc(), constructing);
>     if (!callInfo.init(current, argc))
>         return false;
> 
>     // Try inlining
>     InliningStatus status = inlineCallsite(targets, callInfo);

while compiling 1st `new b` call in `sjcl.misc.hmac` [1] function in stanford-crypto-ccm-data.js, `getPolyCallTargets` returns `sjcl.hash.sha256` [2] function defined in stanford-crypto-ccm-data.js.

It should return `sjcl.hash.sha256` [3] function defined in stanford-crypto-ccm-data.js, or just return nothing.

here's prettified code.  The `sjcl.hash.sha256` definition in both files are same, but even I modified one of them to make them different, still function in stanford-crypto-ccm-data.js is inlined.

sjcl.misc.hmac = function(a, b) {
    this.M = b = b || sjcl.hash.sha256;
    var c = [
            [],
            []
        ],
        d = b.prototype.blockSize / 32;
    this.l = [new b, new b];
    if (a.length > d) a = b.hash(a);
    for (b = 0; b < d; b++) {
        c[0][b] = a[b] ^ 909522486;
        c[1][b] = a[b] ^ 1549556828
    }
    this.l[0].update(c[0]);
    this.l[1].update(c[1])
};

sjcl.hash.sha256 = function(a) {
    this.a[0] || this.w();
    if (a) {
        this.n = a.n.slice(0);
        this.i = a.i.slice(0);
        this.e = a.e
    } else this.reset()
};


[1] https://github.com/h4writer/arewefastyet/blob/master/benchmarks/kraken/tests/kraken-1.1/stanford-crypto-pbkdf2-data.js#L26
[2] https://github.com/h4writer/arewefastyet/blob/master/benchmarks/kraken/tests/kraken-1.1/stanford-crypto-ccm-data.js#L15
[3] https://github.com/h4writer/arewefastyet/blob/master/benchmarks/kraken/tests/kraken-1.1/stanford-crypto-pbkdf2-data.js#L26

Comment 1

[Tooru Fujisawa [:arai]]

posted totally wrong comment :P

I meant following

https://dxr.mozilla.org/mozilla-central/rev/
5e0140b6d11821e0c2a2de25bc5431783f03380a/js/src/jit/IonBuilder.cpp#6611
> bool
> IonBuilder::jsop_call(uint32_t argc, bool constructing)
> {
> ...
>     // Acquire known call target if existent.
>     ObjectVector targets(alloc());
>     TemporaryTypeSet* calleeTypes = current->peek(calleeDepth)->resultTypeSet();
>     if (calleeTypes && !getPolyCallTargets(calleeTypes, constructing, targets, 4))
>         return false;
> 
>     CallInfo callInfo(alloc(), constructing);
>     if (!callInfo.init(current, argc))
>         return false;
> 
>     // Try inlining
>     InliningStatus status = inlineCallsite(targets, callInfo);

while compiling 1st `new b` call in `sjcl.misc.hmac` [1] function in stanford-crypto-pbkdf2-data.js, `getPolyCallTargets` returns `sjcl.hash.sha256` [2] function defined in stanford-crypto-ccm-data.js.

It should return `sjcl.hash.sha256` [3] function defined in stanford-crypto-pbkdf2-data.js, or just return nothing.

Comment 2

[Tooru Fujisawa [:arai]]

the issue disappears with either following change:

1. rename `sjcl` to `sjcl2` in stanford-crypto-pbkdf2-data.js and stanford-crypto-pbkdf2.js.

2. apply following change to kraken test driver to run each test in different global

> --- a/benchmarks/kraken/resources/sunspider-standalone-driver.js
> +++ b/benchmarks/kraken/resources/sunspider-standalone-driver.js
> @@ -33,10 +33,11 @@ for (var krakenCounter = 0; krakenCounter < tests.length; krakenCounter++) {
>      var testBase = "tests/" + suiteName + "/" + tests[krakenCounter];
>      var testName = testBase + ".js";
>      var testData = testBase + "-data.js";
> +    var g = newGlobal();
>      // load test data
> -    load(testData);
> +    g.load(testData);
>      var startTime = new Date;
> -    load(testName);
> +    g.load(testName);
>      times[krakenCounter] = new Date() - startTime;
>      gc();
>  }


so, maybe an issue in type inference or similar place.

Comment 3

[Tooru Fujisawa [:arai]]

(In reply to Tooru Fujisawa [:arai] from comment #1)
> while compiling 1st `new b` call in `sjcl.misc.hmac` [1] function in
> stanford-crypto-pbkdf2-data.js, `getPolyCallTargets` returns
> `sjcl.hash.sha256` [2] function defined in stanford-crypto-ccm-data.js.

actually, sjcl.hash.sha256 in ccm is recorded to `current->peek(calleeDepth)` instruction (MUnbox), as singleton object.

>     TemporaryTypeSet* calleeTypes = current->peek(calleeDepth)->resultTypeSet();
>     if (calleeTypes && !getPolyCallTargets(calleeTypes, constructing, targets, 4))

Comment 4

[Tooru Fujisawa [:arai]]

forgot to note that the inlined *wrong* function is not actually executed.
also, there are several more functions seem to be inlined.

Comment 5

[Eric Faust [:efaust]]

marking ss until we can investigate this further. The title is terrifying.

Comment 6

[Tooru Fujisawa [:arai]]

Attachment: A patch to break on wrong inlining while debugging

To be clear, here's the way I confirmed this issue.
Let me know if I'm doing something wrongly.

Steps to reproduce:

  1. Apply attached patch (adds is_ccm function that is used in step 4)
  2. make test.js with following content

var tests = ['stanford-crypto-ccm', 'stanford-crypto-pbkdf2'], suitePath = 'test/kraken-1.1'; suiteName='kraken-1.1';

  3. run JS shell on debugger, inside arewefastyet/benchmarks/kraken

cd arewefastyet/benchmarks/kraken
lldb path/to/js

  4. add breakpoint to is_ccm function added in step 1

b is_ccm

  5. run benchmark

run --ion-offthread-compile=off -f test.js resources/sunspider-standalone-driver.js

Result:

get following log, and hit a breakpoint in is_ccm:

> ...
> **** IonBuilder, /Users/arai/projects/arewefastyet/benchmarks/kraken/tests/kraken-1.1/stanford-crypto-pbkdf2-data.js:307:19
> **** IonBuilder, /Users/arai/projects/arewefastyet/benchmarks/kraken/tests/kraken-1.1/stanford-crypto-pbkdf2-data.js:573:27
> **** IonBuilder, /Users/arai/projects/arewefastyet/benchmarks/kraken/tests/kraken-1.1/stanford-crypto-pbkdf2-data.js:553:25
> **** IonBuilder, /Users/arai/projects/arewefastyet/benchmarks/kraken/tests/kraken-1.1/stanford-crypto-ccm-data.js:294:27

the benchmark executes stanford-crypto-pbkdf2 *after* stanford-crypto-ccm.
so function in ccm shouldn't be compiled after a function in pbkdf2 gets compiled.


here's the backtrace:

* thread #1: tid = 0x63cefb, 0x0000000100347346 js`is_ccm() + 22 at IonBuilder.cpp:123, queue = 'com.apple.main-thread', stop reason = breakpoint 1.1
  * frame #0: 0x0000000100347346 js`is_ccm() + 22 at IonBuilder.cpp:123
    frame #1: 0x0000000100347868 js`js::jit::IonBuilder::IonBuilder(this=0x00007fff5fbf5350, analysisContext=0x0000000104241c00, comp=0x0000000104227000, options=0x00007fff5fbf694c, temp=0x00007fff5fbf67d0, graph=0x00007fff5fbf6738, constraints=0x000000010459e048, inspector=0x00007fff5fbf5300, info=0x00000001045a2ac8, optimizationInfo=0x0000000101e54bc8, baselineFrame=0x0000000000000000, inliningDepth=1, loopDepth=0) + 1272 at IonBuilder.cpp:180
    frame #2: 0x0000000100344510 js`js::jit::IonBuilder::IonBuilder(this=0x00007fff5fbf5350, analysisContext=0x0000000104241c00, comp=0x0000000104227000, options=0x00007fff5fbf694c, temp=0x00007fff5fbf67d0, graph=0x00007fff5fbf6738, constraints=0x000000010459e048, inspector=0x00007fff5fbf5300, info=0x00000001045a2ac8, optimizationInfo=0x0000000101e54bc8, baselineFrame=0x0000000000000000, inliningDepth=1, loopDepth=0) + 208 at IonBuilder.cpp:170
    frame #3: 0x0000000100365816 js`js::jit::IonBuilder::inlineScriptedCall(this=0x00007fff5fbf68c0, callInfo=0x00007fff5fbf5e18, target=0x000000010438e600) + 2118 at IonBuilder.cpp:5140
    frame #4: 0x0000000100367235 js`js::jit::IonBuilder::inlineSingleCall(this=0x00007fff5fbf68c0, callInfo=0x00007fff5fbf5e18, targetArg=0x000000010438e600) + 197 at IonBuilder.cpp:5652
    frame #5: 0x00000001003674a5 js`js::jit::IonBuilder::inlineCallsite(this=0x00007fff5fbf68c0, targets=0x00007fff5fbf5ea8, callInfo=0x00007fff5fbf5e18) + 581 at IonBuilder.cpp:5708
    frame #6: 0x000000010035697d js`js::jit::IonBuilder::jsop_call(this=0x00007fff5fbf68c0, argc=0, constructing=true) + 669 at IonBuilder.cpp:6645
    frame #7: 0x000000010034e186 js`js::jit::IonBuilder::inspectOpcode(this=0x00007fff5fbf68c0, op=JSOP_NEW) + 3206 at IonBuilder.cpp:1910
    frame #8: 0x000000010034abb7 js`js::jit::IonBuilder::traverseBytecode(this=0x00007fff5fbf68c0) + 999 at IonBuilder.cpp:1544
    frame #9: 0x0000000100344d24 js`js::jit::IonBuilder::build(this=0x00007fff5fbf68c0) + 2052 at IonBuilder.cpp:940
    frame #10: 0x00000001003437eb js`js::jit::AnalyzeNewScriptDefiniteProperties(cx=0x0000000104241c00, fun=0x00000001043e7380, group=0x0000000104341070, baseobj=js::HandlePlainObject @ 0x00007fff5fbf68b0, initializerList=0x00007fff5fbf7360) + 1483 at IonAnalysis.cpp:3729
    frame #11: 0x0000000100b4317a js`js::TypeNewScript::maybeAnalyze(this=0x00000001046c4910, cx=0x0000000104241c00, group=0x0000000104341070, regenerate=0x0000000000000000, force=true) + 1802 at TypeInference.cpp:3747
    frame #12: 0x0000000100320403 js`js::jit::IonCompile(cx=0x0000000104241c00, script=0x00000001043424a0, baselineFrame=0x00007fff5fbf7cf8, osrPc="\343\202V", constructing=false, recompile=false, optimizationLevel=Normal) + 2131 at Ion.cpp:2208
    frame #13: 0x000000010031aec4 js`js::jit::Compile(cx=0x0000000104241c00, script=JS::HandleScript @ 0x00007fff5fbf7a10, osrFrame=0x00007fff5fbf7cf8, osrPc="\343\202V", constructing=false, forceRecompile=false) + 1188 at Ion.cpp:2432
    frame #14: 0x000000010031b886 js`BaselineCanEnterAtBranch(cx=0x0000000104241c00, script=JS::HandleScript @ 0x00007fff5fbf7ac0, osrFrame=0x00007fff5fbf7cf8, pc="\343\202V") + 870 at Ion.cpp:2619
    frame #15: 0x000000010031b230 js`js::jit::IonCompileScriptForBaseline(cx=0x0000000104241c00, frame=0x00007fff5fbf7cf8, pc="\343\202V") + 720 at Ion.cpp:2678
    frame #16: 0x0000000100232ef6 js`js::jit::DoWarmUpCounterFallbackOSR(cx=0x0000000104241c00, frame=0x00007fff5fbf7cf8, stub=0x00000001062abf70, infoPtr=0x00007fff5fbf7ca0) + 390 at BaselineIC.cpp:141
    frame #17: 0x00000001034810b5

Comment 7

[Tooru Fujisawa [:arai]]

some more debug log that shows functions in different files are mixed

(lldb) up
up
frame #1: 0x0000000100347868 js`js::jit::IonBuilder::IonBuilder(this=0x00007fff5fbf5350, analysisContext=0x0000000104241c00, comp=0x0000000104227000, options=0x00007fff5fbf694c, temp=0x00007fff5fbf67d0, graph=0x00007fff5fbf6738, constraints=0x000000010459e048, inspector=0x00007fff5fbf5300, info=0x00000001045a2ac8, optimizationInfo=0x0000000101e54bc8, baselineFrame=0x0000000000000000, inliningDepth=1, loopDepth=0) + 1272 at IonBuilder.cpp:180
   177 	
   178 	    if (is_pbkdf2) {
   179 	        if (strstr(script_->filename(), "ccm") != nullptr) {
-> 180 	            is_ccm();
   181 	        }
   182 	    }
   183 	    if (strstr(script_->filename(), "pbkdf2") != nullptr) {
(lldb) 

frame #2: 0x0000000100344510 js`js::jit::IonBuilder::IonBuilder(this=0x00007fff5fbf5350, analysisContext=0x0000000104241c00, comp=0x0000000104227000, options=0x00007fff5fbf694c, temp=0x00007fff5fbf67d0, graph=0x00007fff5fbf6738, constraints=0x000000010459e048, inspector=0x00007fff5fbf5300, info=0x00000001045a2ac8, optimizationInfo=0x0000000101e54bc8, baselineFrame=0x0000000000000000, inliningDepth=1, loopDepth=0) + 208 at IonBuilder.cpp:170
   167 	    lazyArguments_(nullptr),
   168 	    inlineCallInfo_(nullptr),
   169 	    maybeFallbackFunctionGetter_(nullptr)
-> 170 	{
   171 	    script_ = info->script();
   172 	    fprintf(stderr, "**** IonBuilder, %s:%zu:%zu\n",
   173 	            script_->filename(),
(lldb) 

frame #3: 0x0000000100365816 js`js::jit::IonBuilder::inlineScriptedCall(this=0x00007fff5fbf68c0, callInfo=0x00007fff5fbf5e18, target=0x000000010438e600) + 2118 at IonBuilder.cpp:5140
   5137	    AutoAccumulateReturns aar(graph(), returns);
   5138	
   5139	    // Build the graph.
-> 5140	    IonBuilder inlineBuilder(analysisContext, compartment, options, &alloc(), &graph(), constraints(),
   5141	                             &inspector, info, &optimizationInfo(), nullptr, inliningDepth_ + 1,
   5142	                             loopDepth_);
   5143	
(lldb) p script_->filename()
p script_->filename()
(const char *) $0 = 0x00000001046c1f60 "/Users/arai/projects/arewefastyet/benchmarks/kraken/tests/kraken-1.1/stanford-crypto-pbkdf2-data.js"
(lldb) p script_->lineno()
p script_->lineno()
(size_t) $1 = 553
(lldb) p script_->column()
p script_->column()
(size_t) $2 = 25
(lldb) p calleeScript
p calleeScript
(JSScript *) $3 = 0x000000010436e3d0
(lldb) p calleeScript->filename()
p calleeScript->filename()
(const char *) $4 = 0x00000001046b49b0 "/Users/arai/projects/arewefastyet/benchmarks/kraken/tests/kraken-1.1/stanford-crypto-ccm-data.js"
(lldb) p calleeScript->lineno()
p calleeScript->lineno()
(size_t) $5 = 294
(lldb) p calleeScript->column()
p calleeScript->column()
(size_t) $6 = 27

Comment 8

[Tooru Fujisawa [:arai]]

and more log that shows resultTypeSet contains wrong thing.

(lldb) up
up
frame #4: 0x0000000100367235 js`js::jit::IonBuilder::inlineSingleCall(this=0x00007fff5fbf68c0, callInfo=0x00007fff5fbf5e18, targetArg=0x000000010438e600) + 197 at IonBuilder.cpp:5652
   5649	    // Track success now, as inlining a scripted call makes a new return block
   5650	    // which has a different pc than the current call pc.
   5651	    trackInlineSuccess();
-> 5652	    if (!inlineScriptedCall(callInfo, target))
   5653	        return InliningStatus_Error;
   5654	    return InliningStatus_Inlined;
   5655	}
(lldb) up
up
frame #5: 0x00000001003674a5 js`js::jit::IonBuilder::inlineCallsite(this=0x00007fff5fbf68c0, targets=0x00007fff5fbf5ea8, callInfo=0x00007fff5fbf5e18) + 581 at IonBuilder.cpp:5708
   5705	            callInfo.setFun(constFun);
   5706	        }
   5707	
-> 5708	        return inlineSingleCall(callInfo, target);
   5709	    }
   5710	
   5711	    // Choose a subset of the targets for polymorphic inlining.
(lldb) up
up
frame #6: 0x000000010035697d js`js::jit::IonBuilder::jsop_call(this=0x00007fff5fbf68c0, argc=0, constructing=true) + 669 at IonBuilder.cpp:6645
   6642	        return false;
   6643	
   6644	    // Try inlining
-> 6645	    InliningStatus status = inlineCallsite(targets, callInfo);
   6646	    if (status == InliningStatus_Inlined)
   6647	        return true;
   6648	    if (status == InliningStatus_Error)
(lldb) p calleeTypes
p calleeTypes
(js::TemporaryTypeSet *) $7 = 0x00000001045a0630
(lldb) p calleeTypes->getObjectCount()
p calleeTypes->getObjectCount()
(unsigned int) $8 = 1
(lldb) p calleeTypes->getSingleton(0)
p calleeTypes->getSingleton(0)
(JSObject *) $9 = 0x000000010438e600
(lldb) p ((JSFunction*)calleeTypes->getSingleton(0))->nonLazyScript()
p ((JSFunction*)calleeTypes->getSingleton(0))->nonLazyScript()
(JSScript *) $10 = 0x000000010436e3d0
(lldb) p ((JSFunction*)calleeTypes->getSingleton(0))->nonLazyScript()->filename()
p ((JSFunction*)calleeTypes->getSingleton(0))->nonLazyScript()->filename()
(const char *) $11 = 0x00000001046b49b0 "/Users/arai/projects/arewefastyet/benchmarks/kraken/tests/kraken-1.1/stanford-crypto-ccm-data.js"
(lldb) p ((JSFunction*)calleeTypes->getSingleton(0))->nonLazyScript()->lineno()
p ((JSFunction*)calleeTypes->getSingleton(0))->nonLazyScript()->lineno()
(size_t) $12 = 294
(lldb) p ((JSFunction*)calleeTypes->getSingleton(0))->nonLazyScript()->column()
p ((JSFunction*)calleeTypes->getSingleton(0))->nonLazyScript()->column()
(size_t) $13 = 27

Comment 9

[Tooru Fujisawa [:arai]]

what could be the reason why wrong function is added to the result type set?
where should I look into next?

Comment 10

[Tooru Fujisawa [:arai]]

in the graphs generated by iongraph, all references to function in stanford-crypto-ccm-data.js is "call"ed, not inlined.
(iiuc, if a functions is inlined, the function's constant is shown in the graph but the constant is not referred, and the block jumps to the next block that is the inlined code, right?)

functions referred (called) in the graph are following:
  * sjcl.bitArray.P
  * sjcl.bitArray.clamp
  * sjcl.bitArray.concat
  * sjcl.codec.utf8String.toBits
  * sjcl.exception.invalid

functions passed to IonBuilder ctor (from IonBuilder::inlineScriptedCall) are following:
  * sjcl.bitArray.partial
  * sjcl.bitArray.getPartial
  * sjcl.bitArray.P
  * sjcl.codec.utf8String.toBits
  * sjcl.hash.sha256
  * sjcl.hash.sha256.hash

will look into how those possibly inlined code is handled later today (maybe discarded somewhere?)

Comment 11

[Jan de Mooij [:jandem]]

This seems pretty weird, looking into it..

Comment 12

[Jan de Mooij [:jandem]]

Attachment: Patch

There's an heuristic in PropertyReadNeedsTypeBarrier that adds property types to the observed typeset if the observed set is empty. It only adds the first type, though, so that's causing the confusion here. This patch changes the |if (types.length())| check to |if (types.length() == 1)|.

Not a correctness bug because we'll add a type barrier that will bail at runtime.

Comment 13

[Eric Faust [:efaust]]

Comment on attachment 8725132 [details] [diff] [review]
Patch

Review of attachment 8725132 [details] [diff] [review]:
-----------------------------------------------------------------

Works for me.

Comment 14

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/9d9502981ba6

Comment 15

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/9d9502981ba6