ActionView Erubis rendering is ten times slower than plain Erubis

[brauliobo]

Hello all,

I wanted to know what is the overhead of ActionView and modified slim's benchmarks. See the results below.

1000 Iterations
Rehearsal ----------------------------------------------------------------
(1) erb                        0.010000   0.000000   0.010000 (  0.017649)
(1) erubis                     0.020000   0.000000   0.020000 (  0.015099)
(1) fast erubis                0.020000   0.000000   0.020000 (  0.014776)
(1) rails erubis               0.010000   0.000000   0.010000 (  0.015612)
(1) actionview locals erubis   0.170000   0.010000   0.180000 (  0.168290)
(1) actionview vars erubis     0.150000   0.000000   0.150000 (  0.155732)
(1) temple erb                 0.020000   0.000000   0.020000 (  0.023802)
(1) slim pretty                0.040000   0.000000   0.040000 (  0.040340)
(1) slim ugly                  0.020000   0.000000   0.020000 (  0.019859)
(1) haml pretty                0.100000   0.000000   0.100000 (  0.095830)
(1) haml ugly                  0.080000   0.000000   0.080000 (  0.084720)
(2) erb                        0.030000   0.000000   0.030000 (  0.029845)
(2) erubis                     0.020000   0.000000   0.020000 (  0.025605)
(2) temple erb                 0.030000   0.000000   0.030000 (  0.027858)
(2) slim pretty                0.050000   0.000000   0.050000 (  0.046810)
(2) slim ugly                  0.030000   0.000000   0.030000 (  0.025806)
(2) haml pretty                0.100000   0.000000   0.100000 (  0.100112)
(2) haml ugly                  0.080000   0.000000   0.080000 (  0.088057)
------------------------------------------------------- total: 0.990000sec

To reproduce checkout https://github.com/brauliobo/slim and run TASK=bench bundle exec rake bench iterations=1000

[tgxworld]

Hi @brauliobo! Thanks for taking your time to report an issue 😄. However, I can't seem to understand what the issue is about.

1. What is the basis of comparison that you are using with respect to the rendering times of ActionView vs Rails using Erubis?

Could you also provide more information about the benchmarks that you've made? For instance, I can't be sure what fast erubis or rails erubis is actually benchmarking against without having to look closely into your repository. Providing more information will make it easier for someone to understand and work on this issue. 😸 Thank you!

[rud]

These numbers are very small for a benchmark, could you maybe increase the iteration count by a factor of a lot? That would be awesome :)

[brauliobo]

@rud here they are

~/P/o/slim git:master ❯❯❯ TASK=bench bundle exec rake bench iterations=100000
/home/braulio/.rvm/rubies/ruby-2.1.3/bin/ruby benchmarks/run-benchmarks.rb
100000 Iterations
                                  user     system      total        real
(1) erb                        1.640000   0.000000   1.640000 (  1.636494)
(1) erubis                     1.390000   0.000000   1.390000 (  1.396581)
(1) fast erubis                1.350000   0.000000   1.350000 (  1.354829)
(1) rails erubis               1.390000   0.000000   1.390000 (  1.398227)
(1) actionview locals erubis  13.260000   0.000000  13.260000 ( 13.291269)
(1) actionview vars erubis    12.830000   0.010000  12.840000 ( 12.864042)
(1) temple erb                 2.500000   0.000000   2.500000 (  2.499896)
(1) slim pretty                3.680000   0.000000   3.680000 (  3.691790)
(1) slim ugly                  2.160000   0.000000   2.160000 (  2.167704)
(1) actionview locals slim    10.980000   0.000000  10.980000 ( 11.012458)
(1) haml pretty                9.060000   0.000000   9.060000 (  9.080629)
(1) haml ugly                  8.610000   0.010000   8.620000 (  8.654973)
(2) erb                        3.310000   0.010000   3.320000 (  3.327990)
(2) erubis                     2.170000   0.000000   2.170000 (  2.182279)
(2) temple erb                 3.340000   0.010000   3.350000 (  3.359447)
(2) slim pretty                4.760000   0.000000   4.760000 (  4.771370)
(2) slim ugly                  3.330000   0.000000   3.330000 (  3.343455)
(2) haml pretty               10.220000   0.000000  10.220000 ( 10.264067)
(2) haml ugly                  9.060000   0.000000   9.060000 (  9.100737)

