Development mode performance regression between v2.1.3 and v2.1.4

[willkoehler]

I'm seeing a performance regression in development mode between v2.1.3 and v2.1.4. The symptom is the render time for layouts/application increased from 14msec in v2.1.3 to 250msec in v2.1.4.

Setting config.assets.debug = false lowers the render time to 5msec in v2.1.4. So the slow render time is caused by the asset pipeline.

By checking out subsequent commits of sprocket-rails, I narrowed the problem down to 2de6c40. That is to say b5de852 does not exhibit the regression and 2de6c40 does.

I originally observed the regression in version v2.2.4. So it's still present in the latest version.

I understand that in development mode assets are served individually and performance is not optimized. However performance in development mode has been reasonably fast prior to v2.1.4. Hopefully that performance can be restored.

Thanks for looking into this.

[josh]

Any chance you could try master? Thats currently going to be 3.x, but it has some significant changes around when it checks if the asset is in the precompile list.

[willkoehler]

Om master rendering layouts/applications is ~80msec. It's a little better. However rendering shared/login_form jumped from 8msec to 60msec. I have no idea how that could be related, the only gems that changed were sprockets and sprockets-rails. But it's a repeatable change.

Page performance under v2.1.3

Page performance under master

[josh]

Weird, I wonder what is running under shared/_login_form thats asset related.

Also, what does your config.assets.precompile look like? I wonder if theres anything expensive happening there.

[willkoehler]

Good questions. If it would help, tomorrow I can strip my application down into a bare-bones test app that I can share with you. In the process I may identify some components that are related to the slow rendering.

[willkoehler]

I stripped my application down to a test app that will allow you to reproduce the regression. I've pulled most of the application code out, but I left all the assets in.

https://github.com/willkoehler/sprockets_rails_performance_test

To answer your questions:

• It looks like the call to image_tag in shared/_login_form is taking all the time when running sprockets-rails master. If I comment out that call, the render time for shared/_login_form drops from ~70msec to 7msec
• I don't think anything in config.assets.precompile is causing trouble. I commented it out and still see the same behavior.

[josh]

Om master rendering layouts/applications is ~80msec. It's a little better. However rendering shared/login_form jumped from 8msec to 60msec.

Alright, so I think that change can be explained by the the work just being deferred from the layout to the image_tag call in shared/login_form.

My hunch is the dev time "asset not precompiled" check is still too slow. Like if you complete remove

sprockets-rails/lib/sprockets/rails/helper.rb

Lines 83 to 85 in fdb0df6

	if !precompiled_assets.include?(asset)
	raise AssetNotPrecompiled.new(asset.logical_path)
	end

, I wonder how much faster it is.

[josh]

Other info that might be useful, comparing regular reload times vs load, edit a js/css file, then reload.

[willkoehler]

I commented out

sprockets-rails/lib/sprockets/rails/helper.rb

Lines 83 to 85 in fdb0df6

	if !precompiled_assets.include?(asset)
	raise AssetNotPrecompiled.new(asset.logical_path)
	end

in my local copy of sprockets-rails and the render time for shared/_login_form dropped back down to normal (from ~70msec to 7msec). Render time for layouts/application went up (from ~90msec to ~180msec) when those lines were commented out.

[willkoehler]

I also tried comparing regular load times (clicking on a link) vs reload times (refreshing the page) and didn't see any difference.

[redox]

I confirm the big performance regression as well. Any chance you have some news running the willkoehler/sprockets_rails_performance_test reproduction project?

[eileencodes]

@redox I just fixed a performance regression in sprockets-rails master dealing with the code mentioned in #225 (comment) - can you see if that fixes what you're seeing?

[redox]

Thank you for taking care of it @eileencodes, it turns out that my issue is not between 2.1.3 and 2.1.4 but since 2.2. Here is a more detailed report of what I see:

I'm running rails 4.2.3 and the whole time is spent in the stylesheet_link_tag and javascript_include_tag methods (where I have a bunch of require).

2.1.3: OK

ab -c 1 -n 100 http://localhost:3000/

Server Software:        
Server Hostname:        localhost
Server Port:            3000

Document Path:          /
Document Length:        99234 bytes

Concurrency Level:      1
Time taken for tests:   29.232 seconds
Complete requests:      100
Failed requests:        4
   (Connect: 0, Receive: 0, Length: 4, Exceptions: 0)
