Jets startup time is really long in local development with docker on MacOS

[onnimonni]

I'm seeing quite high waiting times (1m17s) before anything happens.

I'm running the latest jets gem (0.8.17) with ruby 2.5.1 and nodejs v10.11.0.

I shared my docker setup here: https://github.com/onnimonni/jets-project
Similar setup has been working really well for my rails projects.

These are the commands I used inside the docker container:

$ time jets generate scaffold Post title:string
      invoke  active_record
      create    db/migrate/20180922134209_create_posts.rb
      create    /models/post.rb
      invoke  resource_route
       route    resources :posts
      invoke  scaffold_controller
      create    /controllers/posts_controller.rb
      invoke    erb
      create      /views/posts
      create      /views/posts/index.html.erb
      create      /views/posts/edit.html.erb
      create      /views/posts/show.html.erb
      create      /views/posts/new.html.erb
      create      /views/posts/_form.html.erb
      invoke    helper
      create      /helpers/posts_helper.rb

real	1m17.385s
user	0m1.030s
sys	0m0.150s
$ time jets db:create
FATAL:  password authentication failed for user "dbuser"
Couldn't create database for {"adapter"=>"postgresql", "encoding"=>"utf8", "pool"=>"5", "database"=>"development", "username"=>"dbuser", "password"=>"dbpass", "host"=>"db"}
jets aborted!
PG::ConnectionBad: FATAL:  password authentication failed for user "dbuser"
...

Tasks: TOP => db:create
(See full trace by running task with --trace)

real	1m17.327s
user	0m0.920s
sys	0m0.230s

[tongueroo]

Thanks for the report. Took a gander at the Jets example project you’ve set up. Thanks for putting it together. It helps. 👍

This likely has to do with the fact that Jets uses Dir.glob a lot to do inflection and figure out what it needs to do. So Jets is reading a bunch of files on the filesystem. The performance issue then surfaces with Docker shared volumes on a macosx host. Looks like you’ve got a macosx host and are mounting a folder for the app code https://github.com/onnimonni/jets-project/blob/master/docker-compose.yml#L8 Have ran into slowness with Docker, macosx and shared volumes many times before 😞 Even ended up writing a rsync tool https://github.com/tongueroo/docksync to workaround the issue. Gut tells me that is the issue right off the bat though.

Understand that the need the shared volume so that we can edit files locally and see changes immediately reflected on the Docker host. For a test to confirm the theory though, can you try removing the shared volumes and testing the performance speed without the shared volumes? Would like to confirm my gut thoughts.

Would like to improve the performance here to be closer to Rails. Curious to see what happens. Have seen that as any app gets larger, the Docker volume on macosx becomes a problem because it takes time to load the app files themselves. There is no noticeable performance overhead with shared volumes when the host is Linux, only with MacOSX. Also have tried using Docker with NFS volumes instead and that helps but it wasn’t enough.

Will tag this will help wanted.

[pocheptsov]

I've tried @onnimonni project setup on Debian Linux and got this:

docker run -it -v $(pwd)/src:/app -e AWS_REGION=eu-west-1 jetsproject_server bash

> export TEST=true
> time jets generate scaffold TestPost title:string
      invoke  active_record
      create    db/migrate/20180924045646_create_test_posts.rb
      create    /models/test_post.rb
      invoke  resource_route
       route    resources :test_posts
      invoke  scaffold_controller
      create    /controllers/test_posts_controller.rb
      invoke    erb
      create      /views/test_posts
      create      /views/test_posts/index.html.erb
      create      /views/test_posts/edit.html.erb
      create      /views/test_posts/show.html.erb
      create      /views/test_posts/new.html.erb
      create      /views/test_posts/_form.html.erb
      invoke    helper
      create      /helpers/test_posts_helper.rb

real    0m1.719s
user    0m1.120s
sys     0m0.330s

@tongueroo can we use Jets::Timing to help recording startup issue?

[onnimonni]

Thanks for helping out! The test from @pocheptsov seems to confirm that this is just caused from slow bind mounts in MacOS.

My problem is that I have too many ruby projects with different version dependencies so using rbenv or locally installed ruby gets too time consuming. Also docker helps others to start working with the same project faster because the environments are well defined.

I guess the biggest problem is the node_modules folder which is bind mounted to MacOS.
There isn't that many files elsewhere but that folder contains so many files.

I will try this again with setup where those are moved away from the project folder.

Edit: Rails has been slow too but adding the :cached flag into bind mounts has helped and after that those projects have been working properly in MacOS. With Jets this did not seem to help.

[tongueroo]

@pocheptsov Thank so much for testing the theory. It did not even occur to me that you might not be on a macosx machine when I asked you to take a look 🤦🏻‍♂️ Appreciate reproducing it on Linux.

Ha, you noticed the JETS_TIMING code. That's some experimental code I hacked on to do some quick timing analysis. Unsure if it'll be kept around tbh. To turn it on run:

JETS_TIMING=1 jets deploy  

You'll get something like this at the end of the deploy:

Stack success status: UPDATE_COMPLETE
Time took for stack deployment: 1m 11s.
Prewarming application...
Timing report:
overall: 108.102s
commands/deploy.rb:
  run: 108.102s
  build_code: 19.611s
  ship: 88.228s
  rest: 0.263s
commands/build.rb:
  build_code: 19.611s
  build_templates: 0.029s
builders/code_builder.rb:
  build: 19.524s
  compile_assets: 0.000s
  copy_project: 0.686s
  start_app_root_setup: 0.029s
  bundle: 3.560s
  finish_app_root_setup: 6.450s
  create_zip_file: 8.795s
cfn/ship.rb:
  run: 88.198s
  upload_to_s3: 16.730s
  update_stack: 0.097s
  wait_for_stack: 71.196s

The instrumentation has only been added to the build and deploy process. There's no instrumentation that measures the Jets booting process. Feel that Jets timing is pretty hacky and likely will remove it at some point. So it was actually better to go back to puts debugging to identify the performance issue.

@onnimonni @pocheptsov
So dug into it this morning. All the debugging commits are in the #40 You can see the historical commits to see all the puts added to figure it out. My gut thoughts were wrong in this case 😁 It did not have much to do with Jets inflection and eager loading. It was how Jets is determining the region the application is running in. You can see the changes in #40.

TLDR

Essentially, added --max-time 5 --connect-timeout 5 to the curl command and that fixes performance. When you're running docker on macosx, the AWS metadata endpoint is not available and takes forever to connect and timeout. Adding those parameters speed it up.

You can also set the AWS region explicitly with JETS_AWS_REGION and it will entirely short-circuit this curl logic. Interestingly, after curling once it looks like the local DNS caches the connection lookup and the curl request is fast for about a minute.

Test results

$ docker-compose exec server bash
root@0189ebd6ad1d:/app# time jets generate scaffold TestPost title:string
...
real  1m16.941s
user  0m1.090s
sys 0m0.300s
root@0189ebd6ad1d:/app# time bundle exec jets generate scaffold TestPost title:string
...
real  0m1.767s
user  0m1.120s
sys 0m0.210s
root@0189ebd6ad1d:/app# exit

Fork of example jets-project

Also if you're wondering how the issue was debugged. Here are the changes to the @onnimonni jets-project example:

• Commit: tongueroo/jets-project@9d0b882
• My Fork: https://github.com/tongueroo/jets-project

This allowed testing with a local copy of jets with docker-compose and to identify the issue a little more quickly. 👍

[tongueroo]

Released in v0.8.18: CHANGELOG Thanks again for the helpful reporting.

[onnimonni]

Excellent! and thanks for the fast fix!