How to git bisect ruby/ruby repository

how_to_bisect_ruby_ruby.md

How to git bisect ruby/ruby repository

This document explains how to find which commit of CRuby triggers regressions.

If you can reproduce it with simple Ruby script

If you have some simple Ruby script to reproduce regressions, Use rubyfarm-bisect to find which commit triggers it.

Steps to find which commit triggers failure

1. Find the commit hash of last successful and the first failed one.
2. If you just know the tags, find the commit hash corresponding to the tag.
3. Run rubyfarm-bisect -g <last successful commit hash> -b <first failed commit hash>

Example with Regexp#{match,match?} with a nil argument are deprecated and will raise a TypeError in Ruby 3.0

• Refer https://speakerdeck.com/koic/breaking-change?slide=20
• Ruby 2.7.0 preview 2 (v2_7_0_preview2 tag) commit hash is 02aadf1032d71a3f81653a955f2635c8853b0aca
• Ruby 2.7.0 preview 3 (v2_7_0_preview3 tag) commit hash is b563439274a402e33541f5695b1bfd4ac1085638

See each Ruby 2.7.0 preview 2 and preview 3 works

Ruby 2.7.0-preview2 raises TypeError

% docker run --rm -t rubylang/rubyfarm:02aadf1032d71a3f81653a955f2635c8853b0aca ruby -e 'p /re/.match?(nil)'

Traceback (most recent call last):
	1: from -e:1:in `<main>'
-e:1:in `match?': no implicit conversion of nil into String (TypeError)

Ruby 2.7.0-preview3 shows warning

% docker run --rm -t rubylang/rubyfarm:b563439274a402e33541f5695b1bfd4ac1085638 ruby -e 'p /re/.match?(nil)'
-e:1: warning: given argument is nil; this will raise a TypeError in the next release
false

Let's find which commit changes this behavior, from TypeError to warning

% gem install rubyfarm-bisect
% rubyfarm-bisect -g 02aadf1032d71a3f81653a955f2635c8853b0aca -b b563439274a402e33541f5695b1bfd4ac1085638  ruby -e 'p /re/.match?(nil)' # -g <v2_7_0_preview2> -b <v2_7_0_preview3> 

Result:

452bee3ee8d68059fabd9b1c7a75661b14e3933e is the first bad commit
commit 452bee3ee8d68059fabd9b1c7a75661b14e3933e
Author: Kenichi Kamiya <kachick1@gmail.com>
Date:   Sat Nov 2 00:54:36 2019 +0900

    Revert nil error and adding deprecation message

 re.c                                |  8 +++++++-
 spec/ruby/core/regexp/match_spec.rb | 20 ++++++++++++++++----
 test/ruby/test_regexp.rb            |  4 ++--
 3 files changed, 25 insertions(+), 7 deletions(-)
bisect run success
%

Rails framework

Here I'm talking about CI against Rails framework itself, not talking about Rails applications.

Rails uses minitest and CI runs at https://buildkite.com/rails/rails , which runs CI against Ruby versions 2.5, 2.6, 2.7 and 2.8.0dev. Sometimes only CI against Ruby 2.8.0dev fails. Here are the components/modules and why they fail:

