Potential performance regressions in 3.0.0

[xzyfer]

Originally reported in sass/libsass#1205.

Anecdotally I believe 3.0.0 has introduced a noticeable performance regression. Currently I suspect the recent binding updates foe custom functions and importers but I have no evidence as yet.

[am11]

There is an old test called "Huge" (something) in spec repo, which vividly underscores this dramatic difference in performance between node-sass 1.x, 2.x and 3.x. If we target that test only, we can probably figure out the source of issue using some profiler tool (or just by tracing the call stack like how @mgreter do for source-map debugging?).

[blackfalcon]

Having tried to upgrade a project I work on to node-sass 3.0.0 to get the awesome of libsass 3.2.4 I ran into significant performance issues.

I have been using all the latest newness on much smaller project, less then 50 Sass files. But when I tried to upgrade a larger project with hundreds of files, I ran into the issues of;

1. there is no log output of the files created from the processing
2. there is a HUGE reduction in speed of processing

The following is a listing of versions that diff between the master branch and the upgrade branch.

master

/project/package.json "gulp-sass": "^1.3.3",

gulp-sass installed "version": "1.3.3",

/project/node_modules/gulp-sass/package.json "node-sass": "^2.0.1",

node-sass installed "version": "2.1.1", installed

/project/node_modules/gulp-sass/node_modules/node-sass "libsass": "3.1.0",

[07:44:21] Finished 'build:css' after 31 s

libsass upgrade branch

/project/package.json"gulp-sass": "^2.0.1",

gulp-sass installed "version": "2.0.1",

/project/node_modules/gulp-sass/package.json "node-sass": "^3.0.0",

node-sass installed "version": "3.1.2",

/project/node_modules/gulp-sass/node_modules/node-sass "libsass": "3.2.4",

[07:35:20] Finished 'build:css' after 3.15 min

In both cases, the Sass was expected to process 93 individual SCSS files due to our extended theme development process, not counting all the imported dependencies.

[saper]

I am researching webpack-contrib/sass-loader#100 now. This can be actually #857 but it needs to be verified.

[xzyfer]

@saper the regression isn't limited to sass-loader. The node-sass CLI is
also affected. My gut says something with the recent custom importer and
custom function binding is to blame.
On 4 Jun 2015 12:12, "Marcin Cieślak" [email protected] wrote:

I am researching webpack-contrib/sass-loader#100
webpack-contrib/sass-loader#100 now. This can be
actually #857 #857 but it needs
to be verified.

—
Reply to this email directly or view it on GitHub
#970 (comment).

[saper]

@xzyfer yes, of course it has nothing to do with the sass-loader. Maybe some multi-file code triggers #857 ? #857 is relatively easy to detect if setting UV_THREADPOOL_SIZE environment variable before starting node to some large number (>number of opened files) fixes the issue.

[xzyfer]

Honestly I'm not convinced this is related to the thread pool. The larger
issue is that node-sass is slower at a base line. I ran some naive tests a
while ago. Files that compile on 100ms in libsass takes 300ms via node-sass.
On 4 Jun 2015 13:39, "Marcin Cieślak" [email protected] wrote:

@xzyfer https://github.com/xzyfer yes, of course it has nothing to do
with the sass-loader. Maybe some multi-file code triggers #857
#857 ? #857
#857 is relatively easy to
detect if setting UV_THREADPOOL_SIZE to some large number (>number of
opened files) fixes the issue.

—
Reply to this email directly or view it on GitHub
#970 (comment).

[slyoldfox]

Is there any progree on this happening? Otherwise I'll have to instruct our team to possibly downgrade again to the previous version.
Our static compiles have gone down from 10 secs to 2 minutes.

[boschni]

We are also seeing performance differences between [email protected] and [email protected]. Our compile times went up from 2.2s to 3.9s (an increase of 77%). Tested with [email protected] and [email protected].

[MattDiMu]

I got the same issue after upgrading to node-sass 3.2 (using gulp-sass). The compilation time increased from ~150-250ms up to 800-1.200ms. Will probably downgrade, as long as this issue isn't solved.

