[ruby-core:101295] [Ruby master Bug#17373] Ruby 3.0 is slower at Discourse bench than Ruby 2.7

Issue #17373 has been updated by tenderlovemaking (Aaron Patterson).

File aaron — perf _home_aaron_git_railsbench — ssh whiteclaw.local — 299×65 2020-12-07 13-19-20.png added
File aaron — perf _home_aaron_git_railsbench — ssh whiteclaw.local — 175×54 2020-12-07 12-41-58.png added
File aaron — perf _home_aaron_git_railsbench — ssh whiteclaw.local — 175×54 2020-12-07 12-41-12.png added

Here is what I've found so far:

I've been testing with [RailsBench](https://github.com/k0kubun/railsbench).  I ran this command:

```
RAILS_ENV=production INTERVAL=100 WARMUP=1 BENCHMARK=10000 perf record -F 99 --call-graph dwarf (which ruby) bin/bench
```

Then I used this command to find where time is spent:

```
perf report -g graph --no-children
```

Here is the report on Ruby 2.7:

![Ruby 2.7 report](aaron%20%E2%80%94%20perf%20_home%3Aaaron%3Agit%3Arailsbench%20%E2%80%94%20ssh%20whiteclaw.local%20%E2%80%94%20175%C3%9754%202020-12-07%2012-41-12.png)

Here is the report on Ruby 3.0 (master):

![Ruby 3.0 report](aaron%20%E2%80%94%20perf%20_home%3Aaaron%3Agit%3Arailsbench%20%E2%80%94%20ssh%20whiteclaw.local%20%E2%80%94%20175%C3%9754%202020-12-07%2012-41-58.png)

`rb_id_table_lookup` is a new line in the Ruby 3.0 report.  Looking at the callers, it looks like these are coming from the slow path method lookup:

![Slow path lookup](aaron%20%E2%80%94%20perf%20_home%3Aaaron%3Agit%3Arailsbench%20%E2%80%94%20ssh%20whiteclaw.local%20%E2%80%94%20299%C3%9765%202020-12-07%2013-19-20.png)

b9007b6c54 touched these methods, so I ran the benchmarks on that commit:

```
aaron@whiteclaw ~/g/railsbench (ruby-3.0)> RAILS_ENV=production INTERVAL=100 WARMUP=1 BENCHMARK=10000 ruby -v bin/bench
ruby 2.8.0dev (2020-02-22T00:58:59Z pz-mvh-updated-mas.. b9007b6c54) [x86_64-linux]
/home/aaron/.gem/ruby/2.7.3/gems/mail-2.7.1/lib/mail/parsers/address_lists_parser.rb:32454: warning: statement not reached
/home/aaron/.gem/ruby/2.7.3/gems/mail-2.7.1/lib/mail/parsers/address_lists_parser.rb:32615: warning: statement not reached
/home/aaron/.gem/ruby/2.7.3/gems/mail-2.7.1/lib/mail/parsers/address_lists_parser.rb:32651: warning: statement not reached
/home/aaron/.gem/ruby/2.7.3/gems/mail-2.7.1/lib/mail/parsers/address_lists_parser.rb:32740: warning: statement not reached
/home/aaron/.gem/ruby/2.7.3/gems/mail-2.7.1/lib/mail/parsers/address_lists_parser.rb:32756: warning: statement not reached
/home/aaron/.gem/ruby/2.7.3/gems/mail-2.7.1/lib/mail/parsers/address_lists_parser.rb:32822: warning: statement not reached
/home/aaron/.gem/ruby/2.7.3/gems/mail-2.7.1/lib/mail/parsers/address_lists_parser.rb:32863: warning: statement not reached
/home/aaron/.gem/ruby/2.7.3/gems/mail-2.7.1/lib/mail/parsers/address_lists_parser.rb:32888: warning: statement not reached
/home/aaron/.gem/ruby/2.7.3/gems/mail-2.7.1/lib/mail/parsers/address_lists_parser.rb:31984: warning: assigned but unused variable - testEof
/home/aaron/.gem/ruby/2.7.3/gems/sassc-rails-2.1.2/lib/sassc/rails/functions.rb:7: warning: method redefined; discarding old asset_data_url
/home/aaron/.gem/ruby/2.7.3/gems/sprockets-4.0.1/lib/sprockets/sass_processor.rb:274: warning: previous definition of asset_data_url was here
/home/aaron/.gem/ruby/2.7.3/gems/sassc-rails-2.1.2/lib/sassc/rails/compressor.rb:7: warning: method redefined; discarding old initialize
/home/aaron/.gem/ruby/2.7.3/gems/sprockets-4.0.1/lib/sprockets/sass_compressor.rb:39: warning: previous definition of initialize was here
/home/aaron/.gem/ruby/2.7.3/gems/sassc-rails-2.1.2/lib/sassc/rails/compressor.rb:17: warning: method redefined; discarding old call
/home/aaron/.gem/ruby/2.7.3/gems/sprockets-4.0.1/lib/sprockets/sass_compressor.rb:49: warning: previous definition of call was here
Warming up...
Warmup: 1 requests
Benchmark: 10000 requests

Request per second: 993.5 [#/s] (mean)

Percentage of the requests served within a certain time (ms)
  50%    0.98
  66%    0.99
  75%    0.99
  80%    1.00
  90%    1.01
  95%    1.03
  98%    1.60
  99%    2.14
 100%   10.14
```

Mean request per second is 993.5.

If I run with the previous commit f2286925f0 here are the results:

```
aaron@whiteclaw ~/g/railsbench (ruby-3.0)> RAILS_ENV=production INTERVAL=100 WARMUP=1 BENCHMARK=10000 ruby -v bin/bench
ruby 2.8.0dev (2020-02-22T00:58:59Z pz-mvh-updated-mas.. f2286925f0) [x86_64-linux]
/home/aaron/.gem/ruby/2.7.3/gems/mail-2.7.1/lib/mail/parsers/address_lists_parser.rb:32454: warning: statement not reached
/home/aaron/.gem/ruby/2.7.3/gems/mail-2.7.1/lib/mail/parsers/address_lists_parser.rb:32615: warning: statement not reached
/home/aaron/.gem/ruby/2.7.3/gems/mail-2.7.1/lib/mail/parsers/address_lists_parser.rb:32651: warning: statement not reached
/home/aaron/.gem/ruby/2.7.3/gems/mail-2.7.1/lib/mail/parsers/address_lists_parser.rb:32740: warning: statement not reached
/home/aaron/.gem/ruby/2.7.3/gems/mail-2.7.1/lib/mail/parsers/address_lists_parser.rb:32756: warning: statement not reached
/home/aaron/.gem/ruby/2.7.3/gems/mail-2.7.1/lib/mail/parsers/address_lists_parser.rb:32822: warning: statement not reached
/home/aaron/.gem/ruby/2.7.3/gems/mail-2.7.1/lib/mail/parsers/address_lists_parser.rb:32863: warning: statement not reached
/home/aaron/.gem/ruby/2.7.3/gems/mail-2.7.1/lib/mail/parsers/address_lists_parser.rb:32888: warning: statement not reached
/home/aaron/.gem/ruby/2.7.3/gems/mail-2.7.1/lib/mail/parsers/address_lists_parser.rb:31984: warning: assigned but unused variable - testEof
/home/aaron/.gem/ruby/2.7.3/gems/sassc-rails-2.1.2/lib/sassc/rails/functions.rb:7: warning: method redefined; discarding old asset_data_url
/home/aaron/.gem/ruby/2.7.3/gems/sprockets-4.0.1/lib/sprockets/sass_processor.rb:274: warning: previous definition of asset_data_url was here
/home/aaron/.gem/ruby/2.7.3/gems/sassc-rails-2.1.2/lib/sassc/rails/compressor.rb:7: warning: method redefined; discarding old initialize
/home/aaron/.gem/ruby/2.7.3/gems/sprockets-4.0.1/lib/sprockets/sass_compressor.rb:39: warning: previous definition of initialize was here
/home/aaron/.gem/ruby/2.7.3/gems/sassc-rails-2.1.2/lib/sassc/rails/compressor.rb:17: warning: method redefined; discarding old call
/home/aaron/.gem/ruby/2.7.3/gems/sprockets-4.0.1/lib/sprockets/sass_compressor.rb:49: warning: previous definition of call was here
Warming up...
Warmup: 1 requests
Benchmark: 10000 requests

Request per second: 1164.9 [#/s] (mean)

Percentage of the requests served within a certain time (ms)
  50%    0.85
  66%    0.85
  75%    0.85
  80%    0.86
  90%    0.86
  95%    0.87
  98%    0.89
  99%    1.76
 100%    3.44
```

Mean RPS is 1164.

I think b9007b6c54 introduced the performance problem, but I'm not sure why.  The caller `lookup_method_table` didn't change, it just got moved [from here](https://github.com/ruby/ruby/commit/b9007b6c54#diff-884a5a8a369ef1b4c7597e00aa65974cec8c5f54f25f03ad5d24848f64892869L182-L195) to [here](https://github.com/ruby/ruby/commit/b9007b6c54#diff-884a5a8a369ef1b4c7597e00aa65974cec8c5f54f25f03ad5d24848f64892869R624-R636), and `rb_id_table_lookup` is exactly the same too.

My current guess is that we're getting cache misses more frequently for some reason.  I will look in to that now, but I wanted to share what I've found so far.


----------------------------------------
Bug #17373: Ruby 3.0 is slower at Discourse bench than Ruby 2.7
https://bugs.ruby-lang.org/issues/17373#change-88979

* Author: sam.saffron (Sam Saffron)
* Status: Open
* Priority: Normal
* ruby -v: 3.0
* Backport: 2.5: UNKNOWN, 2.6: UNKNOWN, 2.7: UNKNOWN
----------------------------------------
We have a continuous effort to keep https://rubybench.org/ up to date. Unfortunately we have lapsed a bit on updates so I decided to run Discourse bench by hand.

On my local system I am noticing the timing are much slower on Discourse bench than they were on Ruby 2.7: 

```
98c9120cc00ba691b4abcc13a49a30fa54638535

---
categories:
  50: 34
  75: 35
  90: 36
  99: 40
home:
  50: 47
  75: 50
  90: 56
  99: 92
topic:
  50: 53
  75: 55
  90: 58
  99: 92
categories_admin:
  50: 33
  75: 34
  90: 38
  99: 68
home_admin:
  50: 45
  75: 47
  90: 51
  99: 95
topic_admin:
  50: 51
  75: 52
  90: 54
  99: 59
timings:
  load_rails: 1449
ruby-version: 3.0.0-p-1
rss_kb: 293808
pss_kb: 284244

2.7.2


---
categories:
  50: 29
  75: 30
  90: 33
  99: 43
home:
  50: 42
  75: 43
  90: 47
  99: 73
topic:
  50: 47
  75: 47
  90: 52
  99: 54
categories_admin:
  50: 30
  75: 31
  90: 36
  99: 56
home_admin:
  50: 41
  75: 43
  90: 48
  99: 71
topic_admin:
  50: 47
  75: 48
  90: 52
  99: 55
timings:
  load_rails: 1339
ruby-version: 2.7.2-p137
rss_kb: 296836
pss_kb: 287310


2.6.6


---
categories:
  50: 30
  75: 30
  90: 31
  99: 51
home:
  50: 40
  75: 42
  90: 60
  99: 79
topic:
  50: 47
  75: 48
  90: 53
  99: 71
categories_admin:
  50: 30
  75: 31
  90: 35
  99: 50
home_admin:
  50: 41
  75: 43
  90: 62
  99: 100
topic_admin:
  50: 48
  75: 49
  90: 65
  99: 93
timings:
  load_rails: 1464
ruby-version: 2.6.6-p146
rss_kb: 332268
pss_kb: 322865
```

Concretely this means a typical "homepage" view is taking 47 milliseconds now, when in the past it was taking 42 or even 40 ms.

There may be some issues with the bench, you can see it here: 

https://github.com/discourse/discourse/tree/ruby-3

The script to run the bench is `ruby script/bench.rb`

I re-tested against a cleanly built Ruby 2.7 direct from the Git branch to ensure compilation was not at fault.


This is pretty concerning, Discourse bench usually tracks Rails performance pretty accurately. 

---Files--------------------------------
aaron — perf _home_aaron_git_railsbench — ssh whiteclaw.local — 175×54 2020-12-07 12-41-12.png (842 KB)
aaron — perf _home_aaron_git_railsbench — ssh whiteclaw.local — 175×54 2020-12-07 12-41-58.png (874 KB)
aaron — perf _home_aaron_git_railsbench — ssh whiteclaw.local — 299×65 2020-12-07 13-19-20.png (142 KB)


-- 
https://bugs.ruby-lang.org/

Unsubscribe: <mailto:[e-mail]?subject=unsubscribe>
<http://lists.ruby-lang.org/cgi-bin/mailman/options/ruby-core>