Known failures with `2.8.0dev1

• guides(master) will be resolved once the next released version of Rails 6.0.3
• railties(master) will be resolved once the next version of sprockets-rails and sprockets are released
• actionview(master) and actionpack(master) failures need CRuby changes

Run Rails CI locally

Steps

• Here are steps how to run Rails (Action Pack) CI on your development environment with Docker.

% git clone https://github.com/rails/rails.git
% cd rails
% git clone https://github.com/rails/buildkite-config .buildkite/
% RUBY_IMAGE=rubylang/ruby:master-nightly-bionic docker-compose -f .buildkite/docker-compose.yml build base && CI=1 docker-compose -f .buildkite/docker-compose.yml run default runner actionpack 'rake test'

How to bisect steps with the actual example

1. Find the first failed failed build using 2.8.0dev - Build#68202

https://buildkite.com/rails/rails/builds/68202#ee7fdd62-d66b-48a1-a55f-af28a2bff287

2. Click "bundle env" to show the commit hash of Ruby used by Build#68202

Ruby          2.8.0p-1 (2020-04-13 revision f2c3848a5bf2bec0b27a6035c4b7399594c32509) [x86_64-linux]

3. Find the last successful build using 2.8.0dev - Build#68195

https://buildkite.com/rails/rails/builds/68195#7458f629-a61b-4827-9a75-1d8115f9428f

4. Click "bundle env" to show the commit hash of Ruby used by Build#68195

Ruby          2.8.0p-1 (2020-04-12 revision a01bda594996fdc247e183f107cada43e2c8e3b8) [x86_64-linux]

5. Create a minimum case using minitest_bisect

• It does not have to be minimum, as long as it always reproduce
• Refer https://gist.github.com/yahonda/b67b19304d34fc1150a9db79ee325bcc for detail
• Set PARALLEL_WORKERS=1 for Action View and Acton Pack to disable parallel testing.

6. Save the minimum steps to reproduce like actionview/rep.sh

• actionview/rep.sh

PARALLEL_WORKERS=1 bin/test test/actionpack/controller/render_test.rb --seed 53177 -n "/^(?:RenderTest#(?:test_render_call_to_partial_with_layout_in_main_layout_and_within_content_for_layout|test_nested_partial_with_form_builder))$/"

7. See if it reproduces the latest version of 2.8.0dev

% RUBY_IMAGE=rubylang/ruby:master-nightly-bionic docker-compose -f .buildkite/docker-compose.yml build base && CI=1 docker-compose -f .buildkite/docker-compose.yml run default runner actionview 'sh ./rep.sh'
... snip ...
# Running:

.E

Error:
RenderTest#test_nested_partial_with_form_builder:
ActionController::MissingExactTemplate: Fun::GamesController#nested_partial_with_form_builder is missing a template for request formats: text/html
    /rails/actionpack/lib/action_controller/metal/implicit_render.rb:45:in `default_render'
    /rails/actionpack/lib/action_controller/metal/basic_implicit_render.rb:6:in `block in send_action'
    /rails/actionpack/lib/action_controller/metal/basic_implicit_render.rb:6:in `tap'
    /rails/actionpack/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
    /rails/actionpack/lib/abstract_controller/base.rb:195:in `process_action'
    /rails/actionpack/lib/action_controller/metal/rendering.rb:30:in `process_action'
    /rails/actionpack/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
    /rails/activesupport/lib/active_support/callbacks.rb:98:in `run_callbacks'
    /rails/actionpack/lib/abstract_controller/callbacks.rb:41:in `process_action'
    /rails/actionpack/lib/action_controller/metal/rescue.rb:22:in `process_action'
    /rails/actionpack/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
    /rails/activesupport/lib/active_support/notifications.rb:203:in `block in instrument'
    /rails/activesupport/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
    /rails/activesupport/lib/active_support/notifications.rb:203:in `instrument'
    /rails/actionpack/lib/action_controller/metal/instrumentation.rb:33:in `process_action'
    /rails/actionpack/lib/action_controller/metal/params_wrapper.rb:245:in `process_action'
    /rails/actionpack/lib/abstract_controller/base.rb:136:in `process'
    /rails/actionview/lib/action_view/rendering.rb:39:in `process'
    /rails/actionpack/lib/action_controller/metal.rb:190:in `dispatch'
    /rails/actionpack/lib/action_controller/test_case.rb:517:in `process'
    /rails/actionpack/lib/action_controller/test_case.rb:395:in `get'
    /rails/actionview/test/actionpack/controller/render_test.rb:1346:in `test_nested_partial_with_form_builder'


bin/test test/actionpack/controller/render_test.rb:1344



Finished in 0.075085s, 26.6365 runs/s, 13.3182 assertions/s.
2 runs, 1 assertions, 0 failures, 1 errors, 0 skips
%

7. Which Docker image to use?

• Use rubylang/rubyfarm if you need to bisect with the commit hash tag
• Use rubylang/ruby:master-nightly-bionic if you just want to run the latest 2.8.0dev

8. Let's start git bisect

% git clone https://github.com/ruby/ruby.git
% cd ruby
% git bisect start
% git bisect good a01bda594996fdc247e183f107cada43e2c8e3b8 # The last successful Build#68195
% git bisect bad f2c3848a5bf2bec0b27a6035c4b7399594c32509 # The first failed Build#68202
Bisecting: 3 revisions left to test after this (roughly 2 steps)
[3825662d777ae406136fa7d720b60fe04c6eafd2] Set up environment variable for pager [Feature #16754]

9. See if 3825662d777ae406136fa7d720b60fe04c6eafd2 reproduces the error

• Script

RUBY_IMAGE=rubylang/rubyfarm:3825662d777ae406136fa7d720b60fe04c6eafd2 docker-compose -f .buildkite/docker-compose.yml build base && 
CI=1 docker-compose -f .buildkite/docker-compose.yml run default runner actionview 'sh ./rep.sh'

• Result

+++ actionview: sh ./rep.sh
Run options: --seed 53177 -n "/^(?:RenderTest#(?:test_render_call_to_partial_with_layout_in_main_layout_and_within_content_for_layout|test_nested_partial_with_form_builder))$/"

# Running:

.E

Error:
RenderTest#test_nested_partial_with_form_builder:
ActionController::MissingExactTemplate: Fun::GamesController#nested_partial_with_form_builder is missing a template for request formats: text/html
    /rails/actionpack/lib/action_controller/metal/implicit_render.rb:45:in `default_render'
    /rails/actionpack/lib/action_controller/metal/basic_implicit_render.rb:6:in `block in send_action'
    /rails/actionpack/lib/action_controller/metal/basic_implicit_render.rb:6:in `tap'
    /rails/actionpack/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
    /rails/actionpack/lib/abstract_controller/base.rb:195:in `process_action'
    /rails/actionpack/lib/action_controller/metal/rendering.rb:30:in `process_action'
    /rails/actionpack/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
    /rails/activesupport/lib/active_support/callbacks.rb:98:in `run_callbacks'
    /rails/actionpack/lib/abstract_controller/callbacks.rb:41:in `process_action'
    /rails/actionpack/lib/action_controller/metal/rescue.rb:22:in `process_action'
    /rails/actionpack/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
    /rails/activesupport/lib/active_support/notifications.rb:203:in `block in instrument'
    /rails/activesupport/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
    /rails/activesupport/lib/active_support/notifications.rb:203:in `instrument'
    /rails/actionpack/lib/action_controller/metal/instrumentation.rb:33:in `process_action'
    /rails/actionpack/lib/action_controller/metal/params_wrapper.rb:245:in `process_action'
    /rails/actionpack/lib/abstract_controller/base.rb:136:in `process'
    /rails/actionview/lib/action_view/rendering.rb:39:in `process'
    /rails/actionpack/lib/action_controller/metal.rb:190:in `dispatch'
    /rails/actionpack/lib/action_controller/test_case.rb:517:in `process'
    /rails/actionpack/lib/action_controller/test_case.rb:395:in `get'
    /rails/actionview/test/actionpack/controller/render_test.rb:1346:in `test_nested_partial_with_form_builder'


bin/test test/actionpack/controller/render_test.rb:1344



Finished in 0.066287s, 30.1717 runs/s, 15.0858 assertions/s.
2 runs, 1 assertions, 0 failures, 1 errors, 0 skips
%

10. Mark this commit as "bad"

% git bisect bad
Bisecting: 1 revision left to test after this (roughly 1 step)
[f22c4ff359498ab342e4b6d6feb21af6004ee270] View the help message with PAGER [Feature #16754]

11. See if f22c4ff359498ab342e4b6d6feb21af6004ee270 reproduces the error

• Script

RUBY_IMAGE=rubylang/rubyfarm:f22c4ff359498ab342e4b6d6feb21af6004ee270 docker-compose -f .buildkite/docker-compose.yml build base && 
CI=1 docker-compose -f .buildkite/docker-compose.yml run default runner actionview 'sh ./rep.sh'

• Result

+++ actionview: sh ./rep.sh
Run options: --seed 53177 -n "/^(?:RenderTest#(?:test_render_call_to_partial_with_layout_in_main_layout_and_within_content_for_layout|test_nested_partial_with_form_builder))$/"

# Running:

.E

Error:
RenderTest#test_nested_partial_with_form_builder:
ActionController::MissingExactTemplate: Fun::GamesController#nested_partial_with_form_builder is missing a template for request formats: text/html
    /rails/actionpack/lib/action_controller/metal/implicit_render.rb:45:in `default_render'
    /rails/actionpack/lib/action_controller/metal/basic_implicit_render.rb:6:in `block in send_action'
    /rails/actionpack/lib/action_controller/metal/basic_implicit_render.rb:6:in `tap'
    /rails/actionpack/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
    /rails/actionpack/lib/abstract_controller/base.rb:195:in `process_action'
    /rails/actionpack/lib/action_controller/metal/rendering.rb:30:in `process_action'
    /rails/actionpack/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
    /rails/activesupport/lib/active_support/callbacks.rb:98:in `run_callbacks'
    /rails/actionpack/lib/abstract_controller/callbacks.rb:41:in `process_action'
    /rails/actionpack/lib/action_controller/metal/rescue.rb:22:in `process_action'
    /rails/actionpack/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
    /rails/activesupport/lib/active_support/notifications.rb:203:in `block in instrument'
    /rails/activesupport/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
    /rails/activesupport/lib/active_support/notifications.rb:203:in `instrument'
    /rails/actionpack/lib/action_controller/metal/instrumentation.rb:33:in `process_action'
    /rails/actionpack/lib/action_controller/metal/params_wrapper.rb:245:in `process_action'
    /rails/actionpack/lib/abstract_controller/base.rb:136:in `process'
    /rails/actionview/lib/action_view/rendering.rb:39:in `process'
    /rails/actionpack/lib/action_controller/metal.rb:190:in `dispatch'
    /rails/actionpack/lib/action_controller/test_case.rb:517:in `process'
    /rails/actionpack/lib/action_controller/test_case.rb:395:in `get'
    /rails/actionview/test/actionpack/controller/render_test.rb:1346:in `test_nested_partial_with_form_builder'


bin/test test/actionpack/controller/render_test.rb:1344



Finished in 0.070419s, 28.4016 runs/s, 14.2008 assertions/s.
2 runs, 1 assertions, 0 failures, 1 errors, 0 skips
%

12. Mark this commit as "bad"

% git bisect bad
Bisecting: 0 revisions left to test after this (roughly 0 steps)
[5c2768181382bf84137759efea66f3aaf212665d] Enable fastpath on invokesuper (#3021)
%

13. See if 5c2768181382bf84137759efea66f3aaf212665d reproduces the error

• Script

RUBY_IMAGE=rubylang/rubyfarm:5c2768181382bf84137759efea66f3aaf212665d docker-compose -f .buildkite/docker-compose.yml build base && 
CI=1 docker-compose -f .buildkite/docker-compose.yml run default runner actionview 'sh ./rep.sh'

• Result

Run options: --seed 53177 -n "/^(?:RenderTest#(?:test_render_call_to_partial_with_layout_in_main_layout_and_within_content_for_layout|test_nested_partial_with_form_builder))$/"

# Running:

.E

Error:
RenderTest#test_nested_partial_with_form_builder:
ActionController::MissingExactTemplate: Fun::GamesController#nested_partial_with_form_builder is missing a template for request formats: text/html
    /rails/actionpack/lib/action_controller/metal/implicit_render.rb:45:in `default_render'
    /rails/actionpack/lib/action_controller/metal/basic_implicit_render.rb:6:in `block in send_action'
    /rails/actionpack/lib/action_controller/metal/basic_implicit_render.rb:6:in `tap'
    /rails/actionpack/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
    /rails/actionpack/lib/abstract_controller/base.rb:195:in `process_action'
    /rails/actionpack/lib/action_controller/metal/rendering.rb:30:in `process_action'
    /rails/actionpack/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
    /rails/activesupport/lib/active_support/callbacks.rb:98:in `run_callbacks'
    /rails/actionpack/lib/abstract_controller/callbacks.rb:41:in `process_action'
    /rails/actionpack/lib/action_controller/metal/rescue.rb:22:in `process_action'
    /rails/actionpack/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
    /rails/activesupport/lib/active_support/notifications.rb:203:in `block in instrument'
    /rails/activesupport/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
    /rails/activesupport/lib/active_support/notifications.rb:203:in `instrument'
    /rails/actionpack/lib/action_controller/metal/instrumentation.rb:33:in `process_action'
    /rails/actionpack/lib/action_controller/metal/params_wrapper.rb:245:in `process_action'
    /rails/actionpack/lib/abstract_controller/base.rb:136:in `process'
    /rails/actionview/lib/action_view/rendering.rb:39:in `process'
    /rails/actionpack/lib/action_controller/metal.rb:190:in `dispatch'
    /rails/actionpack/lib/action_controller/test_case.rb:517:in `process'
    /rails/actionpack/lib/action_controller/test_case.rb:395:in `get'
    /rails/actionview/test/actionpack/controller/render_test.rb:1346:in `test_nested_partial_with_form_builder'


bin/test test/actionpack/controller/render_test.rb:1344



Finished in 0.072101s, 27.7387 runs/s, 13.8693 assertions/s.
2 runs, 1 assertions, 0 failures, 1 errors, 0 skips
%

14. Mark this commit as "bad"

% git bisect bad
5c2768181382bf84137759efea66f3aaf212665d is the first bad commit
commit 5c2768181382bf84137759efea66f3aaf212665d
Author: Takashi Kokubun <takashikkbn@gmail.com>
Date:   Sat Apr 11 20:45:22 2020 -0700

    Enable fastpath on invokesuper (#3021)

    Fastpath has not been used for invokesuper since it has set vm_call_super_method on every invocation.
    Because it seems to be blocked only by refinements, try enabling fastpath on invokesuper when cme is not for refinements.

    While this patch itself should be helpful for VM performance, a part of this patch's motivation is to unblock inlining invokesuper on JIT.

    $ benchmark-driver -v --rbenv 'before;after' benchmark/vm2_super.yml --repeat-count=4
    before: ruby 2.8.0dev (2020-04-11T15:19:58Z master a01bda5949) [x86_64-linux]
    after: ruby 2.8.0dev (2020-04-12T02:00:08Z invokesuper-fastpath c171984ee3) [x86_64-linux]
    Calculating -------------------------------------
                             before       after
               vm2_super    20.031M     32.860M i/s -      6.000M times in 0.299534s 0.182593s

    Comparison:
                            vm2_super
                   after:  32859885.2 i/s
                  before:  20031097.3 i/s - 1.64x  slower

 vm_insnhelper.c | 5 +++--
 1 file changed, 3 insertions(+), 2 deletions(-)
%

15. Report to https://bugs.ruby-lang.org/

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

16. Validate if it is fixed.

% ruby -v
ruby 2.8.0dev (2020-04-15T06:49:29Z master 79f3403be0) [x86_64-darwin19]
% PARALLEL_WORKERS=1 bin/test test/controller/base_test.rb  --seed 31701 -n "/^(?:UrlOptionsTest#(?:test_url_options_override)|ControllerInstanceTests#(?:test_performed\\?)|PerformActionTest#(?:test_action_missing_should_work))$/"
Run options: --seed 31701 -n "/^(?:UrlOptionsTest#(?:test_url_options_override)|ControllerInstanceTests#(?:test_performed\\?)|PerformActionTest#(?:test_action_missing_should_work))$/"

# Running:

...

Finished in 0.126021s, 23.8056 runs/s, 47.6111 assertions/s.
3 runs, 6 assertions, 0 failures, 0 errors, 0 skips
%

End

Let me know if you have any ideas.