refact: Stories rendering optimize

.dev_to/compose.yml

@@ -45,6 +45,11 @@ x-backend: &backend
     PSQL_HISTFILE: /usr/local/hist/.psql_history
     IRB_HISTFILE: /usr/local/hist/.irb_history
     EDITOR: vi
+    NEW_RELIC_LICENSE_KEY: ${NR_LICENSE_KEY}
+    NEW_RELIC_APP_NAME: "dev_to"
+    NEW_RELIC_LOG: "stdout"
+    NEW_RELIC_AGENT_ENABLED: "true"
+    NEW_RELIC_ENV: "development"
   depends_on: &backend_depends_on
     postgres:
       condition: service_healthy

.gitignore

@@ -56,3 +56,4 @@ package-lock.json
 
 #sitemap
 /public/sitemap.xml.gz
+.env

.ruby-version

@@ -1 +1 @@
-3.3.1
+3.4.1

Gemfile

@@ -40,6 +40,7 @@ gem "dalli", "~> 2.7"
 gem "delayed_job_active_record", "~> 4.1"
 gem "delayed_job_web", "~> 1.4"
 gem "devise", "~> 4.6"
+gem 'dotenv-rails'
 gem "draper", "~> 3.0"
 gem "email_validator", "~> 1.6"
 gem "emoji_regex", "~> 1.0"
@@ -105,6 +106,11 @@ gem "validate_url", "~> 1.0"
 gem "webpacker", "~> 3.6"
 gem "webpush", "~> 0.3"
 
+# Monitoring
+gem "newrelic_rpm"
+gem "rack-mini-profiler"
+gem "pghero"
+
 group :development do
   gem "better_errors", "~> 2.5"
   gem "binding_of_caller", "~> 0.8"
@@ -119,7 +125,7 @@ group :development do
   gem "web-console", "~> 3.7"
 end
 
-group :development, :test do
+group :development, :test, :profile do
   gem "capybara", "~> 3.13"
   gem "derailed", "~> 0.1"
   gem "erb_lint", "~> 0.0", require: false
@@ -132,6 +138,9 @@ group :development, :test do
   gem "rspec-retry", "~> 0.6"
   gem "rubocop", "~> 0.63", require: false
   gem "rubocop-rspec", "~> 1.31"
+  gem "stackprof", "~> 0.2"
+  gem "ruby-prof", "~> 0.17"
+  gem "foreman"
   # gem "spring", "~> 2.0"
   # gem "spring-commands-rspec", "~> 1.0"
   gem "vcr", "~> 4.0"
@@ -146,12 +155,10 @@ group :test do
   gem "launchy", "~> 2.4"
   gem "pundit-matchers", "~> 1.6"
   gem "rails-controller-testing", "~> 1.0"
-  gem "ruby-prof", "~> 0.17", require: false
   gem "selenium-webdriver", "~> 3.141"
   gem "shoulda-matchers", "4.0.0.rc1", require: false
   gem "simplecov", "~> 0.16", require: false
   gem "sinatra", "~> 2.0"
-  gem "stackprof", "~> 0.2", require: false, platforms: :ruby
   gem "stripe-ruby-mock", "~> 2.5", require: "stripe_mock"
   gem "test-prof", "~> 0.7"
   gem "timecop", "~> 0.9"

Gemfile.lock

@@ -254,6 +254,10 @@ GEM
     diff-lcs (1.6.0)
     docile (1.4.1)
     domain_name (0.6.20240107)
+    dotenv (2.8.1)
+    dotenv-rails (2.8.1)
+      dotenv (= 2.8.1)
+      railties (>= 3.2)
     draper (3.1.0)
       actionpack (>= 5.0)
       activemodel (>= 5.0)
@@ -472,6 +476,7 @@ GEM
     fog-xml (0.1.5)
       fog-core
       nokogiri (>= 1.5.11, < 2.0.0)
+    foreman (0.88.1)
     formatador (0.3.0)
     front_matter_parser (0.2.1)
     fugit (1.11.1)
@@ -646,6 +651,7 @@ GEM
     net-smtp (0.5.1)
       net-protocol
     netrc (0.11.0)
+    newrelic_rpm (9.17.0)
     nio4r (2.7.4)
     nokogiri (1.15.7-aarch64-linux)
       racc (~> 1.4)
@@ -697,6 +703,8 @@ GEM
       ast (~> 2.4.1)
       racc
     pg (1.5.9)
+    pghero (2.8.3)
+      activerecord (>= 5)
     pry (0.14.2)
       coderay (~> 1.1)
       method_source (~> 1.0)
@@ -726,6 +734,8 @@ GEM
     rack (2.2.11)
     rack-host-redirect (1.3.0)
       rack