edit: I've tested my project with several versions and the big performance loss seems to occur between node-sass 2.1 and 3.0. All 3.x-Versions seem to suffer from it.

[thomasplevy]

I've been noticing long compile times after upgrading gulp-sass to the most recent version (which bumped up to node-sass 3.0.0 -- I've managed to track the issue down to the upgrade of the node-sass module

After regressing to node-sass 2.1.1 the issue has gone away.

on 3.0.0 compilation takes ~5.5 seconds. Now it's taking ~2.5

[telemakhos]

Same issue here, the current performance makes the builds way too slow. Gonna downgrade until the issue is resolved.

[quantix-studio]

Stuck to @2.1.1 too :(
on a large project :
@2.1.1 : compilation takes less than 3s
@3.0.0 : compilation takes about 30s !! (ruby-sass makes it in less than 10s)

[telemakhos]

I've gone from subsecond compile times to 8s. Not acceptable.

Downgrading to 2.1.1 looks like the only solution for the time being...

[xzyfer]

@telemakhos @quantix-studio I find these hard to believe, I'd be like to see what you're doing.

The regression at worst should make compilations twice as slow between 2.1.1 and 3.2.5. Which given the speed of node-sass isn't that bad.

I'd like more info about your respective projects i.e. asset pipelines grunt/gulp, libraries bourbon/susy/boostrap.. etc The more info the better.

Finally for those who are down grading I can't urge you enough not to do this. You're willing installing a buggy version of LibSass, and inheriting know installation issues with node-sass. If you want this fixed quickly we need your help in creating simple benchmarks that show the regression so we know how best to proceed.

[saper]

With every version we have new bugs :) First we need to isolate the problem - is this related to custom functions/importers or is it just libsass change.

A kind of minimal, dummy project that compiles much slower would be perfect!

[levinelson]

We've got a pretty massive Sass file with 80ish @imports. We use grunt to compile, and updating grunt-sass to version 1.0.0 (which in turn updated node-sass from 2.1.1 to 3.2.0) introduced some massive performance hits like are being discussed here. We were compiling in a couple seconds or less but now it's an unusable 20-30s. Compile time does go down when I remove the lengthiest @imported files (e.g., I can remove one 3000 line @import and gain about 2.5s back, remove another 2500 line @import and gain about 2s back, etc). Removing smaller imported files has less of an impact on compile time.

EDIT: We've also got newest versions of Bourbon & Bourbon Neat (via node-neat and node-bourbon) in the pipeline and we import Foundation manually, if that helps.

[xzyfer]

@levinelson can you ascertain whether it's the size of the file or the number of imports within the file you're removing.

i.e. if you remove a large with no imports do you see the speed up as a file with a large number of imports?

[levinelson]

@xzyfer As near as I can tell, its just the sheer length of the imported Sass files that slow it down.

The baseline time with all imports as normal was 25.3s (same process that was sub 3s before update). Our file structure is pretty flat:

app.scss
|-- _settings.scss
|-- _app-main.scss
     |-- 80ish imported sass files (no further imports)

Out of the 80ish imports, I can remove the just the largest 7 imports (236 KB of the total 439 KB un-minified Sass files) and get the compile time down to 4.7s.

I put one of the large imports back in the pipeline (75KB file, 3338 lines), and the compile time went back to 9.7s. I tried taking the code that's in that large import and just putting it directly in our main app-main.scss stylesheet and compile time only went down slightly to 9.6s.

That large file (like most of the other files) is full of Bourbon mixins and other custom mixins. I tried removing those I could without completely breaking the compile process and reduced the file from 3338 lines to 2725 lines and got compile down to 7.4s.

The last thing I tried was removing one layer of imports (importing everything in app.scss instead of one layer deeper in app-main.scss). This resulted in no material change (25s just like the original).

Let me know if I can get you any more information. Appreciate the help!

[telemakhos]

I'm going to echo what @levinelson has said. Our scss codebases are medium-sized with about 70-90 scss files (500 to 700KB total on disk) using a SMACSS architecture, only for custom sass. We also import bootstrap sass, bourbon, and other vendor libs.

