TEST_CODEOWNERS/rails
3
0
Fork 0
Code Issues Pull Requests 1 Actions Packages Projects Releases Wiki Activity

Replace allocations count by GC time in request logs

Browse Source 
Allocations count is often an interesting proxy for performance,
but not necessarily the most relevant thing to include in request
logs, given they aren't a per thread metric, so the reporting
is widely innacurate in multi-threaded environments.

Since Ruby 3.1 there is now `GC.total_time` which is a monotonically
increasing counter of time spent in GC. It still isn't really a per
thread metric, but is is more interesting because it uses the same
unit as the response time, allowing to better see when you have a GC
pause performance issue.
This commit is contained in:
Jean Boussier 2024-05-08 22:23:36 +02:00
parent 07e40ea316
commit 06d3b358df
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 @@ def process_action(event)
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 @@ def render_template(event)
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 @@ def render_partial(event)
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 @@ def render_partial(event)
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 @@ def render_collection(event)
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 @@ def test_log_with_active_record
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 @@ def test_runtime_reset_before_requests
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 @@ def test_include_time_query_time_after_rendering
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 @@ def test_render_uncached_outer_partial_with_inner_cached_partial_wont_mix_cache_
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 @@ def initialize(name, start, ending, transaction_id, payload)
@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 @@ def record # :nodoc:
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 @@ def allocations
@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 @@ def now_cpu
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)