User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-GB; rv:1.9.1.5) Gecko/20091102 Firefox/3.5.5 (.NET CLR 2.0.50727) Build Identifier: Local m-c build Tracemonkey made things a whole lot slower in a real-world intranet app. Some specific issues have been raised in other bugs and mostly addressed, however a significant slowdown remains. There is some TMFLAGS debug output attached here which shows (I think) a lot of side exits but I need help to work out why those are happening and hence be able to provide test cases. Reproducible: Always I got the numbers below from a local m-c debug build setting TMFLAGS=stats. Also attaching the output from TMFLAGS=minimal,abort. recorder: started(949), aborted(472), completed(1704), different header(0), trees trashed(17), slot promoted(0), unstable loop variable(680), breaks(37), returns(104), merged loop exits(541), unstableInnerCalls(117), blacklisted(103) monitor: exits(71878), timeouts(8), type mismatch(0), triggered(71886), global mismatch(48), flushed(49) My naive intepretation is that the recorder is working passably well (some aborted traces but more completed ones) but the code generated from the traces is virtually always produces a side exit. I would be happy to provide reduced test cases in separate bugs that block this, however I could use some help interpreting the debug output and working out what to do next.

=> Javascript

One of the things my app uses is generators and iterators. It's easy to reproduce aborts using those, for example using the examle from https://developer.mozilla.org/en/New_in_javascript_1.7. Is a generator/iterator loop something that should be traced ? $ cat g.js function fib() { var i = 0, j = 1; while (true) { yield i; var t = i; i = j; j += t; } } var g = fib(); for (var i = 0; i < 10; i++) { print(g.next()); } $ ./js -j g.js 0 Recording starting from g.js:12@30 (FragID=000000) Abort recording of tree g.js:12@30 at g.js:4@19: attempt to reenter interpreter while recording. Recording starting from g.js:3@14 (FragID=000000) Abort recording of tree g.js:3@14 at g.js:4@18: yield. 1 1 2 3 5 8 13 21 34 recorder: started(2), aborted(2), completed(0), different header(0), trees trashed(0), slot promoted(0), unstable loop variable(0), breaks(0), returns(0), merged loop exits(0), unstableInnerCalls(0), blacklisted(0) monitor: exits(0), timeouts(0), type mismatch(0), triggered(0), global mismatch(0), flushed(1) $

We don't trace generators at all. It was not really considered a priority since they are a Mozilla-specific extension.

Ah - that would explain a small number of my aborted traces. I'm actually more stuck with the 70,000 exits - is there a way to get more information about those ?

Yeah, try TMFLAGS=full. It prints out every trace exit/entry. Exits tell you where exactly we fall of trace, and why (exit code).

I'll give that a go tommorrow, hopefully will be able to get counts of different kinds of exits.

TMFLAGS=full is too crashy and the output is gigabytes. Here's TMFLAGS=tracer,abort,minimal,stats for a scaled down test - still 37M unzipped (1.3M zipped) I will have a stab at interpreting this but do tell if anything interesting jumps out.

$ grep "leaving trace" /cygdrive/C/Temp/ff.txt | cut -f4 -d, | sort | uniq -c 1336 exitType=BRANCH 26 exitType=DEEP_BAIL 4344 exitType=LOOP 1593 exitType=MISMATCH 194 exitType=NESTED 4 exitType=RECURSIVE_EMPTY_RP 73 exitType=RECURSIVE_LOOP 5 exitType=RECURSIVE_MISMATCH 4 exitType=RECURSIVE_SLURP_MISMATCH 2 exitType=RECURSIVE_UNLINKED 73 exitType=TIMEOUT 15 exitType=UNSTABLE_LOOP $

$ cat /cygdrive/C/Temp/ff.txt | tr 1234567890 NNNNNNNNNN | sort | uniq -c | sort -nr | head -20 18523 checkType slot NN: interp=B typemap=B isNum=N promoteInt=N 17866 checkType slot NN: interp=S typemap=S isNum=N promoteInt=N 11473 checkType slot NN: interp=O typemap=O isNum=N promoteInt=N 9160 checkType slot N: interp=O typemap=O isNum=N promoteInt=N 7280 checkType slot NN: interp=I typemap=I isNum=N promoteInt=N 4611 capture type varNN: N=B 3506 capture type varNN: N=S 3141 checkType slot N: interp=I typemap=I isNum=N promoteInt=N 3059 checkType slot N: interp=S typemap=S isNum=N promoteInt=N 2826 checkType slot NN: interp=N typemap=N isNum=N promoteInt=N 2599 checkType slot N: interp=B typemap=B isNum=N promoteInt=N 2590 import vp=NNNFNDNN name=$varNN type=string flags=N 2431 checkType slot N: interp=F typemap=F isNum=N promoteInt=N 2308 import vp=NNANNNNN name=$globalN type=boolean flags=N 2304 2112 import vp=NNNFNDNN name=$varNN type=boolean flags=N 2089 checkType slot N: interp=N typemap=N isNum=N promoteInt=N 1854 capture type varN: N=O 1663 capture type globalN: N=B 1508 trying to attach another branch to the tree (hits = N) $

