Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
theblang opened this issue Dec 23, 2017 · 27 comments · Fixed by #7454
Closed

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

theblang opened this issue Dec 23, 2017 · 27 comments · Fixed by #7454

Comments

@theblang
Copy link

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
Copy link
Author

theblang commented Dec 23, 2017

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
Copy link
Member

SimenB commented Dec 23, 2017

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
Copy link

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

@SimenB
Copy link
Member

SimenB commented Dec 27, 2017

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

@chucksellick
Copy link

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

@cpojer
Copy link
Member

cpojer commented Jan 3, 2018

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

@fhinkel
Copy link

fhinkel commented Jan 3, 2018

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
Copy link
Member

cpojer commented Jan 3, 2018

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
Copy link

fhinkel commented Jan 5, 2018

@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
Copy link
Member

cpojer commented Jan 5, 2018

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

@thymikee
Copy link
Collaborator

Looks like we can close this now :)

@theblang
Copy link
Author

theblang commented Feb 25, 2018

@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
Copy link
Member

SimenB commented Feb 26, 2018

I agree. Not sure about the best solution, though

@Jack89ita
Copy link

@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
Copy link

@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
Copy link

@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
Copy link

@Jack89ita A few hundred milliseconds at the very most.

@Jack89ita
Copy link

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

@anescobar1991
Copy link

Possibly but hard to tell without a repro.

@ajhsu
Copy link

ajhsu commented May 16, 2018

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
Copy link

@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
Copy link
Contributor

ColCh commented May 18, 2018

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 #5163 (comment) tells about it

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

@patrickhulce
Copy link

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
Copy link
Member

SimenB commented Jan 27, 2019

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

@scpedicini
Copy link

Any particular reason this was closed? PNGjs lib maintainers believe this is still an issue.

pngjs/pngjs#96

At least on jest 29.5 with some of pngjs I was seeing performance hits around 50x. I spent half an hour trying to setup worker threads before realizing that jest was causing massive slowdown in at least one particular function:

PNG.sync.write

@SimenB
Copy link
Member

SimenB commented May 22, 2023

Any particular reason this was closed?

Yeah, the comment before yours. And the issue you linked to has been closed for 5 years


This is a limitation of how Node's vm API works. We've added a workaround you can use. If that doesn't work, feel free to open up a new issue with a reproduction

@SimenB
Copy link
Member

SimenB commented May 22, 2023

(Locking as this issue has been closed for more than 4 years - not sure why the bot hasn't done so)

@jestjs jestjs locked as resolved and limited conversation to collaborators May 22, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging a pull request may close this issue.