Provide instant feedback when booting Rails

[olivierlacan]

Before:

After:

I've noticed during pair/mob programming sessions with peers that
despite the speed boosts provided by Bootsnap and Spring, there is a
noticeable latency between firing a bin/rails server command and any
feedback being provided to the console. Depending on the size of the
application this lack of feedback can make it seem like something is
wrong when Rails is simply busy initializing.

This change may seem gratuitous but by just printing one line to STDOUT
we're giving a clear signal to the Rails user that their command has
been received and that Rails is indeed booting. It almost imperciptibly
makes Rails feel more responsive.

Sure the code doesn't look very fancy but there's no other appropriate
place I could think of putting it than boot.rb.

[rails-bot]

Thanks for the pull request, and welcome! The Rails team is excited to review your changes, and you should hear from @sgrif (or someone else) soon.

If any changes to this PR are deemed necessary, please add them as extra commits. This ensures that the reviewer can see what has changed since they last reviewed the code. Due to the way GitHub handles out-of-date commits, this should also make it reasonably obvious what issues have or haven't been addressed. Large or tricky changes may require several passes of review and changes.

This repository is being automatically checked for code quality issues using Code Climate. You can see results for this analysis in the PR status below. Newly introduced issues should be fixed before a Pull Request is considered ready to review.

Please see the contribution instructions for more information.

[sgrif]

This seems like a simple and completely reasonable change. I agree that it's an improvement (though I am bothered more than I should be by the fact that you type faster in one gif and that they are different lengths :P)

Can you rebase?

[olivierlacan]

@sgrif Way ahead of you. 😛

I'll redo the GIF.

[rafaelfranca]

I'll defer this to @dhh. I find it unnecessary, but I'm not a UX expert.

[rafaelfranca]

This is also going to show in rails test, rails console, rails db:migrate, etc. I don't think it is interesting to the users to know that Rails is being booted on those commands. Questions like:

What is a Rails boot?
Why should I care about it?

will now appear.

[olivierlacan]

@rafaelfranca Fair point which can easily be addressed by non-language feedback like dots. Package managers which need a lot of time to do graph dependency resolution do this very well either with animated or static feedback.

[derekprior]

What does the experience of running a randomized test suite look like?

.................Booting Rails
......................

?

[olivierlacan]

@derekprior Looks cute to me. 😄

But we can probably find ways to disable this when it's not appropriate. Again this is something that could be addressed by using a loading cursor/symbol rather than text.

[sgrif]

I agree that this should only appear for rails s

[sgrif]

Actually to be more specific, I think it should really show up in any context that => Booting Puma appears (assuming Puma is being used) -- Which I assume is only rails s

[eugeneius]

Adding it right before this line should work:

rails/railties/lib/rails/commands/server/server_command.rb

Line 145 in 9242675

require APP_PATH

[olivierlacan]

@sgrif @eugeneius That would be too easy, sadly. 😃

The reason feedback in print_boot_information is so slow to begin with(as seen in my GIFs in the top post) is precisely because we do a bunch of work before we get to those.

railties-5.0.6/lib/rails/commands/server.rb:137:in `print_boot_information'
railties-5.0.6/lib/rails/commands/server.rb:98:in `start'
railties-5.0.6/lib/rails/commands/commands_tasks.rb:90:in `block in server'
railties-5.0.6/lib/rails/commands/commands_tasks.rb:85:in `tap'
railties-5.0.6/lib/rails/commands/commands_tasks.rb:85:in `server'
railties-5.0.6/lib/rails/commands/commands_tasks.rb:49:in `run_command!'
railties-5.0.6/lib/rails/commands.rb:18:in `<main>'
bootsnap-1.1.6/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:17:in `require'
bootsnap-1.1.6/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:17:in `require'
activesupport-5.0.6/lib/active_support/dependencies.rb:293:in `block in require'
activesupport-5.0.6/lib/active_support/dependencies.rb:259:in `load_dependency'
activesupport-5.0.6/lib/active_support/dependencies.rb:293:in `require'