+    rack-mini-profiler (3.3.1)
+      rack (>= 1.2.0)
     rack-protection (2.2.4)
       rack
     rack-proxy (0.7.7)
@@ -1048,6 +1058,7 @@ DEPENDENCIES
   derailed (~> 0.1)
   derailed_benchmarks (~> 1.3)
   devise (~> 4.6)
+  dotenv-rails
   draper (~> 3.0)
   email_validator (~> 1.6)
   emoji_regex (~> 1.0)
@@ -1062,6 +1073,7 @@ DEPENDENCIES
   figaro (~> 1.1)
   fix-db-schema-conflicts
   fog (~> 1.41)
+  foreman
   front_matter_parser (~> 0.2)
   gemoji (~> 3.0.0)
   gibbon (~> 2.2)
@@ -1081,13 +1093,15 @@ DEPENDENCIES
   liquid (~> 4.0)
   memory_profiler (~> 0.9)
   nakayoshi_fork
+  newrelic_rpm
   nokogiri (~> 1.10)
   octokit (~> 4.13)
   omniauth (~> 1.9)
   omniauth-github (~> 1.3)
   omniauth-twitter (~> 1.4)
   parallel_tests (~> 2.27)
   pg (~> 1.1)
+  pghero
   pry (~> 0.12)
   pry-byebug (~> 3.7)
   pry-rails (~> 0.3)
@@ -1098,6 +1112,7 @@ DEPENDENCIES
   pusher (~> 1.3)
   pusher-push-notifications (~> 1.0)
   rack-host-redirect (~> 1.3)
+  rack-mini-profiler
   rack-timeout (~> 0.5)
   rails (~> 5.1.6)
   rails-assets-airbrake-js-client (~> 1.5)!

Procfile.prof

@@ -0,0 +1,3 @@
+web: bin/rails s -p 3000
+webpacker: ./bin/webpack-dev-server
+job: bin/rake jobs:work

app/controllers/stories_controller.rb

@@ -1,6 +1,13 @@
 class StoriesController < ApplicationController
   before_action :authenticate_user!, except: %i[index search show feed new]
   before_action :set_cache_control_headers, only: %i[index search show]
+  around_action :profile_with_stackprof, only: :index
+
+  def profile_with_stackprof
+    StackProf.run(mode: :wall, raw: true, out: "tmp/stackprof-wall.dump", interval: 50) do
+      yield
+    end
+  end
 
   def index
     add_param_context(:username, :tag)

app/views/stories/_main_stories_feed.html.erb

@@ -55,7 +55,9 @@
     <% if !user_signed_in? && i == 4 %>
       <%= render "stories/sign_in_invitation" %>
     <% end %>
-    <%= render "articles/single_story", story: story %>
+    <% cache ["single_story", story] do %>
+      <%= render "articles/single_story", story: story %>
+    <% end %>
   <% end %>
 <% end %>
 <% if @stories.size > 1 %>

bin/startup

@@ -12,5 +12,10 @@ end
 
 chdir APP_ROOT do
   puts "== STARTING UP =="
-  system! "foreman start -f Procfile.dev"
+  if ENV["RAILS_ENV"] == "profile"
+    system! "bundle exec rake assets:precompile"
+    system! "foreman start -f Procfile.prof"
+  else
+    system! "foreman start -f Procfile.dev"
+  end
 end

case-stady.md

