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

@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));

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"
   }
 }

@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?

@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.

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

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?

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?

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!