sprockets-rails
sprockets-rails copied to clipboard
rails
Development mode performance regression between v2.1.3 and v2.1.4
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 2de6c409267b25ecc10f1a89adb268f7afbda992. That is to say b5de852c8a414f11c930489d73b5edd8754e9976 does not exhibit the regression and 2de6c409267b25ecc10f1a89adb268f7afbda992 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.
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.
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
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.
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.
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_taginshared/_login_formis taking all the time when running sprockets-rails master. If I comment out that call, the render time forshared/_login_formdrops from ~70msec to 7msec - I don't think anything in
config.assets.precompileis causing trouble. I commented it out and still see the same behavior.
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 https://github.com/rails/sprockets-rails/blob/fdb0df6b7bf890df3a632e754ec7d4e51688662f/lib/sprockets/rails/helper.rb#L83-L85, I wonder how much faster it is.
Other info that might be useful, comparing regular reload times vs load, edit a js/css file, then reload.
I commented out https://github.com/rails/sprockets-rails/blob/fdb0df6b7bf890df3a632e754ec7d4e51688662f/lib/sprockets/rails/helper.rb#L83-L85 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.
I also tried comparing regular load times (clicking on a link) vs reload times (refreshing the page) and didn't see any difference.
I confirm the big performance regression as well. Any chance you have some news running the willkoehler/sprockets_rails_performance_test reproduction project?
@redox I just fixed a performance regression in sprockets-rails master dealing with the code mentioned in https://github.com/rails/sprockets-rails/issues/225#issuecomment-73813620 - can you see if that fixes what you're seeing?
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!
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
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
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.
@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).
@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 ?).
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!
@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.
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
@eileencodes I tried master and I'm seeing the same performance I saw on master on Feb 10 (my comment then: https://github.com/rails/sprockets-rails/issues/225#issuecomment-73645681). However the secondary regression with rendering shared/login_form is now gone.
Page performance under current master