We use gulp with swiip's gulp-angular as the base boilerplate. This boilerplate has also experienced an increase in twice the amount of compile time only with the generated defaults, when you start adding stylesheets things go south.

I first noticed the performance decrease when I started using this boilerplate for the Ionic Framework project. I was surprised that their small scss codebase could have such performance issues. Then I updated our other projects to 3.x and started wondering what was happening.

Ionic Framework guys are still using 2.1.1 in their official generators...

[xzyfer]

I've done some quick investigation on this.

Setup

I created a simple boilerplate benchmark which consisted of 11,000 lines of

foo { bar: baz; }

Results

node-sass 2.1.1	node-sass 3.0.0	sassc 3.1.0	sassc 3.2.0	sassc 3.2.5	sassc master
0.5s	1.3s	0.5s	1.3.s	1.3s	0.35s

Summary

This really surprised me for a couple reasons.

We were aware that LibSass 3.2.0 could be slightly slower due to some of the changes in that massive release. We had no idea of the extent of the regression.

Secondly, I had long suspected the Node Sass binding code was to blame for the speed regression, since we also heavily updated it in [email protected]. In fact this small test shows that there is very little over head in this layer which is very exciting!

Conclusion

This appears to be LibSass' fault, which puts it's out of our control.

We've been working on performance in LibSass and our next release will be significantly fast as the above benchmark shows.

[mgreter]

Unfortunately I can reproduce the performance regression on windows with node-sass. I do not see it on linux where I get the expected speed, but on windows it runs about 10 times slower than expected. To reproduce it I simply created a pretty big file with some randomly nested selectors and properties:
https://github.com/mgreter/postcss-playground

# gulp sass
Using gulpfile postcss-playground\gulpfile.js
Starting 'sass'...
Finished 'sass' after 4.35 s

# gulp postcss
Using gulpfile postcss-playground\gulpfile.js
Starting 'postcss'...
Finished 'postcss' after 497 ms

# psass --benchmark test\nested.scss > psass\nested.css
 0 wallclock secs (0.4520 usr + 0.0310 sys = 0.4830 CPU)

[am11]

@mgreter,

Setup:

On win10, I saved https://github.com/mgreter/postcss-playground/blob/master/test/nested.scss?raw=true as c:\temp\big.scss and then in powershell:

cd $env:UserProfile/Source/Repos
git clone https://github.com/sass/libsass ; cd libsass
git clone https://github.com/sass/sassc ; sassc/win/sassc.sln
# opened solution in vs2015

Auto diagnostics tool:

Then in vs2015 > Solution Explorer > Right clicked project > Properties > Debugging > and set Command Arguments to:

\temp\big.scss \temp\big.css

then changed configuration to Release and Alt+F2 (Debug > Start Diagnostics tools..) It eventually exported these reports: http://1drv.ms/1hJPdaG.

Manual benchmark:

After that, for the manual benchmarking, I used this function: http://stackoverflow.com/a/1861337, pasted it at the top of libsass/sassc/sass.c and applied the following patch:

diff --git a/sassc.c b/sassc.c
index a8dd220..23e5793 100644
--- a/sassc.c
+++ b/sassc.c
@@ -281,7 +331,12 @@ int main(int argc, char** argv) {
             strcat(source_map_file, extension);
             sass_option_set_source_map_file(options, source_map_file);
         }
+        uint64 t0 = GetTimeMs64();
+        printf("Started: %d\n", t0);
         result = compile_file(options, argv[optind], outfile);