[olivierlacan]

Since I can't really put this feedback after require "bundler/setup" (which is understandably slow) and everything else that happens before print_boot_information runs I can either argue that Bundler itself could provide some (optional) STDOUT feedback when it starts requiring gems, or that this should be generic enough not to disrupt other rails <commands>.

@derekprior At the least the rspec-rails feedback makes sense:

$ bin/rspec spec/
=> Booting Rails
Running via Spring preloader in process 94838

Randomized with seed 39557
......................................

[matthewd]

Library (and by extension config) files have no business writing directly to stdout/err -- I recently ranted at one of our dependencies for doing so.

More generally, I'd argue that this is how console applications work... and note that I don't particularly want to take the blame for whatever portion of that time is actually "Booting Bundler".

[sgrif]

@matthewd I agree with the general sentiment, but as you mentioned this is a CLI. We aren't doing this on require "rails". While I agree with your point about bundler overhead, do you disagree that giving some immediate output that work is happening is a good thing?

[matthewd]

@sgrif this is not a CLI. config/boot.rb is a library, which gets required by anything that wants the application loaded as a library -- it's not require "rails", but it is require "my_app".

If it were only happening on rails s, I would have no objection (beyond us going out of our way to take the blame for other things being slow), but it is not.

[sgrif]

I am 100% on board with implementing this so that it only occurs when running rails s

[olivierlacan]

@matthewd While you seem to focus on the issue of "taking the blame" I'm concerned about end-users of Rails not receiving any indication that a rails command (whatever it does behind the scenes) is not responding for 5 to 10 seconds.

I find that a very poor experience regardless of who or what is to blame for the delay, and a simple acknowledgement that the command has any effect is the least I feel Rails can do.

Now when it comes to only giving this feedback when rails server or rails s is sent, that's something I can easily extract from ARGV but will make for slightly nastier code in boot.rb.

To me that's a price worth paying. I hope I can convince others. 😄

[dhh]

Like it for console and server 👍

[matthewd]

Suggesting that I'm "focused" on blame, to the detriment of users, just because I've brought it up is not a particularly productive approach to this discussion. Rails is widely maligned as big and slow, and explicit attribution of the startup time to "Booting Rails" feeds that narrative.

Your gif shows the command taking about 1.5 seconds, by my estimate. Is it sped up? That would seem to defeat the point of what it's showing.

If you're trying to address a 5-10 second wait that manifests on larger applications, then we should look at where that time is being spent. It may be far easier to get a message out, from an appropriate place, at the one second mark than at zero seconds -- and I think that would be a fine trade-off.

If this can't be after bundler/setup, I think it's a non-starter. But I also don't see why that's the case -- I took you at your word that it is slow (which would be out of our control), but a quick test locally suggests it's not.

a simple acknowledgement that the command has has any effect is the least I feel Rails can do

What is the non-"least" you feel we can do?

[olivierlacan]

I've updated the code to only fire on variants of rails server and rails console:

if %w[s server c console].any? { |a| ARGV.include?(a) }
  puts "=> Booting Rails"
end

And I've tested the timings before or after bundler/setup and bootsnap/setup

With boot feedback at the top of boot.rb:

$ bin/rails s
2017-12-13T21:22:28.995: puts "=> Booting Rails"
=> Booting Rails
2017-12-13T21:22:28.995: File.expand_path('../Gemfile', __dir__)
2017-12-13T21:22:28.995: require 'bundler/setup'
2017-12-13T21:22:29.322: require 'bootsnap/setup'
2017-12-13T21:22:31.329: => Booting <server>
=> Booting Puma
=> Rails 5.0.6 application starting in development on http://localhost:3000
=> Run `rails server -h` for more startup options
Puma starting in single mode...
* Version 3.6.0 (ruby 2.3.4-p301), codename: Sleepy Sunday Serenity
* Min threads: 5, max threads: 5
* Environment: development
* Listening on tcp://localhost:3000
Use Ctrl-C to stop

With boot feedback at the bottom of the boot.rb:

$ bin/rails s
2017-12-13T21:22:58.434: File.expand_path('../Gemfile', __dir__)
2017-12-13T21:22:58.434: require 'bundler/setup'
2017-12-13T21:22:58.703: require 'bootsnap/setup'
2017-12-13T21:22:58.815: puts "=> Booting Rails"
=> Booting Rails
2017-12-13T21:23:00.186: => Booting <server>
=> Booting Puma
=> Rails 5.0.6 application starting in development on http://localhost:3000
=> Run `rails server -h` for more startup options
Puma starting in single mode...
* Version 3.6.0 (ruby 2.3.4-p301), codename: Sleepy Sunday Serenity
* Min threads: 5, max threads: 5
* Environment: development
* Listening on tcp://localhost:3000

[kaspth]

Having this code in boot.rb seems off to me and sifting off ARGV to print a message likewise, but I don't know where else we'd put it to nip it in the boot.

[olivierlacan]

@kaspth Feels off to me too because boot.rb is so clean but I couldn’t find a drawer to hide this in. Still seems like we have this file and it can do useful work if we don’t overthink it.

[sgrif]

This looks fine to me. I agree that it feels weird to put it in this file, but there's really not a more obvious place to put it. The implementation doesn't handle someone writing rails se, but I don't think that's important. Given where this is being put, I think keeping the code super simple is important. 99% of users are writing either s or server and this is a minor UX improvement in that case. I'm going to go ahead and merge this, as I think all the concerns here have been sufficiently addressed.

[olivierlacan]

@matthewd Sorry for not answering you earlier.

Suggesting that I'm "focused" on blame, to the detriment of users, just because I've brought it up is not a particularly productive approach to this discussion. Rails is widely maligned as big and slow, and explicit attribution of the startup time to "Booting Rails" feeds that narrative.

I'm sorry for making you out to sound like you didn't care about users. There's been a lot of bike-shedding about a really small change here so I think you can see how I might have perceived everyone focusing on everything negative.

The GIFs aren't sped up. It's a production app with 70KLOC with 253 Gemfile dependencies. I ran spring stop to show a cold boot although Bootsnap is in there too and its contribution surely has an impact I haven't subtracted from the example.

If you're trying to address a 5-10 second wait that manifests on larger applications, then we should look at where that time is being spent. It may be far easier to get a message out, from an appropriate place, at the one second mark than at zero seconds -- and I think that would be a fine trade-off.

I believe that's far beyond the scope of this PR, but I agree that it's worthwhile. I disagree that getting a message out later, or in a more appropriate place is solving the problem I'm attempting to address here.

If this can't be after bundler/setup, I think it's a non-starter. But I also don't see why that's the case -- I took you at your word that it is slow (which would be out of our control), but a quick test locally suggests it's not.

I don't think that makes it a non-starter, but my logging in #31434 (comment) shows that there's (at least) 381 milliseconds between the command being issues and the feedback when we puts at the bottom of boot.rb.

.3 seconds is beyond the .1 second perceptual barrier for user-initiated actions to feel instantaneous.

0.1 second is the response time limit if you want users to feel like their actions are directly causing something to happen on the screen.

https://www.nngroup.com/articles/powers-of-10-time-scales-in-ux/

I'm not arguing Rails should feel instantaneous, but we can try to give users as fast a feedback about their actions as possible in the command line.

What is the non-"least" you feel we can do?

Differentiating Rails boot time from Bundler require time would be good and educational. It would subtly help users learn the impact of a bloated Gemfile and I think it would help avoid what you were worried about — people conflating Rails speed and Bundler/Gem require speed.

That said, that is definitely beyond the scope of this PR. If you're interested in trying to address that I think it would be worthwhile although it might require some coordination with the Bundler team. I'm not sure if we can get timing data from require "bundler/setup". That could be a cool useful option to offer people debugging slow boots.

[guilleiguaran]

A small note on this: Checking for ARGV doesn't work when you start the app using the server command instead of rails (e.g starting the app using unicorn, puma or passenger executable)