There's quite a lot of this leaving trace at file:///C:/starteam/Construction/software/BPTM/BPTMPresentation/code/source/com/bt/util/logging/presentation/BPTMDiagram.js:5272@276, op=getelem, lr=089E01C0, exitType=MISMATCH, sp=4, calldepth=0, cycles=0 The relevant code fragment is below. I can't figure out why it would fall off trace there and in a small test program it doesn't. Gal, anyone, why would that be happening ? What should I do to reproduce this in a small program ? I'm happy to go away and read up on background if someone can post a reference. Can also post more of the code if required. var childGraphIDs=this.childGraphIDArray[TSMKeys][lBox.tierKey + DELIMITER3 + threadID]; //if (childGraphIDs==null) return {}; // TSM record with blank threadID... var graphIDNoDUP=stripDUP(graphID); var noSecondPass=false; var parent; if (copiedSummaryFlow) if (firstPass) parent=parentGraphID(graphIDNoDUP); for (var childMessageTypeAndGraphID in childGraphIDs) { var childThreadIDs=childGraphIDs[childMessageTypeAndGraphID]; var values=childThreadIDs.split(DELIMITER3); var childRThreadID=values[0]; var childLThreadID=values[1]; // <=============== line 5272, MISMATCH exits here var values=childMessageTypeAndGraphID.split(DELIMITER3); var childGraphID=values[0]; var childMessageType=values[1]; var childREQOrRCT=(childMessageType=="REQ" || childMessageType=="RCT"); if (firstPass) if (!copiedSummaryFlow) if (!REQOrRCT) if (childREQOrRCT) noSecondPass=true; if (childRThreadID=="") continue;

I filed bug 531629 with a small test program producing continual MISMATCH exits, however not 100% sure it's the same effect. The test case for that bug only produces MISMATCH exits when a statement 'var x="obj=" + {};' is added. This is not present in my real app.

Shell test - it's a monster but is self contained at least. Does not reproduce mismatch exits that occur when the same code runs in the browser but does show performance degradation with JIT, around 3x. $ ./js BPTMDiagram.js START TEST Drawing diagram 1 of 1: Building message arrays... Drawing diagram 1 of 1: Building message arrays... Drawing diagram 1 of 1: Creating initial layout... Drawing diagram 1 of 1: Creating final layout... Drawing diagram 1 of 1: Creating SVG... Drawing diagram 1 of 1: Drawing SVG... END TEST, time=2046 $ export TMFLAGS=stats $ ./js -j BPTMDiagram.js START TEST Drawing diagram 1 of 1: Building message arrays... Drawing diagram 1 of 1: Building message arrays... Drawing diagram 1 of 1: Creating initial layout... Drawing diagram 1 of 1: Creating final layout... Drawing diagram 1 of 1: Creating SVG... Drawing diagram 1 of 1: Drawing SVG... END TEST, time=5654 recorder: started(350), aborted(194), completed(706), different header(0), trees trashed(59), slot promoted(0), unstable loop variable(335), breaks(17), returns(6), merged loop exits(219), unstableInnerCalls(63), blacklisted(35) monitor: exits(3254), BRANCH(1122), CASE(0), DEFAULT(0), LOOP(2128), NESTED(0), MISMATCH(0), OOM(0), OVERFLOW(0), UNSTABLE_LOOP(4), TIMEOUT(0), DEEP_BAIL(0), STATUS(0), RECURSIVE_UNLINKED(0), RECURSIVE_LOOP(0), RECURSIVE_MISMATCH(0), RECURSIVE_EMPTY_RP(0), RECURSIVE_SLURP_FAIL(0), RECURSIVE_SLURP_MISMATCH(0), timeouts(0), type mismatch(0), triggered(3254), global mismatch(1), flushed(2) $

Merge traces *might* help here. Marking as depends on 516264, 523497 because I'd like to see what the effect is when one or other of those land.

This is much better in Fx 4 No JIT - 370ms Trace JIT - 330-400ms Method JIT - 270ms Trace and Method JIT - 300ms Resolving WFM

Slightly improved in Fx 8 No JIT - 350ms Trace JIT - 360ms Method JIT - 250ms Trace and Method JIT - 260ms