mirrors
/
rails
mirror of https://github.com/rails/rails
8
0
Fork 0
Code Issues Projects Releases Wiki Activity

Merge pull request #51770 from Shopify/gc-time 

Replace allocations count by GC time in request logs
This commit is contained in:
Jean Boussier 2024-05-08 23:36:02 +02:00 committed by GitHub
parent 07e40ea316 06d3b358df
commit 25f22503af
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
5 changed files with 32 additions and 12 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
actionpack/lib/action_controller/log_subscriber.rb
View File

@ -33,7 +33,7 @@ module ActionController
status = ActionDispatch::ExceptionWrapper.status_code_for_exception(exception_class_name)
end
additions << "Allocations: #{event.allocations}"
additions << "GC: #{event.gc_time.round(1)}ms"
message = +"Completed #{status} #{Rack::Utils::HTTP_STATUS_CODES[status]} in #{event.duration.round}ms" \
" (#{additions.join(" | ")})"

8
actionview/lib/action_view/log_subscriber.rb
View File

@ -18,7 +18,7 @@ module ActionView
info do
message = +" Rendered #{from_rails_root(event.payload[:identifier])}"
message << " within #{from_rails_root(event.payload[:layout])}" if event.payload[:layout]
message << " (Duration: #{event.duration.round(1)}ms | Allocations: #{event.allocations})"
message << " (Duration: #{event.duration.round(1)}ms | GC: #{event.gc_time.round(1)}ms)"
end
end
subscribe_log_level :render_template, :debug
@ -27,7 +27,7 @@ module ActionView
debug do
message = +" Rendered #{from_rails_root(event.payload[:identifier])}"
message << " within #{from_rails_root(event.payload[:layout])}" if event.payload[:layout]
message << " (Duration: #{event.duration.round(1)}ms | Allocations: #{event.allocations})"
message << " (Duration: #{event.duration.round(1)}ms | GC: #{event.gc_time.round(1)}ms)"
message << " #{cache_message(event.payload)}" unless event.payload[:cache_hit].nil?
message
end
@ -37,7 +37,7 @@ module ActionView
def render_layout(event)
info do
message = +" Rendered layout #{from_rails_root(event.payload[:identifier])}"
message << " (Duration: #{event.duration.round(1)}ms | Allocations: #{event.allocations})"
message << " (Duration: #{event.duration.round(1)}ms | GC: #{event.gc_time.round(1)}ms)"
end
end
subscribe_log_level :render_layout, :info
@ -48,7 +48,7 @@ module ActionView
debug do
message = +" Rendered collection of #{from_rails_root(identifier)}"
message << " within #{from_rails_root(event.payload[:layout])}" if event.payload[:layout]
message << " #{render_count(event.payload)} (Duration: #{event.duration.round(1)}ms | Allocations: #{event.allocations})"
message << " #{render_count(event.payload)} (Duration: #{event.duration.round(1)}ms | GC: #{event.gc_time.round(1)}ms)"
message
end
end

10
actionview/test/activerecord/controller_runtime_test.rb
View File

