Benchmark ORM on Truffleruby vs CRuby perfromance problem

[AlexeyMatskevich]

I was inspired by the article and decided to reproduce the tests for ActiveRecord and ORM in the spirit of Shopify benchmark.

In the results of the article from 2022, the results were as follows

I've created a repository where I defined Dockerfile for ruby and for truffleruby.

And create test inspired by a version from Shopify benchmark but replaced sqlite with postgres.

To customize truffleruby, I have been studying your documentation and followed the next steps:

1. Use Oracle GraalVM instead of Community Edition version
2. Use the Latest Release 24.0.1
3. Use the Correct Runtime Configuration - JVM configuration (install JVM version)
4. Disabling the Global C-Extension Lock
5. Run with Enough Warmup

I end up with the following results:
For MRI 3.3.1

                 user     system      total        real
ActiveRecord:  8.095543   0.786087   8.881630 ( 10.745872)

For Truffleruby 24.0.1-JVM (I've tried running benchmark 10 times to test within a single run to check for warmup)

                 user     system      total        real
ActiveRecord 0: 23.492176   1.226223  24.718399 ( 20.238396)
ActiveRecord 1: 19.394902   1.204641  20.599543 ( 20.041559)
ActiveRecord 2: 19.457829   1.269488  20.727317 ( 19.964144)
ActiveRecord 3: 19.282167   1.163987  20.446154 ( 20.192037)
ActiveRecord 4: 18.421440   1.026265  19.447705 ( 19.845829)
ActiveRecord 5: 18.538499   1.024583  19.563082 ( 19.866452)
ActiveRecord 6: 18.313226   1.094071  19.407297 ( 19.839851)
ActiveRecord 7: 18.565056   1.097710  19.662766 ( 19.882381)
ActiveRecord 8: 18.382542   1.079965  19.462507 ( 19.820898)
ActiveRecord 9: 18.484171   1.083560  19.567731 ( 19.841563)

My system:
NixOS 24.05
Docker version 24.0.9, build v24.0.9
AMD 5950x
128 GB RAM
SSD - intel 905p 1.5 TB

I believe I am doing something wrong that is causing me to get these results, can I get some help with this issue?

[eregon]

Thanks for the report.
It might be helpful to run with sqlite3 to see if that gives numbers close to then.

From your output, where does the number in ActiveRecord 0:, ActiveRecord 1: come from?
I don't see anything that would produce that in https://github.com/AlexeyMatskevich/ruby-orm-benchmark/blob/993ac09aa01fdd0ebb133896e804c3de85efa952/activerecord_truffleruby/benchmark.rb#L53
I also don't see how that code would do 10 measurements (the 10 in Benchmark.bm(10) is just label width, not running things multiple times).
https://github.com/AlexeyMatskevich/ruby-orm-benchmark/blob/993ac09aa01fdd0ebb133896e804c3de85efa952/activerecord_truffleruby/benchmark.rb#L36 does seem to do 30 runs.
Could you post the full output of the run?

[AlexeyMatskevich]

Hi @eregon , I tidied up my examples, and made for all cases where there is a JIT (YJIT or truffleruby) run 30 times during the measurements to see how the execution speed changes. I also added the sqlite version as you suggested and removed the TRUFFLERUBYOPT flag and replaced it with --jvt, here are my results:

1. sqlite

• MRI 3.3.1

                   user     system      total        real
  ActiveRecord sqlite:  6.551442   0.003009   6.554451 (  6.579821)

• MRI 3.3.1 YJIT

                   user     system      total        real
  ActiveRecord YJIT sqlite 0:  2.796044   0.019908   2.815952 (  2.826951)
  ActiveRecord YJIT sqlite 1:  2.756513   0.005015   2.761528 (  2.771209)
  ActiveRecord YJIT sqlite 2:  2.750212   0.003044   2.753256 (  2.763012)
  ActiveRecord YJIT sqlite 3:  2.809360   0.000051   2.809411 (  2.820196)
  ActiveRecord YJIT sqlite 4:  2.783551   0.005997   2.789548 (  2.799685)
  ActiveRecord YJIT sqlite 5:  2.750770   0.007013   2.757783 (  2.767343)
  ActiveRecord YJIT sqlite 6:  2.747675   0.005005   2.752680 (  2.762096)
  ActiveRecord YJIT sqlite 7:  2.749930   0.003984   2.753914 (  2.763372)
  ActiveRecord YJIT sqlite 8:  2.744712   0.005001   2.749713 (  2.759194)
  ActiveRecord YJIT sqlite 9:  2.746885   0.003009   2.749894 (  2.759344)
  ActiveRecord YJIT sqlite 10:  2.779910   0.004976   2.784886 (  2.795253)
  ActiveRecord YJIT sqlite 11:  2.765167   0.004993   2.770160 (  2.780082)
  ActiveRecord YJIT sqlite 12:  2.754309   0.008979   2.763288 (  2.773221)
  ActiveRecord YJIT sqlite 13:  2.879413   0.000995   2.880408 (  2.891538)
  ActiveRecord YJIT sqlite 14:  2.976994   0.004995   2.981989 (  2.993393)
  ActiveRecord YJIT sqlite 15:  3.003423   0.001992   3.005415 (  3.017621)
  ActiveRecord YJIT sqlite 16:  2.960940   0.003990   2.964930 (  2.976004)
  ActiveRecord YJIT sqlite 17:  2.969719   0.002002   2.971721 (  2.983353)
  ActiveRecord YJIT sqlite 18:  2.948430   0.002995   2.951425 (  2.962161)
  ActiveRecord YJIT sqlite 19:  2.951417   0.003991   2.955408 (  2.966119)
  ActiveRecord YJIT sqlite 20:  2.920427   0.001991   2.922418 (  2.933821)
  ActiveRecord YJIT sqlite 21:  2.903476   0.004983   2.908459 (  2.918869)
  ActiveRecord YJIT sqlite 22:  2.764103   0.006978   2.771081 (  2.780912)
  ActiveRecord YJIT sqlite 23:  2.757982   0.000997   2.758979 (  2.768787)
  ActiveRecord YJIT sqlite 24:  2.743710   0.002994   2.746704 (  2.756160)
  ActiveRecord YJIT sqlite 25:  2.812459   0.002985   2.815444 (  2.825411)
  ActiveRecord YJIT sqlite 26:  2.863648   0.003986   2.867634 (  2.877905)
  ActiveRecord YJIT sqlite 27:  2.919676   0.001001   2.920677 (  2.931196)
  ActiveRecord YJIT sqlite 28:  2.934392   0.009964   2.944356 (  2.955091)
  ActiveRecord YJIT sqlite 29:  2.926114   0.002986   2.929100 (  2.939524)

• Truffleruby-JVM 24.0.1

                       user     system      total        real
  ActiveRecord truffleruby sqlite 0: 80.609847   1.629485  82.239332 (  7.301696)
  ActiveRecord truffleruby sqlite 1: 25.992300   0.511173  26.503473 (  3.934268)
  ActiveRecord truffleruby sqlite 2:  6.342972   0.092789   6.435761 (  3.674677)
  ActiveRecord truffleruby sqlite 3:  3.747358   0.027036   3.774394 (  3.622449)
  ActiveRecord truffleruby sqlite 4:  3.710655   0.053433   3.764088 (  3.658411)
  ActiveRecord truffleruby sqlite 5:  3.714152   0.064390   3.778542 (  3.597596)
  ActiveRecord truffleruby sqlite 6:  3.758769   0.031185   3.789954 (  3.608972)
  ActiveRecord truffleruby sqlite 7:  4.318399   0.117433   4.435832 (  3.592337)
  ActiveRecord truffleruby sqlite 8:  3.549380   0.009302   3.558682 (  3.535733)
  ActiveRecord truffleruby sqlite 9:  3.657236   0.040960   3.698196 (  3.611520)
  ActiveRecord truffleruby sqlite 10:  3.820298   0.022546   3.842844 (  3.715115)
  ActiveRecord truffleruby sqlite 11:  3.946100   0.063571   4.009671 (  3.588842)
  ActiveRecord truffleruby sqlite 12:  3.907324   0.033441   3.940765 (  3.593855)
  ActiveRecord truffleruby sqlite 13:  4.000013   0.021414   4.021427 (  3.599289)
  ActiveRecord truffleruby sqlite 14:  3.680991   0.001282   3.682273 (  3.606944)
  ActiveRecord truffleruby sqlite 15:  3.789138   0.005904   3.795042 (  3.694431)
  ActiveRecord truffleruby sqlite 16:  3.655121   0.015047   3.670168 (  3.642124)
  ActiveRecord truffleruby sqlite 17:  3.661154   0.016717   3.677871 (  3.659822)
  ActiveRecord truffleruby sqlite 18:  3.560600   0.027222   3.587822 (  3.578228)
  ActiveRecord truffleruby sqlite 19:  3.544671   0.002114   3.546785 (  3.545028)
  ActiveRecord truffleruby sqlite 20:  3.555212   0.002767   3.557979 (  3.551740)
  ActiveRecord truffleruby sqlite 21:  3.589249   0.003830   3.593079 (  3.585985)
  ActiveRecord truffleruby sqlite 22:  3.553823   0.005884   3.559707 (  3.554729)
  ActiveRecord truffleruby sqlite 23:  3.802055   0.059895   3.861950 (  3.608615)
  ActiveRecord truffleruby sqlite 24:  3.948730   0.060110   4.008840 (  3.562451)
  ActiveRecord truffleruby sqlite 25:  3.793893   0.030030   3.823923 (  3.606609)
  ActiveRecord truffleruby sqlite 26:  3.775485   0.010473   3.785958 (  3.597859)
  ActiveRecord truffleruby sqlite 27:  3.825302   0.017923   3.843225 (  3.597168)
  ActiveRecord truffleruby sqlite 28:  3.646626   0.017574   3.664200 (  3.595037)
  ActiveRecord truffleruby sqlite 29:  3.704118   0.007050   3.711168 (  3.584320)

2. postgres

• MRI 3.3.1

                       user     system      total        real
  ActiveRecord postgres:  8.349865   0.893011   9.242876 ( 11.197822)

• Truffleruby-JVM 24.0.1

                       user     system      total        real
  ActiveRecord truffleruby postgres 0:141.260251   3.852272 145.112523 ( 23.477568)
  ActiveRecord truffleruby postgres 1: 19.959210   1.097211  21.056421 ( 20.775617)
  ActiveRecord truffleruby postgres 2: 20.436062   1.094602  21.530664 ( 20.726903)
  ActiveRecord truffleruby postgres 3: 18.760096   0.982179  19.742275 ( 20.414279)
  ActiveRecord truffleruby postgres 4: 18.816556   0.940958  19.757514 ( 20.640142)
  ActiveRecord truffleruby postgres 5: 19.168734   0.982705  20.151439 ( 21.005674)
  ActiveRecord truffleruby postgres 6: 18.962551   1.013158  19.975709 ( 20.770934)
  ActiveRecord truffleruby postgres 7: 19.423208   1.089924  20.513132 ( 20.506810)
  ActiveRecord truffleruby postgres 8: 18.807747   0.995719  19.803466 ( 20.678445)
  ActiveRecord truffleruby postgres 9: 18.633941   0.959020  19.592961 ( 20.417587)
  ActiveRecord truffleruby postgres 10: 18.896460   0.990395  19.886855 ( 20.376277)
  ActiveRecord truffleruby postgres 11: 18.976280   1.113067  20.089347 ( 20.362866)
  ActiveRecord truffleruby postgres 12: 19.417751   1.130830  20.548581 ( 21.050883)
  ActiveRecord truffleruby postgres 13: 19.228303   1.083680  20.311983 ( 20.606263)
  ActiveRecord truffleruby postgres 14: 19.032978   1.080656  20.113634 ( 20.825480)
  ActiveRecord truffleruby postgres 15: 18.744966   0.969025  19.713991 ( 20.710741)
  ActiveRecord truffleruby postgres 16: 18.640492   1.075623  19.716115 ( 20.604810)
  ActiveRecord truffleruby postgres 17: 18.464173   1.091171  19.555344 ( 20.346136)
  ActiveRecord truffleruby postgres 18: 18.173570   1.159790  19.333360 ( 20.211893)
  ActiveRecord truffleruby postgres 19: 18.273660   1.238172  19.511832 ( 20.264353)
  ActiveRecord truffleruby postgres 20: 18.202484   1.109144  19.311628 ( 20.076461)
  ActiveRecord truffleruby postgres 21: 18.281282   1.223475  19.504757 ( 20.108086)
  ActiveRecord truffleruby postgres 22: 18.263482   1.083066  19.346548 ( 20.114387)
  ActiveRecord truffleruby postgres 23: 18.758474   1.179018  19.937492 ( 20.418387)
  ActiveRecord truffleruby postgres 24: 19.000586   1.198470  20.199056 ( 20.375268)
  ActiveRecord truffleruby postgres 25: 18.891088   1.263628  20.154716 ( 20.361767)
  ActiveRecord truffleruby postgres 26: 18.806537   1.224570  20.031107 ( 20.374270)
  ActiveRecord truffleruby postgres 27: 18.833047   1.207035  20.040082 ( 20.298596)
  ActiveRecord truffleruby postgres 28: 18.490631   1.182860  19.673491 ( 20.161590)
  ActiveRecord truffleruby postgres 29: 18.710398   1.178700  19.889098 ( 20.203460)

So far, it turns out that when using Sqlite, truffleruby outperforms MRI by a factor of two, but does not outperform MRI YJIT. In case of using postgres, truffleruby lags behind more than twice after warming up.

Does this look normal or am I missing/doing something wrong?

[eregon]

Those results do look like there is enough warmup, so I think the benchmarking itself is fine.
The results also seem somewhat credible, YJIT got better in Ruby 3.3 (compared to 3.1 YJIT) and this benchmark has some differences.
Also TruffleRuby changes how it runs C extensions and sometimes it's slower.

One thing though is it's not ideal to benchmark in Docker, but it should in theory affect CRuby & TruffleRuby the same, but maybe not in practice.
Are you running this with a Linux or macOS machine?
We will try to reproduce your results when we get some time, the sqlite3 ones should be easy to repro.

It might be worth a try to disable the C extension lock, that might speed things up a bit. It's also something that could be improved in TruffleRuby.
Also we are planning to use Panama for C extensions soon, see more about that in https://eregon.me/blog/assets/research/from-interpreting-c-extensions-to-compiling-them.pdf

[AlexeyMatskevich]

@eregon thank you very much for your reply! About my system:

OS: Linux distro NixOS 24.05 - Kernel 6.6.32
Docker version 24.0.9, build v24.0.9
Hardware: AMD 5950x +128 GB RAM, system disk - SSD intel 905p (standart ext 4)

I gave up testing on mac os, due to its aggressive compression of RAM to disk, as described in your documentation. I also tried testing on Windows wsl2 docker (Ubuntu 24.04) and got the same performance ratios, only on WSL2 everything is one and a half times slower (just a fun fact).

[AlexeyMatskevich]

I tried a lock with the C extension, the difference is at the margin of error.

[eregon]

FYI @nirvdrum was trying to run the benchmarks but encountered an issue: #3590
The issue seems specific to running in Docker/the OS used in Docker somehow.

[eregon]

Recently I ran yjit-bench's activerecord benchmark (which uses sqlite3), on JVM EE from the last GFTC dev build:
550ms / iteration without Panama, 175ms / iteration with Panama, approximately 3.14 times faster!
Panama is a faster way to support C extensions, enabled via --cexts-panama.
It's not default yet as it needs some more fixes to be fully compatible, but should be default soon.