Based on headius/pgrailsbench, but on Rails 6.1 and with database seeds.
This application is generated by following commands:
rails new railsbench
rails g scaffold post title:string body:text published:boolean
Populate database and assets for RAILS_ENV=production.
# Ubuntu
sudo apt install libsqlite3-dev nodejs npm
sudo npm install -g yarn
bundle install
bundle exec rake db:create db:migrate db:seed RAILS_ENV=production
bundle exec rake assets:precompile RAILS_ENV=production# MRI
bundle exec puma -e production --workers=4 --threads=1 --preload
# JRuby, TruffleRuby
bundle exec puma -e production --threads=4You can see posts on localhost:3000/posts.
Assets are not shown properly with -e production but it's intentional because
Rails assumes we delegate assets distribution to a reverse proxy on production by default.
If you want to see the actual apprecation behavior, do the setup with RAILS_ENV=development
and try puma -e development.
Install Apache Bench with sudo apt install apache2-utils. Then:
# HTML posts#index
ab -c 4 -n 10000 localhost:3000/posts
# JSON posts#index
ab -c 4 -n 10000 localhost:3000/posts.json
# HTML posts#show
ab -c 4 -n 10000 localhost:3000/posts/1
# JSON posts#show
ab -c 4 -n 10000 localhost:3000/posts/1.jsonHere is the benchmark result on: Intel 4.0GHz i7-4790K, 16GB memory, x86-64 Ubuntu 8 Cores
JRuby claims to be faster than MRI when after 50k requests with a single post read. This part measures results with following steps:
- Restart puma
- Run
ab -n 50000as warmup - Run
ab -n 10000as benchmark
See log/benchmark_50k for details.
The following table is showing response time milliseconds for each %ile in the last 10,000 requests.
| Ruby 2.6.2 | Ruby 2.6.2 JIT | JRuby 9.2.6.0 indy | |
|---|---|---|---|
| 50% | 2 | 4 | 3 |
| 66% | 2 | 5 | 3 |
| 75% | 3 | 5 | 3 |
| 80% | 3 | 6 | 3 |
| 90% | 3 | 8 | 3 |
| 95% | 3 | 10 | 4 |
| 98% | 6 | 15 | 5 |
| 99% | 10 | 17 | 6 |
| 100% | 54 | 37 | 15 |
The following table is showing # of requests per second (mean).
| Ruby 2.6.2 | Ruby 2.6.2 JIT | JRuby 9.2.6.0 indy | |
|---|---|---|---|
| #/s | 1653.11 | 744.18 | 1335.05 |
Here is the benchmark result on: Intel 4.0GHz i7-4790K, 16GB memory, x86-64 Ubuntu 8 Cores
For each result, I measured results with following steps:
- Restart puma
- Run
ab -n 10000as warmup - Run
ab -n 1000as benchmark
Following tables are showing response time milliseconds for each %ile in the last 1,000 requests. See log/benchmark for details.
| Ruby 2.6.2 | Ruby 2.6.2 JIT | JRuby 9.2.6.0 | JRuby 9.2.6.0 indy | JRuby 9.2.6.0 indy Graal | |
|---|---|---|---|---|---|
| 50% | 11 | 23 | 18 | 13 | 22 |
| 66% | 15 | 27 | 21 | 18 | 22 |
| 75% | 16 | 30 | 26 | 19 | 22 |
| 80% | 17 | 31 | 26 | 19 | 24 |
| 90% | 18 | 41 | 28 | 20 | 28 |
| 95% | 24 | 51 | 29 | 22 | 35 |
| 98% | 28 | 61 | 32 | 26 | 36 |
| 99% | 34 | 70 | 34 | 28 | 38 |
| 100% | 44 | 101 | 41 | 35 | 44 |
| Ruby 2.6.2 | Ruby 2.6.2 JIT | JRuby 9.2.6.0 | JRuby 9.2.6.0 indy | JRuby 9.2.6.0 indy Graal | |
|---|---|---|---|---|---|
| 50% | 27 | 61 | 31 | 21 | 53 |
| 66% | 29 | 69 | 32 | 23 | 58 |
| 75% | 30 | 76 | 34 | 26 | 61 |
| 80% | 31 | 81 | 35 | 28 | 62 |
| 90% | 40 | 106 | 40 | 31 | 68 |
| 95% | 54 | 117 | 45 | 32 | 78 |
| 98% | 56 | 131 | 47 | 35 | 85 |
| 99% | 62 | 144 | 50 | 38 | 92 |
| 100% | 78 | 203 | 56 | 45 | 101 |
| Ruby 2.6.2 | Ruby 2.6.2 JIT | JRuby 9.2.6.0 | JRuby 9.2.6.0 indy | JRuby 9.2.6.0 indy Graal | |
|---|---|---|---|---|---|
| 50% | 3 | 5 | 8 | 7 | 8 |
| 66% | 4 | 6 | 9 | 8 | 9 |
| 75% | 4 | 7 | 9 | 9 | 12 |
| 80% | 5 | 8 | 10 | 10 | 13 |
| 90% | 5 | 10 | 13 | 12 | 16 |
| 95% | 6 | 12 | 15 | 14 | 19 |
| 98% | 9 | 17 | 19 | 18 | 22 |
| 99% | 14 | 22 | 22 | 19 | 26 |
| 100% | 28 | 31 | 28 | 46 | 28 |
| Ruby 2.6.2 | Ruby 2.6.2 JIT | JRuby 9.2.6.0 | JRuby 9.2.6.0 indy | JRuby 9.2.6.0 indy Graal | |
|---|---|---|---|---|---|
| 50% | 3 | 4 | 8 | 7 | 6 |
| 66% | 3 | 6 | 9 | 7 | 7 |
| 75% | 4 | 7 | 9 | 8 | 8 |
| 80% | 4 | 7 | 10 | 9 | 8 |
| 90% | 5 | 9 | 13 | 11 | 9 |
| 95% | 5 | 13 | 16 | 11 | 10 |
| 98% | 6 | 17 | 19 | 13 | 10 |
| 99% | 11 | 21 | 19 | 16 | 12 |
| 100% | 29 | 29 | 28 | 20 | 15 |
$ WARMUP=1 BENCHMARK=10000 RAILS_ENV=production sudo -E perf record -c 10000 ~/.rbenv/versions/2.6.2/bin/ruby bin/bench
Warmup: 1 requests
Benchmark: 10000 requests
Request per second: 843.8 [#/s] (mean)
Percentage of the requests served within a certain time (ms)
50% 1.02
66% 1.14
75% 1.26
80% 1.30
90% 1.35
95% 1.48
98% 1.79
99% 5.96
100% 13.65
[ perf record: Woken up 106 times to write data ]
[ perf record: Captured and wrote 26.491 MB perf.data (857163 samples) ]
$ sudo perf report
Samples: 857K of event 'cycles:ppp', Event count (approx.): 8571630000
Overhead Command Shared Object Symbol
20.21% ruby ruby [.] vm_exec_core
3.71% ruby ruby [.] st_lookup
3.24% ruby ruby [.] vm_call_cfunc
2.63% ruby ruby [.] rb_wb_protected_newobj_of
2.51% ruby ruby [.] vm_call_iseq_setup
2.34% ruby ruby [.] rb_id_table_lookup
2.26% ruby ruby [.] method_entry_get
2.16% ruby ruby [.] vm_call_iseq_setup_normal_0start_0params_0locals
1.55% ruby ruby [.] find_entry
1.55% ruby ruby [.] gc_sweep_step
1.41% ruby libc-2.27.so [.] _int_malloc
1.38% ruby ruby [.] rb_class_of
1.35% ruby ruby [.] vm_call_iseq_setup_normal_0start_1params_1locals
1.13% ruby ruby [.] setup_parameters_complex
1.10% ruby ruby [.] rb_memhash
1.00% ruby libc-2.27.so [.] __malloc_usable_size
0.94% ruby libc-2.27.so [.] malloc
0.79% ruby ruby [.] vm_call0_body.constprop.402
0.75% ruby ruby [.] match_at
0.75% ruby ruby [.] rb_obj_is_kind_of
0.72% ruby libc-2.27.so [.] malloc_consolidate
0.72% ruby ruby [.] rb_enc_get
0.71% ruby libc-2.27.so [.] cfree@GLIBC_2.2.5
0.61% ruby ruby [.] vm_call_method_each_type
0.57% ruby ruby [.] rb_get_alloc_func
0.56% ruby ruby [.] st_update
0.55% ruby libc-2.27.so [.] __memmove_avx_unaligned_erms
0.54% ruby ruby [.] str_buf_cat
0.53% ruby ruby [.] rb_callable_method_entry
0.49% ruby ruby [.] rb_call0.constprop.401
0.49% ruby ruby [.] vm_call_method
Samples: 2M of event 'cycles:ppp', Event count (approx.): 20509820000
Overhead Command Shared Object Symbol
8.70% ruby ruby [.] vm_exec_core
1.65% ruby ruby [.] st_lookup
1.45% ruby ruby [.] vm_call_cfunc
1.28% ruby ruby [.] rb_wb_protected_newobj_of
1.21% ruby ruby [.] vm_call_iseq_setup
1.07% ruby ruby [.] method_entry_get
1.07% ruby ruby [.] vm_call_iseq_setup_normal_0start_0params_0locals
1.04% ruby libc-2.27.so [.] _int_malloc
1.03% ruby ruby [.] rb_id_table_lookup
1.01% cc1 cc1 [.] _Z14bitmap_set_bitP11bitmap_headi
0.85% ruby ruby [.] gc_sweep_step
0.71% ruby ruby [.] vm_call_iseq_setup_normal_0start_1params_1locals
0.71% ruby libc-2.27.so [.] __malloc_usable_size
0.68% ruby ruby [.] find_entry
0.62% ruby ruby [.] rb_class_of
0.55% cc1 libc-2.27.so [.] cfree@GLIBC_2.2.5
0.54% cc1 libc-2.27.so [.] _int_malloc
0.54% ruby ruby [.] setup_parameters_complex
0.46% ruby libc-2.27.so [.] malloc_consolidate
0.45% ruby ruby [.] rb_memhash
0.43% cc1 cc1 [.] _Z12bitmap_bit_pP11bitmap_headi
0.41% ruby libc-2.27.so [.] malloc
0.41% cc1 cc1 [.] _Z18ggc_internal_allocmPFvPvEmm
0.39% ruby libc-2.27.so [.] cfree@GLIBC_2.2.5
0.37% ruby ruby [.] mjit_exec.part.335
0.34% ruby ruby [.] rb_obj_is_kind_of
0.33% ruby ruby [.] match_at
0.32% cc1 cc1 [.] _Z16bitmap_clear_bitP11bitmap_headi
0.32% ruby ruby [.] vm_call0_body.constprop.402
0.31% ruby ruby [.] rb_enc_get
0.29% ruby ruby [.] gc_mark_children
$ PROFILE=wall INTERVAL=100 WARMUP=1 BENCHMARK=10000 bin/bench
Warmup: 1 requests
Benchmarking 10000 requests...
Request per second: 860.5 [#/s] (mean)
$ stackprof stackprof-2019-03-17_12:17:46_+0900.dump
==================================
Mode: wall(100)
Samples: 114881 (0.81% miss rate)
GC: 4907 (4.27%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
6363 (5.5%) 6363 (5.5%) Concurrent::Collection::NonConcurrentMapBackend#[]
4907 (4.3%) 4907 (4.3%) (garbage collection)
3843 (3.3%) 3843 (3.3%) Logger::Formatter#format_datetime
4774 (4.2%) 3418 (3.0%) Logger::LogDevice#write
2878 (2.5%) 2878 (2.5%) Rack::Request::Env#get_header
2116 (1.8%) 2116 (1.8%) ActiveSupport::SafeBuffer#initialize
6212 (5.4%) 1773 (1.5%) Logger::Formatter#call
2374 (2.1%) 1454 (1.3%) ActionView::Helpers::TagHelper::TagBuilder#tag_option
2105 (1.8%) 1436 (1.2%) block (2 levels) in class_attribute
1399 (1.2%) 1399 (1.2%) block (4 levels) in class_attribute
1347 (1.2%) 1347 (1.2%) ActiveSupport::InheritableOptions#initialize
1218 (1.1%) 1218 (1.1%) ActiveSupport::PerThreadRegistry#instance
1178 (1.0%) 1178 (1.0%) ActionDispatch::Http::FilterParameters#initialize
1076 (0.9%) 1076 (0.9%) ActiveSupport::Configurable::ClassMethods#config
1051 (0.9%) 1051 (0.9%) Rack::Request::Env#fetch_header
1029 (0.9%) 1029 (0.9%) Rack::Utils::HeaderHash#[]=
1025 (0.9%) 1025 (0.9%) ActiveModel::Attribute#initialize
982 (0.9%) 982 (0.9%) ActiveSupport::TaggedLogging::Formatter#current_tags
963 (0.8%) 963 (0.8%) MonitorMixin#mon_enter
960 (0.8%) 960 (0.8%) Set#include?
929 (0.8%) 929 (0.8%) ActiveRecord::Base.logger
921 (0.8%) 921 (0.8%) #<Module:0x000055e69f38da70>.encode_www_form_component
1493 (1.3%) 870 (0.8%) ActiveModel::Attribute#hash
1551 (1.4%) 858 (0.7%) ActiveSupport::TaggedLogging::Formatter#tags_text
1607 (1.4%) 811 (0.7%) Rails::Rack::Logger#started_request_message
786 (0.7%) 786 (0.7%) ActiveSupport::SafeBuffer#html_safe?
18279 (15.9%) 779 (0.7%) Logger#add
779 (0.7%) 779 (0.7%) ActiveSupport::ToJsonWithActiveSupportEncoder#to_json
763 (0.7%) 763 (0.7%) String#blank?
757 (0.7%) 757 (0.7%) ActionDispatch::Response#parse_content_type
$ RUBYOPT="--jit-verbose=1 -v" PROFILE=wall INTERVAL=100 WARMUP=50000 BENCHMARK=10000 bin/bench
ruby 2.7.0dev (2019-03-17 trunk 67281) +JIT [x86_64-linux]
JIT success (41.6ms): block in remove_unresolved_default_spec@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/2.7.0/rubygems.rb:1292 -> /tmp/_ruby_mjit_p5340u0.c
/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/bootsnap-1.4.1/lib/bootsnap/compile_cache/yaml.rb:48: warning: method redefined; discarding old load_file
/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/2.7.0/psych.rb:576: warning: previous definition of load_file was here
JIT success (111.1ms): canonical_segments@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/2.7.0/rubygems/version.rb:370 -> /tmp/_ruby_mjit_p5340u1.c
JIT success (109.1ms): _segments@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/2.7.0/rubygems/version.rb:383 -> /tmp/_ruby_mjit_p5340u5.c
JIT success (83.3ms): block (2 levels) in initialize@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/bootsnap-1.4.1/lib/bootsnap/load_path_cache/loaded_features_index.rb:36 -> /tmp/_ruby_mjit_p5340u6.c
JIT success (87.1ms): block in tsort_each_child@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/railties-5.2.2.1/lib/rails/initializable.rb:50 -> /tmp/_ruby_mjit_p5340u7.c
JIT success (28.1ms): before@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/railties-5.2.2.1/lib/rails/initializable.rb:19 -> /tmp/_ruby_mjit_p5340u8.c
/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activerecord-5.2.2.1/lib/active_record/statement_cache.rb:90: warning: tried to create Proc object without a block
JIT success (33.1ms): after@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/railties-5.2.2.1/lib/rails/initializable.rb:23 -> /tmp/_ruby_mjit_p5340u9.c
Warmup: 120/50000JIT success (146.3ms): ==@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/2.7.0/rubygems/dependency.rb:173 -> /tmp/_ruby_mjit_p5340u2.c
Warmup: 214/50000JIT success (109.4ms): ==@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/2.7.0/bundler/dep_proxy.rb:16 -> /tmp/_ruby_mjit_p5340u3.c
Warmup: 240/50000JIT success (32.1ms): get_header@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/rack-2.0.6/lib/rack/request.rb:52 -> /tmp/_ruby_mjit_p5340u10.c
Warmup: 266/50000JIT success (32.5ms): []@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/concurrent-ruby-1.1.5/lib/concurrent/collection/map/non_concurrent_map_backend.rb:19 -> /tmp/_ruby_mjit_p5340u11.c
Warmup: 1027/50000JIT success (888.4ms): []@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/concurrent-ruby-1.1.5/lib/concurrent/map.rb:132 -> /tmp/_ruby_mjit_p5340u12.c
Warmup: 1049/50000JIT success (32.0ms): include?@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/2.7.0/set.rb:253 -> /tmp/_ruby_mjit_p5340u13.c
Warmup: 1144/50000JIT success (108.0ms): instance@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/per_thread_registry.rb:46 -> /tmp/_ruby_mjit_p5340u14.c
Warmup: 1176/50000JIT success (50.5ms): block in initialize@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/ordered_options.rb:73 -> /tmp/_ruby_mjit_p5340u15.c
Warmup: 1213/50000JIT success (54.0ms): block in xor_byte_strings@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/actionpack-5.2.2.1/lib/action_controller/metal/request_forgery_protection.rb:405 -> /tmp/_ruby_mjit_p5340u17.c
Warmup: 1228/50000JIT success (29.3ms): block (4 levels) in class_attribute@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/core_ext/class/attribute.rb:106 -> /tmp/_ruby_mjit_p5340u16.c
Warmup: 1271/50000JIT success (70.4ms): html_safe?@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/core_ext/string/output_safety.rb:210 -> /tmp/_ruby_mjit_p5340u18.c
Warmup: 1380/50000JIT success (141.3ms): mon_check_owner@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/2.7.0/monitor.rb:267 -> /tmp/_ruby_mjit_p5340u19.c
Warmup: 1443/50000JIT success (95.2ms): mon_exit@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/2.7.0/monitor.rb:199 -> /tmp/_ruby_mjit_p5340u20.c
Warmup: 1692/50000JIT success (320.0ms): mon_synchronize@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/2.7.0/monitor.rb:227 -> /tmp/_ruby_mjit_p5340u21.c
Warmup: 1816/50000JIT success (152.4ms): mon_enter@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/2.7.0/monitor.rb:187 -> /tmp/_ruby_mjit_p5340u22.c
Warmup: 1882/50000JIT success (86.3ms): convert_key@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/hash_with_indifferent_access.rb:349 -> /tmp/_ruby_mjit_p5340u23.c
Warmup: 1901/50000JIT success (25.6ms): html_safe?@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/core_ext/string/output_safety.rb:123 -> /tmp/_ruby_mjit_p5340u24.c
Warmup: 1939/50000JIT success (80.4ms): block (2 levels) in class_attribute@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/core_ext/class/attribute.rb:124 -> /tmp/_ruby_mjit_p5340u25.c
Warmup: 1974/50000JIT success (43.5ms): block in symbolize_keys!@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/core_ext/hash/keys.rb:64 -> /tmp/_ruby_mjit_p5340u26.c
Warmup: 2049/50000JIT success (115.5ms): block in forwarded_scheme@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/rack-2.0.6/lib/rack/request.rb:489 -> /tmp/_ruby_mjit_p5340u27.c
Warmup: 2173/50000JIT success (192.7ms): unwrapped_html_escape@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/core_ext/string/output_safety.rb:34 -> /tmp/_ruby_mjit_p5340u28.c
Warmup: 2261/50000JIT success (115.1ms): tidy_bytes@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/multibyte/unicode.rb:226 -> /tmp/_ruby_mjit_p5340u29.c
Warmup: 2907/50000JIT success (785.2ms): initialize@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/core_ext/string/output_safety.rb:172 -> /tmp/_ruby_mjit_p5340u30.c
Warmup: 3036/50000JIT success (151.1ms): connection_specification_name@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activerecord-5.2.2.1/lib/active_record/connection_handling.rb:96 -> /tmp/_ruby_mjit_p5340u31.c
Warmup: 3063/50000JIT success (40.4ms): block in view_assigns@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/actionpack-5.2.2.1/lib/abstract_controller/rendering.rb:68 -> /tmp/_ruby_mjit_p5340u32.c
Warmup: 3097/50000JIT success (45.2ms): present?@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/core_ext/object/blank.rb:26 -> /tmp/_ruby_mjit_p5340u33.c
MJIT warning: Skipped to compile unsupported instruction: getblockparamproxy
JIT failure (0.0ms): fetch_header@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/rack-2.0.6/lib/rack/request.rb:58 -> /tmp/_ruby_mjit_p5340u34.c
Warmup: 3130/50000JIT success (48.8ms): logger@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/configurable.rb:23 -> /tmp/_ruby_mjit_p5340u35.c
Warmup: 3197/50000JIT success (104.3ms): safe_concat@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/core_ext/string/output_safety.rb:167 -> /tmp/_ruby_mjit_p5340u36.c
Warmup: 3334/50000JIT success (190.7ms): config@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/configurable.rb:30 -> /tmp/_ruby_mjit_p5340u37.c
Warmup: 3394/50000JIT success (91.6ms): event_stack@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/subscriber.rb:106 -> /tmp/_ruby_mjit_p5340u38.c
Warmup: 3425/50000JIT success (65.6ms): get_queue@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/subscriber.rb:126 -> /tmp/_ruby_mjit_p5340u39.c
Warmup: 3509/50000JIT success (141.1ms): listeners_for@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/notifications/fanout.rb:55 -> /tmp/_ruby_mjit_p5340u40.c
Warmup: 3678/50000JIT success (231.4ms): convert_value@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/hash_with_indifferent_access.rb:353 -> /tmp/_ruby_mjit_p5340u41.c
Warmup: 3894/50000JIT success (260.6ms): block in tag_options@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/actionview-5.2.2.1/lib/action_view/helpers/tag_helper.rb:63 -> /tmp/_ruby_mjit_p5340u42.c
Warmup: 4025/50000JIT success (172.9ms): tag_option@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/actionview-5.2.2.1/lib/action_view/helpers/tag_helper.rb:87 -> /tmp/_ruby_mjit_p5340u43.c
Warmup: 4085/50000JIT success (86.2ms): html_safe@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/core_ext/string/output_safety.rb:255 -> /tmp/_ruby_mjit_p5340u44.c
Warmup: 4784/50000JIT success (859.4ms): []=@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/rack-2.0.6/lib/rack/utils.rb:468 -> /tmp/_ruby_mjit_p5340u45.c
Warmup: 4854/50000JIT success (87.1ms): path_info@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/rack-2.0.6/lib/rack/request.rb:132 -> /tmp/_ruby_mjit_p5340u47.c
Warmup: 4931/50000JIT success (93.1ms): logger@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/actionpack-5.2.2.1/lib/action_controller/log_subscriber.rb:72 -> /tmp/_ruby_mjit_p5340u49.c
Warmup: 5581/50000JIT success (793.2ms): <<@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/actionview-5.2.2.1/lib/action_view/buffers.rb:12 -> /tmp/_ruby_mjit_p5340u51.c
Warmup: 5620/50000JIT success (48.8ms): logger@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/configurable.rb:115 -> /tmp/_ruby_mjit_p5340u50.c
Warmup: 5881/50000JIT success (348.2ms): __getobj__@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/2.7.0/delegate.rb:392 -> /tmp/_ruby_mjit_p5340u46.c
Warmup: 5900/50000JIT success (24.1ms): loaded?@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/actionpack-5.2.2.1/lib/action_dispatch/request/session.rb:192 -> /tmp/_ruby_mjit_p5340u48.c
Warmup: 5921/50000JIT success (31.5ms): set_header@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/rack-2.0.6/lib/rack/request.rb:68 -> /tmp/_ruby_mjit_p5340u52.c
Warmup: 6564/50000JIT success (795.3ms): level@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/logger_thread_safe_level.rb:29 -> /tmp/_ruby_mjit_p5340u53.c
Warmup: 6607/50000JIT success (49.9ms): local_level@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/logger_thread_safe_level.rb:17 -> /tmp/_ruby_mjit_p5340u54.c
Warmup: 6668/50000JIT success (81.7ms): local_log_id@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/logger_thread_safe_level.rb:13 -> /tmp/_ruby_mjit_p5340u55.c
Warmup: 7264/50000JIT success (779.6ms): initialize@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/actionpack-5.2.2.1/lib/action_dispatch/http/request.rb:59 -> /tmp/_ruby_mjit_p5340u56.c
Warmup: 7885/50000JIT success (759.4ms): initialize@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/rack-2.0.6/lib/rack/request.rb:40 -> /tmp/_ruby_mjit_p5340u57.c
Warmup: 8513/50000JIT success (769.3ms): initialize@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/actionpack-5.2.2.1/lib/action_dispatch/http/url.rb:186 -> /tmp/_ruby_mjit_p5340u58.c
Warmup: 9139/50000JIT success (759.2ms): initialize@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/actionpack-5.2.2.1/lib/action_dispatch/http/filter_parameters.rb:34 -> /tmp/_ruby_mjit_p5340u59.c
Warmup: 9238/50000JIT success (123.6ms): current_tags@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/tagged_logging.rb:47 -> /tmp/_ruby_mjit_p5340u60.c
Warmup: 9899/50000JIT success (813.0ms): request_method@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/actionpack-5.2.2.1/lib/action_dispatch/http/request.rb:134 -> /tmp/_ruby_mjit_p5340u62.c
Warmup: 9987/50000JIT success (113.7ms): block in delegating_block@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/2.7.0/delegate.rb:347 -> /tmp/_ruby_mjit_p5340u61.c
Warmup: 10617/50000JIT success (770.6ms): concat@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/core_ext/string/output_safety.rb:186 -> /tmp/_ruby_mjit_p5340u63.c
Warmup: 10704/50000JIT success (109.5ms): html_escape_interpolated_argument@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/core_ext/string/output_safety.rb:243 -> /tmp/_ruby_mjit_p5340u64.c
Warmup: 10726/50000JIT success (29.4ms): block in initialize@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/rack-2.0.6/lib/rack/utils.rb:443 -> /tmp/_ruby_mjit_p5340u65.c
Warmup: 10810/50000JIT success (133.6ms): now@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/subscriber.rb:110 -> /tmp/_ruby_mjit_p5340u66.c
Warmup: 10838/50000JIT success (46.8ms): presence@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/core_ext/object/blank.rb:46 -> /tmp/_ruby_mjit_p5340u67.c
Warmup: 11464/50000JIT success (795.7ms): default@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/hash_with_indifferent_access.rb:206 -> /tmp/_ruby_mjit_p5340u69.c
Warmup: 11529/50000JIT success (88.3ms): script_name@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/rack-2.0.6/lib/rack/request.rb:129 -> /tmp/_ruby_mjit_p5340u68.c
Warmup: 11545/50000JIT success (27.9ms): to_s@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/core_ext/string/output_safety.rb:214 -> /tmp/_ruby_mjit_p5340u70.c
Warmup: 11694/50000JIT success (240.8ms): scheme@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/rack-2.0.6/lib/rack/request.rb:188 -> /tmp/_ruby_mjit_p5340u71.c
Warmup: 11838/50000JIT success (207.4ms): forwarded_scheme@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/rack-2.0.6/lib/rack/request.rb:483 -> /tmp/_ruby_mjit_p5340u72.c
Warmup: 12735/50000JIT success (1092.5ms): to_s@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/core_ext/numeric/conversions.rb:104 -> /tmp/_ruby_mjit_p5340u73.c
Warmup: 12790/50000JIT success (75.4ms): value@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activemodel-5.2.2.1/lib/active_model/attribute.rb:40 -> /tmp/_ruby_mjit_p5340u74.c
Warmup: 13479/50000JIT success (861.8ms): add@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/logger.rb:87 -> /tmp/_ruby_mjit_p5340u75.c
Warmup: 13848/50000JIT success (455.4ms): add@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/2.7.0/logger.rb:455 -> /tmp/_ruby_mjit_p5340u76.c
Warmup: 13913/50000JIT success (84.2ms): config@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/configurable.rb:146 -> /tmp/_ruby_mjit_p5340u90.c
Warmup: 13965/50000JIT success (71.3ms): format_severity@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/2.7.0/logger.rb:577 -> /tmp/_ruby_mjit_p5340u77.c
Warmup: 14059/50000JIT success (132.1ms): lookup_context@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/actionview-5.2.2.1/lib/action_view/view_paths.rb:40 -> /tmp/_ruby_mjit_p5340u89.c
Warmup: 14098/50000JIT success (62.5ms): format_message@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/2.7.0/logger.rb:581 -> /tmp/_ruby_mjit_p5340u78.c
Warmup: 14753/50000JIT success (827.8ms): call@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/tagged_logging.rb:22 -> /tmp/_ruby_mjit_p5340u79.c
Warmup: 14849/50000JIT success (125.3ms): tags_text@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/tagged_logging.rb:53 -> /tmp/_ruby_mjit_p5340u80.c
Warmup: 14879/50000JIT success (42.3ms): block in tags_text@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/tagged_logging.rb:56 -> /tmp/_ruby_mjit_p5340u81.c
Warmup: 14965/50000JIT success (135.2ms): call@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/2.7.0/logger.rb:596 -> /tmp/_ruby_mjit_p5340u82.c
Warmup: 14994/50000JIT success (53.7ms): format_datetime@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/2.7.0/logger.rb:603 -> /tmp/_ruby_mjit_p5340u83.c
Warmup: 15067/50000JIT success (120.6ms): msg2str@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/2.7.0/logger.rb:607 -> /tmp/_ruby_mjit_p5340u84.c
Warmup: 15124/50000JIT success (105.0ms): write@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/2.7.0/logger.rb:684 -> /tmp/_ruby_mjit_p5340u85.c
Warmup: 15164/50000JIT success (61.1ms): block in write@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/2.7.0/logger.rb:686 -> /tmp/_ruby_mjit_p5340u86.c
Warmup: 15221/50000JIT success (95.7ms): committed?@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/actionpack-5.2.2.1/lib/action_dispatch/http/response.rb:219 -> /tmp/_ruby_mjit_p5340u87.c
Warmup: 15240/50000JIT success (29.2ms): block in committed?@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/actionpack-5.2.2.1/lib/action_dispatch/http/response.rb:219 -> /tmp/_ruby_mjit_p5340u88.c
Warmup: 15286/50000JIT success (90.2ms): load_for_read!@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/actionpack-5.2.2.1/lib/action_dispatch/request/session.rb:212 -> /tmp/_ruby_mjit_p5340u91.c
Warmup: 15323/50000JIT success (54.3ms): get_header@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/actionpack-5.2.2.1/lib/action_dispatch/http/response.rb:181 -> /tmp/_ruby_mjit_p5340u93.c
Warmup: 15357/50000JIT success (69.3ms): block in extract!@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/core_ext/hash/slice.rb:46 -> /tmp/_ruby_mjit_p5340u92.c
Warmup: 15386/50000JIT success (44.4ms): []@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/actionpack-5.2.2.1/lib/action_dispatch/request/session.rb:48 -> /tmp/_ruby_mjit_p5340u94.c
Warmup: 15420/50000JIT success (53.0ms): get_or_default@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/concurrent-ruby-1.1.5/lib/concurrent/collection/map/non_concurrent_map_backend.rb:108 -> /tmp/_ruby_mjit_p5340u95.c
Warmup: 15768/50000JIT success (484.5ms): fetch@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/concurrent-ruby-1.1.5/lib/concurrent/map.rb:168 -> /tmp/_ruby_mjit_p5340u96.c
Warmup: 15825/50000JIT success (82.2ms): blank?@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/core_ext/object/blank.rb:122 -> /tmp/_ruby_mjit_p5340u97.c
Warmup: 15895/50000JIT success (98.1ms): owner_to_pool@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:1054 -> /tmp/_ruby_mjit_p5340u98.c
Warmup: 15969/50000JIT success (109.8ms): connection_handler@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activerecord-5.2.2.1/lib/active_record/core.rb:130 -> /tmp/_ruby_mjit_p5340u99.c
Warmup: 16008/50000JIT success (53.1ms): connection_handler@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activerecord-5.2.2.1/lib/active_record/runtime_registry.rb:20 -> /tmp/_ruby_mjit_p5340u100.c
Warmup: 16037/50000JIT success (55.0ms): start@/home/k0kubun/.rbenv/versions/ruby-svn/lib/ruby/gems/2.7.0/gems/activesupport-5.2.2.1/lib/active_support/notifications/instrumenter.rb:34 -> /tmp/_ruby_mjit_p5340u101.c
Warmup: 16051/50000JIT compaction (23.7ms): Compacted 100 methods -> /tmp/_ruby_mjit_p5340u990.so
Warmup: 50000 requests
Benchmarking 10000 requests...
Request per second: 818.3 [#/s] (mean)
Successful MJIT finish
/home/k0kubun/src/github.com/k0kubun/railsbench † bionic status: 0 (git)-[master]-
$ stackprof stackprof-2019-03-17_17:51:33_+0900.dump
==================================
Mode: wall(100)
Samples: 121143 (0.61% miss rate)
GC: 5436 (4.49%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
5890 (4.9%) 5890 (4.9%) Concurrent::Collection::NonConcurrentMapBackend#[]
5436 (4.5%) 5436 (4.5%) (garbage collection)
3903 (3.2%) 3903 (3.2%) Logger::Formatter#format_datetime
4990 (4.1%) 3556 (2.9%) Logger::LogDevice#write
3307 (2.7%) 3307 (2.7%) Rack::Request::Env#get_header
2384 (2.0%) 2384 (2.0%) ActiveSupport::SafeBuffer#initialize
6335 (5.2%) 1773 (1.5%) Logger::Formatter#call
2330 (1.9%) 1619 (1.3%) block (2 levels) in class_attribute
1444 (1.2%) 1444 (1.2%) block (4 levels) in class_attribute
1949 (1.6%) 1261 (1.0%) ActionView::Helpers::TagHelper::TagBuilder#tag_option
1254 (1.0%) 1254 (1.0%) ActiveSupport::PerThreadRegistry#instance
1231 (1.0%) 1231 (1.0%) ActionDispatch::Http::FilterParameters#initialize
1226 (1.0%) 1226 (1.0%) Rack::Utils::HeaderHash#[]=
1219 (1.0%) 1219 (1.0%) Rack::Request::Env#fetch_header
1188 (1.0%) 1188 (1.0%) ActiveSupport::InheritableOptions#initialize
1187 (1.0%) 1187 (1.0%) ActiveSupport::Configurable::ClassMethods#config
1131 (0.9%) 1131 (0.9%) MonitorMixin#mon_enter
1264 (1.0%) 984 (0.8%) ActionView::LogSubscriber#from_rails_root
953 (0.8%) 953 (0.8%) ActionDispatch::Response#parse_content_type
944 (0.8%) 944 (0.8%) #<Module:0x0000561544a19168>.encode_www_form_component
18841 (15.6%) 933 (0.8%) Logger#add
908 (0.7%) 908 (0.7%) ActiveSupport::TaggedLogging::Formatter#current_tags
900 (0.7%) 900 (0.7%) Set#include?
889 (0.7%) 889 (0.7%) ActiveModel::Attribute#initialize
1503 (1.2%) 865 (0.7%) ActiveSupport::TaggedLogging::Formatter#tags_text
840 (0.7%) 840 (0.7%) ActiveSupport::HashWithIndifferentAccess#convert_key
1471 (1.2%) 832 (0.7%) ActiveModel::Attribute#hash
830 (0.7%) 830 (0.7%) #<Class:0x0000561545c7a578>#__getobj__
828 (0.7%) 828 (0.7%) ActiveRecord::Base.logger
781 (0.6%) 781 (0.6%) MonitorMixin#mon_enter
MIT License