emotion icon indicating copy to clipboard operation
emotion copied to clipboard

Old performance issue not fixed ( development only )

Open itsUndefined opened this issue 3 years ago • 37 comments

Current behavior: Performance difference between development and production is very different when using jsx pragma. Issue probably has to do with #1467

In one of my material-ui projects I get the following numbers in development: image and the following in production: image Performance difference is almost 150 times slower. The screenshots are from only 3 material-ui elements that are rendering.

To reproduce:

  1. Use a chromium based browser to get a highly accurate timer on the console
  2. Go to https://codesandbox.io/s/emotion-issue-template-forked-my9lw
  3. Click on rerender and watch console for time it took to run jsx code in development.
  4. Uncomment line 13 to set NODE_ENV environment to production
  5. Click on rerender and watch console for time compared to step 3

Expected behavior: I expected the performance difference to be at the worst case scenario 2x times slower

Environment information:

  • react version: 17.0.1
  • @emotion/react version: 11.1.5

itsUndefined avatar Mar 21 '21 23:03 itsUndefined

I'm slammed with work right now so I won't be able to look into it soon. It would be appreciated if you could dig into this deeper to assess what's the problem.

Andarist avatar Mar 22 '21 20:03 Andarist

@Andarist after checking the code out I saw that the issue with with way the stack is used to find the name of the function that called for the css prop. That code is terribly inefficient but I don't know how you could possibly fix it. It also makes sense why on bigger and deeper projects it literally hangs the browser.

Using a cache on the problematic code fixes the rerender performance. Initial render performance still suffers. Specifically I tried the following code:

var cache = []; // top of file

if (process.env.NODE_ENV !== 'production') {
    if(cache[type]) {
      newProps[labelPropName] = cache[type];
    } else {
      var error = new Error();
      if (error.stack) {
        // chrome
        var match = error.stack.match(/at (?:Object\.|Module\.|)(?:jsx|createEmotionProps).*\n\s+at (?:Object\.|)([A-Z][A-Za-z0-9$]+) /);
  
        if (!match) {
          // safari and firefox
          match = error.stack.match(/.*\n([A-Z][A-Za-z0-9$]+)@/);
        }
        if (match) {
          cache[type] = sanitizeIdentifier(match[1])
          newProps[labelPropName] = sanitizeIdentifier(match[1]);
        }
    }
}

Question: If you implement such a cache to at least fix rerenders and make apps responsive, how would you prevent the memory from climbing steadily? Is that a possible issue or since it's for development only it's ok? I don't know when a component get's a new "identity" aka type.

For those who want initial render performance a possible solution is to have a flag that you can set on the main entrypoint of a react application to disable the labelling using the stack at the cost of debugging experience on devtools. I would for sure use that option on my application.

I also tried to come up with an idea using the JSX function of emotion to get rid of the problematic code but it's probably impossible with the way react rendering and memoization works.

Last but not least I would like to say that using the stack that is generated with new Error() has no place in a high performance css library. Caching shouldn't make this issue completely fixed. I would like to also be able to disable the problematic code.

Thank you for your time.

itsUndefined avatar Mar 23 '21 00:03 itsUndefined

Caching won't work here because this is not extracting a match for the type but for its "caller".

Last but not least I would like to say that using the stack that is generated with new Error() has no place in a high performance css library.

Well, we really didn't have that many issues created in response to that so I believe that you are slightly exaggerating its importance.

Using the provided codesandbox I don't see any difference between those runs. Could you maybe record the profiler session and upload the dump so I could take a look at it? What browser (and what version of it) are you using?

Andarist avatar Mar 23 '21 16:03 Andarist

I am using chrome version 89.0.4389.90 but I am pretty sure firefox is just as slow from what I can tell from the website I am building. Performance profiles with dev vs production below:

profiles.zip

All I am doing is holding down a key on my keyboard on an <input> on my page and in production it properly renders around 30 frames per second with devtools recording. In development the browser is completely blocked from rendering frames and it drops to 0 fps while holding the key.

I am not rendering any lists on my website. I have properly memoized my components and all the lag comes from around 5 to 10 css props processing.

Sorry if I exaggerated before. It's true that in the code sandbox the difference is not that big. I don't understand why. Maybe it has to do with the size of the call stack generated? The problem is of course not a big deal since it doesn't exist in production. It's only an inconvenience in development because it makes the developer think they have made mistakes with memoization when in fact it's createEmotionProps wasting the cpu cycles.

itsUndefined avatar Mar 23 '21 17:03 itsUndefined

Hi, I'm also using emotion and everything is really really slow in dev for me too.
Profiling is showing emotion as the main culprit. Some widgets takes up to 500ms to render, and I'm currently considering my options while lurking this issue.

rvion avatar Mar 24 '21 17:03 rvion

Well, we really didn't have that many issues created in response to that so I believe that you are slightly exaggerating its importance.

considering the previous issue here https://github.com/emotion-js/emotion/issues/1467#issue-479286534 only had 2 thumbs up, I guess the situation may be similar 🤔

rvion avatar Mar 24 '21 17:03 rvion

It was hard for me to find the issue because I am not experienced with profiling. I guess that's the reason why the issue is not open more often ( and since it's only on dev ). I would really love if someone opened a PR with a kill switch as a flag. Something like emotion.labelFromStack = false;