+        uint64 t1 = GetTimeMs64();
+        printf("Ended: %d\n", t1);
+        printf("Difference: %d\n", t1-t0);
     } else {
         if (optind < argc) {
             outfile = argv[optind];
@@ -290,6 +345,6 @@ int main(int argc, char** argv) {
     }

     free(include_paths);
-
+    system("pause");
     return result;
 }

Ran 5 times and on average: with configuration Release:Win32, it gave 450-550ms and with Release:Win64, it was around 500-620ms.

[mgreter]

It seems to be fixed with latest master! Did pretty much the same test and found out that producing the output is actually the slow partI don't know why it was triggering that regressions, but it mainly seemed to came from appending to strings. But I didn't look much further as using the lastest libsass master seemed to provide the expected speed. When I changed the output generating from using a string buffer to using ostringstream, I got decent results on MSVC but got a pretty big performance regression with gcc (as expected). Appending to a string should be faster than using ostringstream anyway!?

Long story short, lets wait for next release and try again!

[mgreter]

Good news is that we have better performance than postcss, which is what I initially wanted to assess!
edit: All in all it really looks like a compiler bug, as I don't see why using ostringstream instead of string should give such a big performance impact! Also instrumenting via MSVC did not report the correct thing, since I clearly could time the compile time (~6s), but the results only showed an execution time of 0.5s ...

[am11]

Does using string::append or operator+= fix the regression for both GCC and MSVCR?

Regarding the compiler bug, see https://gcc.gnu.org/bugzilla/show_bug.cgi?id=53221. Code involving certain string-related operations (including push_back()) compiled with GCC 4.6-4.9 will be much faster than if it is compiled with GCC5 (depending on which combination of operations you are using), because in 4x, it was avoiding the COW which the standard requires and hence it was making a huge performance difference. In a perfect world, when "std::" will be more reliable and consistent cross-platform: "copy should take equal amount of time as move without no-except; while move with no-except should be much faster than copy and move without no-except". It turns out you can get very substantial performance improvements by not doing the right thing. 8-)

[mgreter]

We are already using operator+=, but I also tried string::append and also tried to reserve the whole memory beforehand, but nothing gave the expected speed. Only changing it completely to use a stringstream solved the problem, and I fail to see why using strm << str vs buffer += str should have like 500ms vs 5s execution time (stringstream should in theory even be a bit slower)!? And I was not able to reproduce this with a very simple example.

The only reason it is slow seems to come from append_string in emitter.cpp:

wbuf.buffer += text

[am11]

I found this article interesting: 4350% Performance Improvement with the StringBuilder for C++!. The class is built using the good parts of C++11 string functions stitched together. The code is redistributable commercially as per the code project license. I have added the extracted code here.

Do you think it is worth to give it a try, replacing OutputBuffer::buffer type from std::string to StringBuilder<wchar_t> and then use its .Append() and .AppendLine() functions?

[mgreter]

As I said, it seems to be fixed in master, so I don't see a reason to change anything at that point ...

[am11]

Yup, I can confirm that it is fixed when we compile sassc in Release configuration. With debug config, since the optimization flags are not set, it takes about ~10+ seconds to compile the big.scss file.
Since pangyp PR is pending the review: rvagg/archived-pangyp#9, I can't build node-sass locally with VS2015 at the moment. I requested CI build and tested with build artifact and it takes about half a seconds (347ms) to compile:

C:\Users\Adeel\source\Repos\node-sass [request-ci-artifacts]> node
> require('./').renderSync({file:'/temp/big.scss'})
{ stats:
   { entry: 'c:\\temp\\big.scss',
     start: 1440882797033,
     includedFiles: [ 'c:/temp/big.scss' ],
     end: 1440882797380,
     duration: 347 },
  css: <Buffer 2e 77 61 72 6e 69 6e 67 20 54 45 58 54 41 52 45 41 2e 6f 70 65 6e 20 23 63 61 72 6f 75 73 65 6c 2e 77 61
72 6e 69 6e 67 20 7b 0a 20 20 66 6f 6e 74 2d ... > }

Thanks to @mgreter and @xzyfer for the efforts. 👍
This issue is fixed. Waiting for libsass vNext. 😃

[opeologist]

this issue is resolved with the current version of node-sass? or are you saying the issue is fixed in the latest version of libsass? if it's fixed in libsass, has that version been updated in node-sass? using latest node-sass, i'm still seeing performance regression with my projects.

[saper]

this issue is resolved with the current version of node-sass? or are you saying the issue is fixed in the latest version of libsass? if it's fixed in libsass, has that version been updated in node-sass?

You can try node-sass@beta, which includes a very recent libsass. A lot of changed since then.

[opeologist]

saw that, thank you!!! works beautifully

[xzyfer]

Fixed in #1214. Will be in v3.4.0.