Processing scss very slow since 1.7.1

[muffl0n]

We are using version 1.7.0 of the WRO-Plugin since last year. Today I updated to version 1.7.6 in order to speed things up with incremental builds and parallel processing.

After realizing that my builds need significant more time I discovered that the time needed to process my scss-files jumps from 40 seconds (1.7.0) to 2m20s (1.7.1). After enabling parallelProcessing I got the time down to 1m20s. But this is far worse than the time the build needs with 1.7.0.

I don't know if this behaviour only relates to scss-processing.

I'm not sure what information would be helpful to diagnose this problem. But I would be happy to contribute whatever is needed.

[muffl0n]

In AbstractWro4jMojo I found that persistResourceFingerprints() get's called in getTargetGroupsAsList() regardless of the value for "incrementalBuild". There is no need to persist Fingerprints when not running an incrementalBuild, is there?

[alexo]

That is correct. Thanks for opening the issue.

[muffl0n]

I'm also a bit confused about duplicate log messages "Persist fingerprint for resource". I created a small example project: base.scss:

@import 'header.scss';

header.scss:

#header {
  width: 100%;
}

When running wro4j with -X I get this:

[DEBUG] Persist fingerprint for resource '/scss/base.scss' : 67c3942433ae295ea819b541303b648f32f2ae0c
[DEBUG] Check @import directive from ro.isdc.wro.model.resource.Resource@1133ec6e[CSS,/scss/base.scss,true]
[DEBUG] Found @import /scss/header.scss
[DEBUG] Persist fingerprint for resource '/scss/header.scss' : 77141eb86ceb6a88beabe40d81fd1a65b5ce9e64
[DEBUG] Check @import directive from ro.isdc.wro.model.resource.Resource@4e4efc1b[CSS,/scss/header.scss,true]
[DEBUG] Persist fingerprint for resource '/scss/header.scss' : 77141eb86ceb6a88beabe40d81fd1a65b5ce9e64
[DEBUG] Check @import directive from ro.isdc.wro.model.resource.Resource@7a56812e[CSS,/scss/header.scss,true]
[DEBUG] Persist fingerprint for resource '/scss/header.scss' : 77141eb86ceb6a88beabe40d81fd1a65b5ce9e64
[DEBUG] Check @import directive from ro.isdc.wro.model.resource.Resource@7e70bd39[CSS,/scss/header.scss,true]

The resource header.scss seems to get persisted three times. It also is checked three times for @import. The strange thing is: There seem to be three different Resource objects for the same file:

ro.isdc.wro.model.resource.Resource@4e4efc1b[CSS,/scss/header.scss,true]
ro.isdc.wro.model.resource.Resource@7a56812e[CSS,/scss/header.scss,true]
ro.isdc.wro.model.resource.Resource@7e70bd39[CSS,/scss/header.scss,true]

[alexo]

@muffl0n there is no optimization of this aspect right now. If the resources is imported 3 times, it will be fingerprinted 3 times. Anyway, the fingerprinting operation is supposed to be very fast. There are 3 different instance of the Resource object because it is instantiated 3 times. There is no pool of Resources to reuse previously created instances.

[muffl0n]

I see, but my test project only consists of the two files base.scss and header.scss. And there is only one import statement in base.scss (see my comment above). I wonder where the three instances come from.

Anyway, in my repository https://github.com/muffl0n/wro4j-fingerprint there are two Profiler Snapshot files I saved with VisualVM:

• https://github.com/muffl0n/wro4j-fingerprint/blob/master/wro-1.7.0.nps
• https://github.com/muffl0n/wro4j-fingerprint/blob/master/wro-1.7.1.nps

Maybe they help identifying the hotspots.

[alexo]

The fingerprint doesn't seem to be the problem. The hotspot is jruby invocation. The problem could be: 1) multiple processing of the same resource (can be identified by turning debug log level). 2) use of different jruby version which could potentially have performance degradation.

The wro4j-1.7.0 uses jruby-1.6.8, while wro4j-1.7.1 uses jruby-1.7.4. Could you use the jruby-1.6.8 dependency explicitly with latest version of wro4j and profile the app again?

[muffl0n]

With jruby-1.6.8 the build finishes in 58s. Still slower than wro4j-1.7.0 but a huge amount faster than with jruby-1.7.4. I committed the Profiler Snapshot here: https://github.com/muffl0n/wro4j-fingerprint/blob/master/wro-1.7.1_jruby-1.6.8.nps After enabling parallelProcessing I event got the duration down to 37s.

[alexo]

@muffl0n indeed, in the latest snapshot it is visible that the persistResourceFingerprints method has a 10 seconds penalty... mostly because it search inside css files for imports.. There is clearly a room for improvement.

[muffl0n]

I compared the 1.7.x versions of jruby to the last known version that was not terribly slow for sass-processing and got these results:

1.6.8: 2.667s

1.7.0: 7.435s
1.7.1: 9.501s
1.7.2: 10.554s
1.7.3: 10.354s
1.7.4: 9.133s
1.7.5: 11.753s
1.7.6: 11.63s
1.7.7: error
1.7.8: 12.121s
1.7.9: 11.294s
1.7.10: 11.721s
1.7.11: 11.448s
1.7.12: 11.404s
1.7.13: 11.906s
1.7.14: 2.531s

While 1.7.7 did not compile at all one can clearly see that there is a massive improvement with 1.7.14. Processing with this version is even faster than with 1.6.8.

My project now completes in 43s, down from 1m45s with jruby 1.7.11.

[alexo]

The branch 1.7.x (which will be used to release version 1.7.7) is stable. You suggest to update jruby to 1.7.11 to improve the processing performance?

[muffl0n]

The branch 1.7.x currently uses jruby 1.7.11 which is really slow. I suggest updating it to use jruby 1.7.14. See #199.