(1) Compiled benchmark. Template is parsed before the benchmark and
    generated ruby code is compiled into a method.
    This is the fastest evaluation strategy because it benchmarks
    pure execution speed of the generated ruby code.

(2) Compiled Tilt benchmark. Template is compiled with Tilt, which gives a more
    accurate result of the performance in production mode in frameworks like
    Sinatra, Ramaze and Camping. (Rails still uses its own template
    compilation.)

[brauliobo]

@tgxworld The purpose of this issue is to find out what is the overhead of views, rendering helpers and its context (controller) on template rendering. I think it might help to improve rails performance.

Fast erubis is just one the engines erubis provides, please look at their website.

More information can be easily found on https://github.com/brauliobo/slim/blob/master/benchmarks/run-benchmarks.rb

[thedarkone]

@brauliobo thanks for bringing our attention to this. I tried to investigate, here are my 2 issues with the benchmarks you're running:

Firstly, (1) rails erubis bench naming is misleading because it is a "pure erubis" bench: it invokes context.run_erubis, that has nothing to do with Rails. Instead it needs to invoke context.run_rails_erubis (this requires changing def run_rails_erubis; #{rails_erubis.src}; end to also lazy-init output_buffer like this: def run_rails_erubis; output_buffer ||= nil; #{rails_erubis.src}; end).

Fixing the bench to run context.run_rails_erubis brings the perf diff between "rails erubis" and "actionview locals erubis" to about 3X (instead of 10X).

Secondly, (1) actionview locals erubis uses the whole ActionView template lookup machinery, which probably explains the remaining 3X perf overhead.

@brauliobo maybe you should profile the bench, to see where the time is being spent?

[brauliobo]

@thedarkone you're completely right, rails erubis was just pure erubis. commited the fix and here are the corrected benchmarks:

                                   user     system      total        real
(1) erb                        1.590000   0.000000   1.590000 (  1.589469)
(1) erubis                     1.320000   0.000000   1.320000 (  1.324961)
(1) fast erubis                1.310000   0.000000   1.310000 (  1.306978)
(1) rails erubis               4.340000   0.020000   4.360000 (  4.347810)
(1) actionview locals erubis  11.910000   0.000000  11.910000 ( 11.899713)
(1) actionview vars erubis    11.600000   0.000000  11.600000 ( 11.589539)
(1) temple erb                 2.380000   0.000000   2.380000 (  2.378356)
(1) slim pretty                3.390000   0.000000   3.390000 (  3.388827)
(1) slim ugly                  1.920000   0.000000   1.920000 (  1.917130)
(1) actionview locals slim     9.890000   0.000000   9.890000 (  9.873888)
(1) haml pretty                8.460000   0.040000   8.500000 (  8.489442)
(1) haml ugly                  7.650000   0.030000   7.680000 (  7.670104)
(2) erb                        3.110000   0.000000   3.110000 (  3.102469)
(2) erubis                     2.010000   0.000000   2.010000 (  2.006057)
(2) temple erb                 3.150000   0.000000   3.150000 (  3.152332)
(2) slim pretty                4.430000   0.000000   4.430000 (  4.429535)
(2) slim ugly                  2.670000   0.000000   2.670000 (  2.670091)
(2) haml pretty                9.260000   0.000000   9.260000 (  9.257175)
(2) haml ugly                  8.290000   0.000000   8.290000 (  8.286993)

[brauliobo]

@thedarkone now we have two slow downs: rails erubis (~3x) and actionview (~3x).

i'm still learning about profiling tools, and I'll certainly profile more deeply this code to find the reasons.

but maybe on rails erubis the reason is probably the different buffer used?

[brauliobo]

@thedarkone I tried to use ActionView without AbstractController or ActionController::Base but couldn't. If you have some code for it please share.

[rails-bot]

This issue has been automatically marked as stale because it has not been commented on for at least
three months.

The resources of the Rails team are limited, and so we are asking for your help.

If you can still reproduce this error on the 4-2-stable, 4-1-stable branches or on master,
please reply with all of the information you have about it in order to keep the issue open.

Thank you for all your contributions.

[rails-bot]

This issue has been automatically marked as stale because it has not been commented on for at least
three months.

The resources of the Rails team are limited, and so we are asking for your help.

If you can still reproduce this error on the 4-2-stable, 4-1-stable branches or on master,
please reply with all of the information you have about it in order to keep the issue open.

Thank you for all your contributions.

[byroot]

Erubis has been replaced with Erubi as of 7da8d76, so I think we can close this issue.