Jest: Calls to Math are several orders of magnitude slower than when run outside of Jest

[theblang]

It appears that at least some calls to Math (only tested abs and acos) are several orders of magnitude slower than when run outside of the Jest environment.

See this repo and follow the first list of instructions to reproduce the issue. Running Math.abs ten million times takes about 10ms outside of Jest, but increases to about 2000ms within a Jest environment.

OS: macOS High Sierra 10.13.2
Jest: 21.2.1
Node: 8.9.1
NPM: 5.5.1

[theblang]

It seems like it could be some issue of optimization at a lower level perhaps because a single call, or even ten calls, to Math.abs is about the same speed regardless of environment; but as soon as I make the call a hundred times I can tell a difference in run speed. It was suggested in the referenced ticket to try a VM context, which I did and saw no slowdown.

[SimenB]

This is really interesting... It went from 2000ms to 1000ms by just injecting Math from parent context, but it's still a lot slower (and we don't want to do that anyways).

I think we somehow hit some deoptimisation, but I'm not sure how to debug that.

Thanks for the focused reproduction!

[chucksellick]

My suspicion is that this is somehow to do with parallel virtualisation of tests, which uses workers.

[SimenB]

Using runInBand (which disabled parallelization) doesn't make a difference

[chucksellick]

Does jest affect babel configuration in any way or does it take whatever's in .babelrc?

[cpojer]

cc @fhinkel do you ave any insights as to why Math would behave so much differently inside of a vm context vs outside?

[fhinkel]

I don't know of an obvious reason why Math.abs should be slower in a vm context. But I think @mattblang said in comment that he doesn't observe the slowdown when comparing regular to vm runs?

[cpojer]

Yeah that makes it even more odd, we are not touching the Math object created using the VM module so I’m unclear what would cause it to be slower than normal.

[fhinkel]

@mattblang thanks so much for providing a focused repo and instructions so I didn't have to guess what to run and what to time 👍 .

I digged into this a little 🕵️‍♀️:

Unfortunately, it's the normal overhead that comes from using the vm module. The vm module uses interceptors for every global property and the interceptors are not cheap. If the code heavily uses global variables, the slowdown is larger. It's not specific to Math, you see the slowdown for any global object.

Jest uses the vm module. If the vm module doesn't find a property, e.g., Math, in the sandboxed context, it has to go on and search the global context. Here's the relevant line of code: if the property is not on the sandbox, go on and check the global context. I think that's why @SimenB sees the 50% speed up, because it's one instead of two look ups. Here's a bit of background information if you want to understand the vm implementation on a high level.

I'm assuming you opened this issue because that slowdown is a real world problem for Math heavy applications like pngjs? If needed, one could introduce a --math mode to Jest: If you know that the code you want to test heavily uses Math, Jest could wrap all content in a function that has Math as a local variable. With a dirty hack that brings the tests back to 20ms instead of 2000ms (1000ms if Math is injected in the sandboxed context).

I added one line to script_transformer.js:

try {

      content = '((Math)=> {\n' + content + '\n })(Math);';         // This line is new.

      if (willTransform) {
        const transformedSource = this.transformSource(
        filename,
        content,
        instrument,
        !!(options && options.mapCoverage));

[cpojer]

@fhinkel thank you so much for digging into this, this is really really useful.

[thymikee]

Looks like we can close this now :)

[theblang]

@thymikee Well, we understand the cause now but it is still a problem that renders stuff like jest-image-snapshot almost unusable. Should this issue be left open?

[SimenB]

I agree. Not sure about the best solution, though

[Jack89ita]

@theblang Any news about this issue? i've got the same problem you had here. Using jest-image-snapshot take about 20sec per snap.
Thanks.

[anescobar1991]

@jack89ita that should no longer be an issue. I made some changes in Jest-image-snapshot awhile back to fix the perf issues. Can you open an issue in Jest-image-snapshot with a repro? A test taking 20 seconds is way beyond normal.

[Jack89ita]

@anescobar1991 thank you for your answer. I was doing some test and i noticed that for taking a new snapshot it takes around 7s, but if i already have one the comparison takes about 20s. I am taking a fullpage screenshot with puppeteer at hight resolution (1920px width, the height depens on the page).
How much time it should take for a "normal" snapshot?
Thanks.

[anescobar1991]

@jack89ita A few hundred milliseconds at the very most.

[Jack89ita]

@anescobar1991 wow..that's a big difference. may this be caused by the images dimensions?

[anescobar1991]

Possibly but hard to tell without a repro.

[ajhsu]

Hi @anescobar1991 , as you mentioned:

I made some changes in Jest-image-snapshot awhile back to fix the perf issues

I would like to know where these changes are;
Because the image comparison took me nearly 2 minutes between two images (~3MB per image) right now. Since the jest-image-snapshot package is the best solution for visual regression testing with Jest so far, I really love to figure out any solutions to tweak this perf issue.

[anescobar1991]

@ajhsu this was solved in v2.0.0 that was released awhile back, so taking 2 minutes to compare is not normal. Either way can you open an issue in jest- image-snapshot? Let’s not spam this jest issue.

[ColCh]

for me - not really. I will dig into it at weekends

paeth predictor is that Math.abs heavy user

https://github.com/lukeapage/pngjs/blob/master/lib/paeth-predictor.js#L3

Yup comment https://github.com/facebook/jest/issues/5163#issuecomment-355509597 tells about it

@fhinkel If understand properly, there is no way to resolve this issue - because of lookup of global variable?

[patrickhulce]

I'm also experiencing this, ballooning what was a <1s test suite in mocha to a 2 minute (!!) test suite 😞

Would it be problematic to automatically do this for commonly used globals based on a config property as suggested?

[SimenB]

Using jest 24 and the option added in #7454, these are the numbers I'm seeing with the repro in the OP:

    console.time pixelmatch.js:9
      reading screenshot-a:: 3ms
    console.time pixelmatch.js:13
      reading screenshot-b:: 2ms
    console.time pixelmatch.js:24
      running image comparison:: 249ms
    console.time pixelmatch.js:28
      creating diff buffer:: 253ms
    console.time pixelmatch.js:32
      writing diff file:: 18ms

vs without changes:

    console.log console.js:258
      reading screenshot-a:: 0.401ms
    console.log console.js:258
      reading screenshot-b:: 0.330ms
    console.log console.js:258
      running image comparison:: 1070.510ms
    console.log console.js:258
      creating diff buffer:: 22004.161ms
    console.log console.js:258
      writing diff file:: 1.074ms

Diff:

diff --git i/package.json w/package.json
index df1978c..61333f9 100644
--- i/package.json
+++ w/package.json
@@ -6,7 +6,7 @@
   "author": "",
   "dependencies": {
     "jasmine": "^2.8.0",
-    "jest": "21.2.1",
+    "jest": "24.0.0",
     "pixelmatch": "4.0.2",
     "pngjs": "^3.3.1",
     "pngjs-nozlib": "1.0.0",
@@ -17,6 +17,9 @@
     "test": "jest"
   },
   "jest": {
+    "extraGlobals": [
+      "Math"
+    ],
     "testEnvironment": "node"
   }
 }