@ -68,7 +68,7 @@ class ControllerRuntimeLogSubscriberTest < ActionController::TestCase
wait
assert_equal 2, @logger.logged(:info).size
assert_match(/\(Views: [\d.]+ms \| ActiveRecord: [\d.]+ms \(0 queries, 0 cached\) \| Allocations: [\d.]+\)/, @logger.logged(:info)[1])
assert_match(/\(Views: [\d.]+ms \| ActiveRecord: [\d.]+ms \(0 queries, 0 cached\) \| GC: [\d.]+ms\)/, @logger.logged(:info)[1])
end
def test_runtime_reset_before_requests
@ -77,20 +77,20 @@ class ControllerRuntimeLogSubscriberTest < ActionController::TestCase
wait
assert_equal 2, @logger.logged(:info).size
assert_match(/\(Views: [\d.]+ms \| ActiveRecord: [\d.]+ms \(0 queries, 0 cached\) \| Allocations: [\d.]+\)/, @logger.logged(:info)[1])
assert_match(/\(Views: [\d.]+ms \| ActiveRecord: [\d.]+ms \(0 queries, 0 cached\) \| GC: [\d.]+ms\)/, @logger.logged(:info)[1])
end
def test_log_with_active_record_when_post
post :create
wait
assert_match(/ActiveRecord: ([1-9][\d.]+)ms \(1 query, 0 cached\) \| Allocations: [\d.]+\)/, @logger.logged(:info)[2])
assert_match(/ActiveRecord: ([1-9][\d.]+)ms \(1 query, 0 cached\) \| GC: [\d.]+ms\)/, @logger.logged(:info)[2])
end
def test_log_with_active_record_when_redirecting
get :redirect
wait
assert_equal 3, @logger.logged(:info).size
assert_match(/\(ActiveRecord: [\d.]+ms \(0 queries, 0 cached\) \| Allocations: [\d.]+\)/, @logger.logged(:info)[2])
assert_match(/\(ActiveRecord: [\d.]+ms \(0 queries, 0 cached\) \| GC: [\d.]+ms\)/, @logger.logged(:info)[2])
end
def test_include_time_query_time_after_rendering
@ -98,6 +98,6 @@ class ControllerRuntimeLogSubscriberTest < ActionController::TestCase
wait
assert_equal 2, @logger.logged(:info).size
assert_match(/\(Views: [\d.]+ms \| ActiveRecord: ([1-9][\d.]+)ms \(1 query, 0 cached\) \| Allocations: [\d.]+\)/, @logger.logged(:info)[1])
assert_match(/\(Views: [\d.]+ms \| ActiveRecord: ([1-9][\d.]+)ms \(1 query, 0 cached\) \| GC: [\d.]+ms\)/, @logger.logged(:info)[1])
end
end

4
actionview/test/template/log_subscriber_test.rb
View File

@ -186,14 +186,14 @@ class AVLogSubscriberTest < ActiveSupport::TestCase
wait
*, cached_inner, uncached_outer = @logger.logged(:debug)
assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache miss\]/, cached_inner)
assert_match(/Rendered test\/_nested_cached_customer\.erb \(Duration: .*?ms \| Allocations: .*?\)$/, uncached_outer)
assert_match(/Rendered test\/_nested_cached_customer\.erb \(Duration: .*?ms \| GC: .*?\)$/, uncached_outer)
# Second render hits the cache for the _cached_customer partial. Outer template's log shouldn't be affected.
@view.render(partial: "test/nested_cached_customer", locals: { cached_customer: Customer.new("Stan") })
wait
*, cached_inner, uncached_outer = @logger.logged(:debug)
assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache hit\]/, cached_inner)
assert_match(/Rendered test\/_nested_cached_customer\.erb \(Duration: .*?ms \| Allocations: .*?\)$/, uncached_outer)
assert_match(/Rendered test\/_nested_cached_customer\.erb \(Duration: .*?ms \| GC: .*?\)$/, uncached_outer)
end
end

20
activesupport/lib/active_support/notifications/instrumenter.rb
View File

@ -117,6 +117,8 @@ module ActiveSupport
@cpu_time_finish = 0.0
@allocation_count_start = 0
@allocation_count_finish = 0
@gc_time_start = 0
@gc_time_finish = 0
end
def time
@ -144,12 +146,14 @@ module ActiveSupport
def start!
@time = now
@cpu_time_start = now_cpu
@gc_time_start = now_gc
@allocation_count_start = now_allocations
end
# Record information at the time this event finishes
def finish!
@cpu_time_finish = now_cpu
@gc_time_finish = now_gc
@end = now
@allocation_count_finish = now_allocations
end
@ -173,6 +177,12 @@ module ActiveSupport
@allocation_count_finish - @allocation_count_start
end
# Returns the time spent in GC (in milliseconds) between the call to #start!
# and the call to #finish!
def gc_time
(@gc_time_finish - @gc_time_start) / 1_000_000.0
end
# Returns the difference in milliseconds between when the execution of the
# event started and when it ended.
#
@ -206,6 +216,16 @@ module ActiveSupport
end
end
if GC.respond_to?(:total_time)
def now_gc
GC.total_time
end
else
def now_gc
0
end
end
if GC.stat.key?(:total_allocated_objects)
def now_allocations
GC.stat(:total_allocated_objects)