itsUndefined avatar Mar 24 '21 17:03 itsUndefined

For the time being I suggest using patch-package to disable that part of the code.

I'll be investigating this - I'd like to understand why this is slow for you first. After I get a better understanding the issue will get either fixed or some kind of an opt-out flag will be added (I don't completely put off the table dropping this code entirely either).

Andarist avatar Mar 24 '21 17:03 Andarist

I'm having this issue too. Let me know if there's any information I can provide to help research the issue.

tlindstrom avatar Mar 28 '21 20:03 tlindstrom

I've checked out the provided profiles - they lack source code so I can't really click on specific call sites to get a better understanding of the issue (which might be a good thing for you since this might have been recorded on a private project). However, I think I've still learned some things.

Could any of you (more people the better) dump an example stack trace that is being created there? Also - could you leave the .stack access but at the same time remove our regexp parsing from there and check if there is any difference?

Andarist avatar Mar 29 '21 08:03 Andarist

Hi. I don't have a problem to have the source code on the performance profiles. I just dοn't know how to do it without uploading and giving the whole repository which will probably waste your valuable time to check out since it requires backend API to get to the problematic screen. I did not find a checkmark on the performance tab to include source code on the saved profiles. I am gonna publish the timers with the following JSX deep inside the project. It's the same 3 material-ui that gave the timer printouts on the original issue post I made.

console.time("jsx");
const a = (<Card css={styles.fullHeight}>
    <CardContent css={styles.fullHeight}>
        <Box css={styles.previewerContainer}>
        </Box>
    </CardContent>
</Card>);
console.timeEnd("jsx");
  • Production time: 0.022ms
  • Development time with problematic code completely removed: 0.025ms
  • Development time with new Error() but no access to error.stack and no regex: 0.12ms
  • Development time with access to error.stack but no regex: 0.7ms
  • Development time with problematic code left as is: 2 - 5 ms

Some extra timers inside the suspect code: image

I find it weird that by having timers inside the suspect code, the stack generation/access seems to be the slowest operation but by timing the JSX creation time by removing lines inside the suspect code it feels like the regex is the slowest operation. Still, even at 0.7ms per component (no regex but stack access) my website's framerate drops below 5 but it feels better than with the regex. With the regex the framerate goes to 0 and the browser doesn't repaint.

Stack trace created:

Error
    at createEmotionProps (emotion-element-4fbd89c5.browser.esm.js:113)
    at jsx (emotion-react-jsx-runtime.browser.esm.js:18)
    at Previewer.tsx:54
    at renderWithHooks (react-dom.development.js:14985)
    at updateFunctionComponent (react-dom.development.js:17356)
    at updateSimpleMemoComponent (react-dom.development.js:17215)
    at beginWork (react-dom.development.js:19140)
    at beginWork$1 (react-dom.development.js:23940)
    at performUnitOfWork (react-dom.development.js:22776)
    at workLoopSync (react-dom.development.js:22707)
    at renderRootSync (react-dom.development.js:22670)
    at performSyncWorkOnRoot (react-dom.development.js:22293)
    at react-dom.development.js:11327
    at unstable_runWithPriority (scheduler.development.js:468)
    at runWithPriority$1 (react-dom.development.js:11276)
    at flushSyncCallbackQueueImpl (react-dom.development.js:11322)
    at flushSyncCallbackQueue (react-dom.development.js:11309)
    at scheduleUpdateOnFiber (react-dom.development.js:21893)
    at dispatchAction (react-dom.development.js:16139)
    at Object.onChange (ΕxercisePage.tsx:80)
    at Object.onChange (Editor.tsx:51)
    at editor.tsx:161
    at Emitter.fire (event.js:469)
    at codeEditorWidget.js:1036
    at textModel.js:188
    at Emitter.fire (event.js:469)
    at DidChangeContentEmitter.endDeferredEmit (textModel.js:2630)
    at TextModel.pushEditOperations (textModel.js:903)
    at Function._innerExecuteCommands (cursor.js:613)
    at Function.executeCommands (cursor.js:580)
    at Cursor._executeEditOperation (cursor.js:347)
    at cursor.js:517
    at Cursor._executeEdit (cursor.js:478)
    at Cursor.type (cursor.js:507)
    at viewModelImpl.js:748
    at ViewModel._withViewEventsCollector (viewModelImpl.js:812)
    at ViewModel._executeCursorEdit (viewModelImpl.js:734)
    at ViewModel.type (viewModelImpl.js:748)
    at StandaloneEditor._type (codeEditorWidget.js:721)
    at StandaloneEditor.trigger (codeEditorWidget.js:665)
    at EditorHandlerCommand.runCommand (coreCommands.js:1529)
    at handler (editorExtensions.js:60)
    at idOrCommand.handler (commands.js:37)
    at InstantiationService.invokeFunction (instantiationService.js:46)
    at StandaloneCommandService.executeCommand (simpleServices.js:180)
    at Object.type (codeEditorWidget.js:1136)
    at ViewController.type (viewController.js:19)
    at textAreaHandler.js:190
    at Emitter.fire (event.js:469)
    at HTMLTextAreaElement.<anonymous> (textAreaInput.js:234)

itsUndefined avatar Mar 29 '21 12:03 itsUndefined

I don't have a problem to have the source code on the performance profiles.

it's because those scripts that the profile references are accessible on your machine (they are referenced by localhost URLs).

I just dοn't know how to do it without uploading and giving the whole repository which will probably waste your valuable time to check out since it requires backend API to get to the problematic screen.

Right, I don't mind - I think the already received profile helped me as much as it could.

Still, even at 0.7ms per component (no regex but stack access) my website's framerate drops below 5 but it feels better than with the regex.

Hmm, how many Emotion components render in a single frame then (let's focus on the update case for now)? The 0.7ms doesn't sound that bad on its own - but I understand that this can add up.


The problem definitely is amplified by this RegExp not catching your case stack properly (so it goes over the full string) and I think that this can be optimized by a lot. From what I understand this might still not be enough for you though.

Andarist avatar Mar 29 '21 14:03 Andarist

I would say it's about 10 or 15 components that render after the textArea onChange is triggered. My page doesn't do a whole lot though. I can imagine some probably rare cases where bigger widgets/pages slowly add up. Also I am sorry but I think I made a mistake on my calculations above. Chromium is reporting 0.7ms (without the regex) per 3 (not 1) components as I was timing the JSX shown. Not sure if I can help with any more information since my specific website is not that big. I started using patch-package, like you instructed, successfully and I can once again feel the performance close to production. I would bet the performance issue gets amplified because react calls render twice in development.

itsUndefined avatar Mar 29 '21 14:03 itsUndefined

Here's a demo Next.js demo project demonstrating the problem as I'm experiencing it. A dev tools profile dump is also checked into the repo.

https://github.com/tlindstrom/emotion-next-problem

Does this help? Anything else I can provide?

tlindstrom avatar Apr 24 '21 12:04 tlindstrom

Also occurs on rerenders (seems like downloading it is necessary to view the real profiling results). https://codesandbox.io/s/emotion-css-prop-perf-124fa-ytuoo?file=/src/App.tsx

Same results as described in that mentioned issue https://github.com/emotion-js/emotion/issues/1467

image image

orenklein avatar May 04 '21 17:05 orenklein

Here's another repro case using Next.js, but for an incremental game built in React. https://github.com/threehams/incremental-game-jam-2/tree/emotion-speed

To see it in action:

  1. Start up the server with yarn dev or npm run dev
  2. Click "Travel to the Killing Fields"
  3. Click "Kill something"
  4. Drag the item you get around the grid.

Framerate will drop significantly. This only happens in dev mode, and all the cost is in emotion. This is not written efficiently at all (hey, game jam code) but it can run at 60fps in production mode, and will also run 60fps in dev mode using Tailwind.

threehams avatar May 23 '21 01:05 threehams

@threehams I've opened https://github.com/emotion-js/emotion/issues/2303, which is different because it's more focused on the LightHouse "performance" score (in production), but your latest example interests me. I wonder if you've noticed any difference in "Performance" sore when using Tailwind versus Emotion.

Could you share an audit for each? (I assume since you've mentioned Tailwind, you've built like two versions of the same app, one using Emotion and another using Tailwind)

Vadorequest avatar May 23 '21 13:05 Vadorequest

Both versions get 95 scores, it's not the right project to test your issue. This is a project which is small and very quick to render/hydrate, but updates at 60fps.

threehams avatar May 23 '21 17:05 threehams

hi, this is very interesting and I think I'm fassing similar issues with emotion 11 and material-ui 5. Are there any news on workarounds or similar? @Andarist where can I find the patch-package related instructions mentioned above?

mdugue avatar Jun 28 '21 10:06 mdugue

I'm also seeing this issue. It's 66% of a 10s render. Looks like a debugging feature. Is it possible to make it optional? This is interfering with other debugging on the page. Screen Shot 2021-11-03 at 1 51 18 PM

bgirard avatar Nov 03 '21 20:11 bgirard

@bgirard there is an ongoing effort to rewrite this label extraction here: https://github.com/emotion-js/emotion/pull/2534 . Making it more performant would be something that I think should be attempted first, before introducing flags for disabling this. Coyld you share you example stack trace there?

Andarist avatar Nov 03 '21 23:11 Andarist

I can't share the trace unfortunately since it's a closed source project but I'm happy to provide additional information that I can share. Just capturing a stack is fairly expensive and resource intensive and can have side effects in the JS VM that aren't fully captured in performance traces. It would be ideal to let users match the production flow if they aren't debugging emotion.

Happy to re-test once a new package is published containing the PR and report on the improvement in my use case. To be fair my use case really needs to be virtualized, but I still like to stamp out large skews between prod and dev.

bgirard avatar Nov 04 '21 00:11 bgirard

You could replace sensitive information in the stack trace with something meaningless.

Andarist avatar Nov 04 '21 06:11 Andarist

Hi, when will the version containing this PR be released? Thanks!

gavinxgu avatar Nov 26 '21 01:11 gavinxgu

@gavinxgu @emotion/[email protected] with this change should be released in a moment

Andarist avatar Nov 26 '21 09:11 Andarist

Performance issue on my application ( and on provided codesandbox ) did not change on Chrome V96. I would love to have a toggle to disable this feature for the few of us with big/deep applications.

itsUndefined avatar Nov 26 '21 10:11 itsUndefined

@itsUndefined thanks for the feedback, we’ll definitely consider a global flag for this then. Could you share an example stack trace in the meantime and maybe a performance profile?

Andarist avatar Nov 26 '21 11:11 Andarist

@Andarist +1 for the flag to turn this off during dev. I just ran into this too. 11.7 hasn't helped unfortunately.

akutruff avatar Jan 13 '22 21:01 akutruff

@akutruff could you share a performance profile?

Andarist avatar Jan 14 '22 09:01 Andarist

@Andarist Thanks for responding. Chrome profile below.

The app has a ton of DOM elements that are added on a click. Almost half the render time is spent in emotion during the dev build. All the emotion styles are declared once at module scope and used through the css property.

https://gist.github.com/akutruff/8c5fe32aff25123298760eb77d56dcd1

akutruff avatar Jan 14 '22 13:01 akutruff