TruffleRuby performance or memory regression on rspec

[petenorth]

I've noticed that a CI job I have started showing errors recently

https://github.com/petenorth/schools-experience/actions?query=workflow%3A%22rspec+with+truffleruby%22

The issues seems to have been introduced between

https://github.com/oracle/truffleruby/commit/a54e85bbd68e3929781fc1654a2c1ce71e782a37

and

https://github.com/oracle/truffleruby/commit/b682c1923c76934abaa5f43099d6771e93693a60

I am guessing it is associated with the language agnostic inlining default change?

It only shows up for throughput mode and was a unfortunate as that engine mode had been improving recently .

[eregon]

Thanks for the report.

So the mode that matters is the first one, the rspec mode. BTW, to simplify, I'd recommend always using the default mode for the app since it doesn't seem to change much while running tests. The two runs that failed: https://github.com/petenorth/schools-experience/runs/684091843?check_suite_focus=true https://github.com/petenorth/schools-experience/runs/682109341?check_suite_focus=true and the one with LanguageAgnosticInlining=false: https://github.com/petenorth/schools-experience/runs/684430557?check_suite_focus=true

Both of these commits are before 385179facf139b4aab97efca8594450da2c11239 which enables the new language agnostic inlining by default.

Maybe some of the variations here are due to GitHub Actions which probably uses shared resources to run workflows? Could you try to reproduce the difference locally, e.g., by running a subset of specs?

[petenorth]

Last night's run showed that in latency mode the rspec tests ran twice a slowly as before (they were taking c. 15 mins and now they take c. 30 mins).

For running the rspec tests in throughput mode it is also taking longer c. 40 mins vs 25 mins .

[petenorth]

I've added the inline option to the matrix for the rspec job (only applying it to the rspec process)

https://github.com/petenorth/schools-experience/runs/689491563?check_suite_focus=true

LanguageAgnosticInlining=false does result in faster runs.

[eregon]

I've been meaning to look this but didn't get the time yet.

I want to reproduce it locally to get a better estimate of how much slower and to debug it.

[eregon]

It seems the new inlining doesn't respect --engine.Mode=latency so that's probably a good part of it: https://github.com/oracle/truffleruby/issues/1625#issuecomment-645407618

[eregon]

@petenorth --engine.Mode=latency is now respected by the new inlining: 2d854d124b187e6c85c9a47b2ffbfe3f50610c4b

Could you retry?

[petenorth]

I seem to be having issues in the bundle install now, it is hanging with this output

Fetching https://github.com/microsoft/ApplicationInsights-Ruby.git
Fetching https://github.com/DFE-Digital/govuk_elements_form_builder.git
Fetching gem metadata from https://rubygems.org/.

Has only started recently (last couple days) and is also causing the github actions to hang.

[petenorth]

Tried it with --verbose and got