Total transferred:      9992384 bytes
HTML transferred:       9923384 bytes
Requests per second:    3.42 [#/sec] (mean)
Time per request:       292.318 [ms] (mean)
Time per request:       292.318 [ms] (mean, across all concurrent requests)
Transfer rate:          333.82 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.1      0       1
Processing:   194  292  83.5    279     817
Waiting:      194  292  83.5    279     817
Total:        194  292  83.5    279     818

Percentage of the requests served within a certain time (ms)
  50%    279
  66%    298
  75%    311
  80%    325
  90%    380
  95%    441
  98%    544
  99%    818
 100%    818 (longest request)

2.1.4: OK

ab -c 1 -n 100 http://localhost:3000/

Server Software:        
Server Hostname:        localhost
Server Port:            3000

Document Path:          /
Document Length:        99234 bytes

Concurrency Level:      1
Time taken for tests:   26.767 seconds
Complete requests:      100
Failed requests:        5
   (Connect: 0, Receive: 0, Length: 5, Exceptions: 0)
Total transferred:      9992380 bytes
HTML transferred:       9923380 bytes
Requests per second:    3.74 [#/sec] (mean)
Time per request:       267.670 [ms] (mean)
Time per request:       267.670 [ms] (mean, across all concurrent requests)
Transfer rate:          364.56 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:   195  267  44.8    260     396
Waiting:      195  267  44.8    260     396
Total:        195  268  44.8    260     396

Percentage of the requests served within a certain time (ms)
  50%    260
  66%    284
  75%    297
  80%    312
  90%    333
  95%    352
  98%    361
  99%    396
 100%    396 (longest request)

2.2.3: KO (from 260 -> 1336ms)

ab -c 1 -n 100 http://localhost:3000/ # stopped after ~59 requests, too slow :)

Server Software:        
Server Hostname:        localhost
Server Port:            3000

Document Path:          /
Document Length:        99734 bytes

Concurrency Level:      1
Time taken for tests:   90.088 seconds
Complete requests:      59
Failed requests:        1
   (Connect: 0, Receive: 0, Length: 1, Exceptions: 0)
Total transferred:      5925012 bytes
HTML transferred:       5884302 bytes
Requests per second:    0.65 [#/sec] (mean)
Time per request:       1526.920 [ms] (mean)
Time per request:       1526.920 [ms] (mean, across all concurrent requests)
Transfer rate:          64.23 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:  1123 1524 739.2   1336    6682
Waiting:     1123 1524 739.2   1336    6681
Total:       1123 1524 739.2   1336    6682

Percentage of the requests served within a certain time (ms)
  50%   1334
  66%   1437
  75%   1505
  80%   1550
  90%   1912
  95%   2380
  98%   2654
  99%   6682
 100%   6682 (longest request)

2.3.2: KO (from 1336 -> 1709ms)

ab -c 1 -n 100 http://localhost:3000/ # stopped after 29 request, too slow :)

Server Software:        
Server Hostname:        localhost
Server Port:            3000

Document Path:          /
Document Length:        99734 bytes

Concurrency Level:      1
Time taken for tests:   52.671 seconds
Complete requests:      29
Failed requests:        0
Total transferred:      2912296 bytes
HTML transferred:       2892286 bytes
Requests per second:    0.55 [#/sec] (mean)
Time per request:       1816.237 [ms] (mean)
Time per request:       1816.237 [ms] (mean, across all concurrent requests)
Transfer rate:          54.00 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.1      0       1
Processing:  1332 1786 527.4   1709    3684
Waiting:     1332 1786 527.4   1709    3684
Total:       1332 1786 527.4   1710    3684

Percentage of the requests served within a certain time (ms)
  50%   1709
  66%   1790
  75%   1879
  80%   2048
  90%   2630
  95%   2727
  98%   3684
  99%   3684
 100%   3684 (longest request)

github: 'rails/sprockets-rails`: better but still far from 2.1.x (from 1709 -> 1192)

ab -c 1 -n 100 http://localhost:3000/ # stopped after 79 request, too slow :)

Server Software:        
Server Hostname:        localhost
Server Port:            3000

Document Path:          /
Document Length:        115009 bytes

Concurrency Level:      1
Time taken for tests:   101.617 seconds
Complete requests:      79
Failed requests:        3
   (Connect: 0, Receive: 0, Length: 3, Exceptions: 0)
Total transferred:      9140288 bytes
HTML transferred:       9085699 bytes
Requests per second:    0.78 [#/sec] (mean)
Time per request:       1286.296 [ms] (mean)
Time per request:       1286.296 [ms] (mean, across all concurrent requests)
Transfer rate:          87.84 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.1      0       0
Processing:   866 1280 331.1   1192    2704
Waiting:      866 1280 331.1   1192    2703
Total:        867 1281 331.1   1192    2704

Percentage of the requests served within a certain time (ms)
  50%   1190
  66%   1318
  75%   1411
  80%   1503
  90%   1706
  95%   1996
  98%   2279
  99%   2704
 100%   2704 (longest request)

Let me know what you think!

[redox]

And here is what I see with ruby-prof on the master branch:

Measure Mode: wall_time
Thread ID: 70253745167340
Fiber ID: 70253756137300
Total: 1.518107
Sort by: self_time

 %self      total      self      wait     child     calls  name
 19.84      0.302     0.301     0.000     0.000     1368   <Module::Marshal>#load_without_autoloading
  5.71      0.087     0.087     0.000     0.000      143   Zlib::Inflate#inflate
  4.60      0.070     0.070     0.000     0.000     1339   <Class::File>#utime
  4.22      0.074     0.064     0.000     0.010     1908   Sprockets::URIUtils#join_file_uri
  3.72      0.448     0.056     0.000     0.392     1339   Sprockets::EncodingUtils#unmarshaled_deflated
  3.58      0.054     0.054     0.000     0.000    21137   String#scan
  2.48      0.222     0.038     0.000     0.184    20937   Sprockets::Resolve#parse_path_extnames
  2.16      0.033     0.033     0.000     0.000     4095   <Class::File>#exist?
  2.03      0.031     0.031     0.000     0.000        2   SQLite3::Statement#step
  1.77      0.055     0.027     0.000     0.029    20939   Array#reverse_each
  1.75      0.048     0.027     0.000     0.021      302   Array#include?
  1.74      0.028     0.026     0.000     0.002     7471  *String#gsub
  1.63      0.025     0.025     0.000     0.000     1370   File#initialize
  1.46      0.022     0.022     0.000     0.000   120894   String#==
  1.42      0.052     0.022     0.000     0.031     1831   Sprockets::DigestUtils#digest
  1.38      0.021     0.021     0.000     0.000    21201   <Class::File>#basename
  1.32      0.020     0.020     0.000     0.000       20   <Class::Dir>#[]
  1.29      0.020     0.020     0.000     0.000     3203   Regexp#===
  1.28      0.161     0.019     0.000     0.141    20937   Sprockets::PathUtils#match_path_extname

[eileencodes]

Are you seeing the same in a vanilla application? I'm not seeing a slowdown between tag v2.1.4 and tag v2.2.3 (using https://github.com/eileencodes/perf_regression_sprockets) - I'm actually seeing a speed up between the two using benchmark-ips. I'm not really sure why there's the difference, but I think this might be a different issue mentioned above so we should move this discussion to a new issue.

v2.1.4

Calculating -------------------------------------
     Running test...    28.000  i/100ms
-------------------------------------------------
     Running test...    269.960  (±11.9%) i/s -      1.344k

v2.2.3

Calculating -------------------------------------
     Running test...    61.000  i/100ms
-------------------------------------------------
     Running test...    739.657  (± 8.2%) i/s -      3.721k

[redox]

Yeah it might be something else, I cannot reproduce the issue with the vanilla app. I'll try to create an open-source vanilla app reproducing the issue.

[redox]

@eileencodes Let me know what you think about this reproduction case: https://github.com/redox/perf_regression_sprockets#readme

As you said, it's probably not the same issue so I would be happy to create another issue. This vanilla projects illustrates the performance regression between 2.1.3 and all other releases.

From 20ms to 60ms in the current master branch (was 200+ in 2.1.4).

[redox]

@eileencodes So from what I understand, what I see has nothing to deal with sprocket-rails but rather with the way path_to_stylesheet resolves the logical_path (so I assume rather a regression in sprockets ?).

[eileencodes]

hey sorry I didn't respond earlier @redox I was at a conference.

So from your app it looks like you're saying it happens when there are a ton of required files? Can you open a new issue and cc me? Thanks for looking into this!

[eileencodes]

@willkoehler can you check master and see if the issue still exists for you there? I fixed a perf issue in the area of code you mentioned in an earlier post.

[redox]

So from your app it looks like you're saying it happens when there are a ton of required files? Can you open a new issue and cc me? Thanks for looking into this!

Sure thing @eileencodes

[willkoehler]

@eileencodes I tried master and I'm seeing the same performance I saw on master on Feb 10 (my comment then: #225 (comment)). However the secondary regression with rendering shared/login_form is now gone.

Page performance under current master