@@ -0,0 +1,154 @@
+## Актуальная проблема
+Cтраница `StoriesController#index` загружается очень медленно. Необходимо исследовать проблему на возможность оптимизации.
+
+## Формирование метрики
+В качестве метрики я использовал данные из `ab` бенмарка, а именно среднее значение времени затраченного на выполнение запроса
+на тесте `ab -n 100 -c 5 http://localhost:3000/`
+
+## Статистика до оптимизации
+Выполнение бенчмарка `ab -n 100 -c 5 http://localhost:3000/` показало значение `Time per request: 4792.132 [ms]`
+```
+Concurrency Level:      5
+Time taken for tests:   95.843 seconds
+Complete requests:      100
+Failed requests:        62
+   (Connect: 0, Receive: 0, Length: 62, Exceptions: 0)
+Total transferred:      16150036 bytes
+HTML transferred:       16048916 bytes
+Requests per second:    1.04 [#/sec] (mean)
+Time per request:       4792.132 [ms] (mean)
+Time per request:       958.426 [ms] (mean, across all concurrent requests)
+Transfer rate:          164.56 [Kbytes/sec] received
+
+Connection Times (ms)
+              min  mean[+/-sd] median   max
+Connect:        0    0   0.2      0       2
+Processing:  2766 4644 285.4   4675    4950
+Waiting:     2765 4643 285.4   4674    4950
+Total:       2766 4644 285.4   4675    4950
+
+Percentage of the requests served within a certain time (ms)
+  50%   4675
+  66%   4712
+  75%   4757
+  80%   4797
+  90%   4852
+  95%   4915
+  98%   4947
+  99%   4950
+ 100%   4950 (longest request)
+```
+
+## Поиск точек роста
+Для поиска точек роста я воспользовался инструментами rack-mini-profiler и Newrelic.
+
+Newrelic подтверждает значения полученные в ab:
+![newrelic](/public/newrelic.png)
+
+rack-mini-profiler показал большое количество рендеринга `_single_story.html.erb`
+![single_story](/public/single_story.png)
+
+## Оптимизация
+
+Кэшируем проблемный паршиал:
+```
+<% cache ["single_story", story] do %>
+  <%= render "articles/single_story", story: story %>
+<% end %>
+```
+Проверяем `ab` бенчмарком насколько изменилась метрика:
+```
+Server Software:
+Server Hostname:        localhost
+Server Port:            3000
+
+Document Path:          /
+Document Length:        158982 bytes
+
+Concurrency Level:      5
+Time taken for tests:   20.597 seconds
+Complete requests:      100
+Failed requests:        15
+   (Connect: 0, Receive: 0, Length: 15, Exceptions: 0)
+Total transferred:      15999369 bytes
+HTML transferred:       15898184 bytes
+Requests per second:    4.86 [#/sec] (mean)
+Time per request:       1029.829 [ms] (mean)
+Time per request:       205.966 [ms] (mean, across all concurrent requests)
+Transfer rate:          758.59 [Kbytes/sec] received
+
+Connection Times (ms)
+              min  mean[+/-sd] median   max
+Connect:        0    1   2.0      0      13
+Processing:   240 1010 111.1   1018    1266
+Waiting:      240 1009 111.1   1015    1262
+Total:        241 1011 110.9   1018    1266
+
+Percentage of the requests served within a certain time (ms)
+  50%   1018
+  66%   1041
+  75%   1060
+  80%   1073
+  90%   1125
+  95%   1158
+  98%   1229
+  99%   1266
+ 100%   1266 (longest request)
+```
+Получаем значение Time per request: 1029.829 [ms], что почти в 5 раз быстрее первоначальных цифр.
+rack-mini-profiler теперь показывает что данные кэшируется и лишний раз паршиал `_single_story.html.erb` не рендерится.
+При этом показатели количества комментариев и количества лайков показывают актальное значение, тк сам объект story не закэширован.
+
+Попробовал профилирование с помощью Stackprof в `around_action` режиме и Ruby-prof с `callgrind`.
+Удобно для профилирования отдельных методов. Из минусов, в трейсе много лишней рельсовой информации.
+
+## Local_Production env
+Создал новый энв `profile`, который максимально приближен к production.
+`ab` бенчмарк показал Time per request: 92.812 [ms], что в 10 раз быстрее последнего оптимизированного варианта.
+```
+ab -n 100 -c 5 http://localhost:3000/
+This is ApacheBench, Version 2.3 <$Revision: 1913912 $>
+Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
+Licensed to The Apache Software Foundation, http://www.apache.org/
+
+Benchmarking localhost (be patient).....done
+
+
+Server Software:
+Server Hostname:        localhost
+Server Port:            3000
+
+Document Path:          /
+Document Length:        136409 bytes
+
+Concurrency Level:      5
+Time taken for tests:   1.856 seconds
+Complete requests:      100
+Failed requests:        97
+   (Connect: 0, Receive: 0, Length: 97, Exceptions: 0)
+Non-2xx responses:      97
+Total transferred:      602228 bytes
+HTML transferred:       584118 bytes
+Requests per second:    53.87 [#/sec] (mean)
+Time per request:       92.812 [ms] (mean)
+Time per request:       18.562 [ms] (mean, across all concurrent requests)
+Transfer rate:          316.83 [Kbytes/sec] received
+
+Connection Times (ms)
+              min  mean[+/-sd] median   max
+Connect:        0    0   0.9      0       7
+Processing:     6   63 123.9     18     760
+Waiting:        6   62 123.8     17     760
+Total:          6   64 123.9     18     760
+
+Percentage of the requests served within a certain time (ms)
+  50%     18
+  66%     24
+  75%     41
+  80%     53
+  90%    207
+  95%    272
+  98%    759
+  99%    760
+ 100%    760 (longest request)
+```

config/application.rb

@@ -35,6 +35,7 @@ class Application < Rails::Application
     config.active_job.queue_adapter = :delayed_job
 
     config.middleware.use Rack::Deflater
+    config.middleware.use(Rack::RubyProf, enabled: true, path: "tmp/profile")
 
     # Globally handle Pundit::NotAuthorizedError by serving 404
     config.action_dispatch.rescue_responses["Pundit::NotAuthorizedError"] = :not_found