HTTP 200 OK https://index.rubygems.org/versions
Fetching gem metadata from https://rubygems.org/
Looking up gems ["rails", "pg", "pg_search", "activerecord-postgis-adapter", "breasal", "geocoder", "puma", "sassc-rails", "autoprefixer-rails", "sprockets", "uglifier", "webpacker", "bootsnap", "canonical-rails", "notifications-ruby-client", "acts_as_list", "delayed_job_active_record", "delayed_cron_job", "delayed_job_web", "redis", "exception_notification", "slack-notifier", "dotenv-rails", "kaminari", "phonelib", "sentry-raven", "rack-rewrite", "rack-timeout", "openid_connect", "uk_postcode", "addressable", "faraday", "validates_timeliness", "activerecord-import", "tzinfo-data", "byebug", "rubocop", "govuk-lint", "pry-rails", "pry-byebug", "rspec-rails", "rspec_junit_formatter", "factory_bot_rails", "brakeman", "bullet", "parallel_tests", "web-console", "listen", "spring", "spring-watcher-listen", "spring-commands-rspec", "foreman", "rails-erd", "capybara", "selenium-webdriver", "webdrivers", "cucumber-rails", "database_cleaner", "shoulda-matchers", "rails-controller-testing", "webmock", "capybara-screenshot", "govuk_frontend_toolkit", "govuk_elements_rails"]
HTTP GET https://index.rubygems.org/info/activerecord-postgis-adapter
HTTP GET https://index.rubygems.org/info/acts_as_list
HTTP GET https://index.rubygems.org/info/kaminari
HTTP GET https://index.rubygems.org/info/exception_notification
HTTP GET https://index.rubygems.org/info/kaminari
HTTP GET https://index.rubygems.org/info/exception_notification
HTTP GET https://index.rubygems.org/info/rails
HTTP GET https://index.rubygems.org/info/pg_search
HTTP GET https://index.rubygems.org/info/redis
HTTP GET https://index.rubygems.org/info/notifications-ruby-client
HTTP GET https://index.rubygems.org/info/delayed_job_web
HTTP GET https://index.rubygems.org/info/delayed_job_web
HTTP GET https://index.rubygems.org/info/webpacker
HTTP GET https://index.rubygems.org/info/puma
HTTP GET https://index.rubygems.org/info/uglifier
HTTP GET https://index.rubygems.org/info/geocoder
HTTP GET https://index.rubygems.org/info/dotenv-rails
/truffleruby-head/lib/mri/bundler/vendor/thor/lib/thor/shell/basic.rb:92:in `handle': Illegal seek (Errno::ESPIPE)
    from /truffleruby-head/lib/mri/bundler/vendor/thor/lib/thor/shell/basic.rb:92:in `block in unseek!'
    from /truffleruby-head/lib/mri/bundler/vendor/thor/lib/thor/shell/basic.rb:92:in `synchronized'
    from /truffleruby-head/lib/mri/bundler/vendor/thor/lib/thor/shell/basic.rb:92:in `unseek!'
    from /truffleruby-head/lib/mri/bundler/vendor/thor/lib/thor/shell/basic.rb:92:in `reset_buffering'
    from /truffleruby-head/lib/mri/bundler/vendor/thor/lib/thor/shell/basic.rb:92:in `write'
    from /truffleruby-head/lib/mri/bundler/vendor/thor/lib/thor/shell/basic.rb:92:in `block in print'
    from /truffleruby-head/lib/mri/bundler/vendor/thor/lib/thor/shell/basic.rb:92:in `each'
    from /truffleruby-head/lib/mri/bundler/vendor/thor/lib/thor/shell/basic.rb:92:in `print'
    from /truffleruby-head/lib/mri/bundler/vendor/thor/lib/thor/shell/basic.rb:92:in `print'
    from /truffleruby-head/lib/mri/bundler/vendor/thor/lib/thor/shell/basic.rb:92:in `say'
    from /truffleruby-head/lib/mri/bundler/ui/shell.rb:107:in `tell_me'
    from /truffleruby-head/lib/mri/bundler/ui/shell.rb:39:in `warn'
    from /truffleruby-head/lib/mri/bundler/retry.rb:53:in `fail_attempt'
    from /truffleruby-head/lib/mri/bundler/retry.rb:42:in `run'
    from /truffleruby-head/lib/mri/bundler/retry.rb:30:in `attempt'
    from /truffleruby-head/lib/mri/bundler/fetcher.rb:112:in `specs_with_retry'
    from /truffleruby-head/lib/mri/bundler/source/rubygems.rb:407:in `block in fetch_names'
    from /truffleruby-head/lib/mri/bundler/source/rubygems.rb:404:in `each'
    from /truffleruby-head/lib/mri/bundler/source/rubygems.rb:404:in `fetch_names'
    from /truffleruby-head/lib/mri/bundler/source/rubygems.rb:399:in `block in remote_specs'
    from /truffleruby-head/lib/mri/bundler/index.rb:11:in `build'
    from /truffleruby-head/lib/mri/bundler/source/rubygems.rb:386:in `remote_specs'
    from /truffleruby-head/lib/mri/bundler/source/rubygems.rb:89:in `specs'
    from /truffleruby-head/lib/mri/bundler/definition.rb:273:in `block (2 levels) in index'
    from /truffleruby-head/lib/mri/bundler/definition.rb:271:in `each'
    from /truffleruby-head/lib/mri/bundler/definition.rb:271:in `block in index'
    from /truffleruby-head/lib/mri/bundler/index.rb:11:in `build'
    from /truffleruby-head/lib/mri/bundler/definition.rb:268:in `index'
    from /truffleruby-head/lib/mri/bundler/definition.rb:258:in `resolve'
    from /truffleruby-head/lib/mri/bundler/definition.rb:170:in `specs'
    from /truffleruby-head/lib/mri/bundler/definition.rb:158:in `resolve_remotely!'
    from /truffleruby-head/lib/mri/bundler/installer.rb:310:in `resolve_if_needed'
    from /truffleruby-head/lib/mri/bundler/installer.rb:84:in `block in run'
    from /truffleruby-head/lib/mri/bundler/process_lock.rb:12:in `block in lock'
    from /truffleruby-head/lib/mri/bundler/process_lock.rb:9:in `open'
    from /truffleruby-head/lib/mri/bundler/process_lock.rb:9:in `lock'
    from /truffleruby-head/lib/mri/bundler/installer.rb:73:in `run'
    from /truffleruby-head/lib/mri/bundler/installer.rb:25:in `install'
    from /truffleruby-head/lib/mri/bundler/cli/install.rb:65:in `run'
    from /truffleruby-head/lib/mri/bundler/cli.rb:235:in `block in install'
    from /truffleruby-head/lib/mri/bundler/settings.rb:143:in `temporary'
    from /truffleruby-head/lib/mri/bundler/cli.rb:234:in `install'
    from /truffleruby-head/lib/mri/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
    from /truffleruby-head/lib/mri/bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command'
    from /truffleruby-head/lib/mri/bundler/vendor/thor/lib/thor.rb:387:in `dispatch'
    from /truffleruby-head/lib/mri/bundler/cli.rb:27:in `dispatch'
    from /truffleruby-head/lib/mri/bundler/vendor/thor/lib/thor/base.rb:466:in `start'
    from /truffleruby-head/lib/mri/bundler/cli.rb:18:in `start'
    from /truffleruby-head/lib/gems/gems/bundler-1.17.2/exe/bundle:30:in `block in <top (required)>'
    from /truffleruby-head/lib/mri/bundler/friendly_errors.rb:124:in `with_friendly_errors'
    from /truffleruby-head/lib/gems/gems/bundler-1.17.2/exe/bundle:22:in `<top (required)>'
    from /truffleruby-head/bin/bundle:43:in `load'
    from /truffleruby-head/bin/bundle:43:in `load'
    from /truffleruby-head/bin/bundle:43:in `<main>'
The command '/bin/sh -c bundle install --verbose --without development' returned a non-zero code: 1

[petenorth]

Have reproduced it using the setup-ruby github action (so not within a Docker build, but guess it might still be running within a Docker container)

https://github.com/petenorth/schools-experience/blob/master/.github/workflows/bundle-install.yml

the actual run is

https://github.com/petenorth/schools-experience/runs/813730149?check_suite_focus=true

[eregon]

@petenorth Somehow I missed the notification about your replies. The Bundler issue is probably related to #2041 and #2034.

[petenorth]

@eregon Everything looks good with the most recent run

https://github.com/petenorth/schools-experience/actions/runs/157247118

The timings are probably as fast as they have ever been (obvs the underlying github infrastructure can change) .

The language agnostic inlining flag now seems to respect the engine flag value of latency. Also, there is no significant difference in run duration in the rspec test between agnostic inlining being set to false or true.

I think the issue can be closed.

[eregon]

That's great to hear and it looks good, thanks for checking the results. Thank you again for reporting this issue, and sorry I didn't reply sooner, latency Mode not working with the new inlining was indeed a serious issue (affecting nightly builds but not releases, 20.1 defaults to the old inlining).

The Illegal seek (Errno::ESPIPE) still seems a bug (maybe hapenning only in Docker?), I reopened #2034 to track that.