Fix elapsed time calculations

I've found a few places in Rails code base where I think it makes sense
to calculate elapsed time more precisely by using
`Concurrent.monotonic_time`:

- Fix calculation of elapsed time in `ActiveSupport::Cache::MemoryStore#prune`
- Fix calculation of elapsed time in
  `ActiveRecord::ConnectionAdapters::ConnectionPool::Queue#wait_poll`
- Fix calculation of elapsed time in
  `ActiveRecord::ConnectionAdapters::ConnectionPool#attempt_to_checkout_all_existing_connections`
- Fix calculation of elapsed time in `ActiveRecord::ConnectionAdapters::Mysql2Adapter#explain`

See
https://docs.ruby-lang.org/en/2.5.0/Process.html#method-c-clock_gettime
https://blog.dnsimple.com/2018/03/elapsed-time-with-ruby-the-right-way

Related to 7c4542146f
This commit is contained in:
bogdanvlviv 2018-12-04 23:24:23 +02:00
parent b67d5c6ded
commit dda9452314
No known key found for this signature in database
GPG Key ID: E4ACD76A6DB6DFDD
4 changed files with 9 additions and 9 deletions

View File

@ -185,7 +185,7 @@ module ActiveRecord
def wait_poll(timeout)
@num_waiting += 1
t0 = Time.now
t0 = Concurrent.monotonic_time
elapsed = 0
loop do
ActiveSupport::Dependencies.interlock.permit_concurrent_loads do
@ -194,7 +194,7 @@ module ActiveRecord
return remove if any?
elapsed = Time.now - t0
elapsed = Concurrent.monotonic_time - t0
if elapsed >= timeout
msg = "could not obtain a connection from the pool within %0.3f seconds (waited %0.3f seconds); all pooled connections were in use" %
[timeout, elapsed]
@ -686,13 +686,13 @@ module ActiveRecord
end
newly_checked_out = []
timeout_time = Time.now + (@checkout_timeout * 2)
timeout_time = Concurrent.monotonic_time + (@checkout_timeout * 2)
@available.with_a_bias_for(Thread.current) do
loop do
synchronize do
return if collected_conns.size == @connections.size && @now_connecting == 0
remaining_timeout = timeout_time - Time.now
remaining_timeout = timeout_time - Concurrent.monotonic_time
remaining_timeout = 0 if remaining_timeout < 0
conn = checkout_for_exclusive_access(remaining_timeout)
collected_conns << conn

View File

@ -166,9 +166,9 @@ module ActiveRecord
def explain(arel, binds = [])
sql = "EXPLAIN #{to_sql(arel, binds)}"
start = Time.now
start = Concurrent.monotonic_time
result = exec_query(sql, "EXPLAIN", binds)
elapsed = Time.now - start
elapsed = Concurrent.monotonic_time - start
MySQL::ExplainPrettyPrinter.new.pp(result, elapsed)
end

View File

@ -62,13 +62,13 @@ module ActiveSupport
return if pruning?
@pruning = true
begin
start_time = Time.now
start_time = Concurrent.monotonic_time
cleanup
instrument(:prune, target_size, from: @cache_size) do
keys = synchronize { @key_access.keys.sort { |a, b| @key_access[a].to_f <=> @key_access[b].to_f } }
keys.each do |key|
delete_entry(key, options)
return if @cache_size <= target_size || (max_time && Time.now - start_time > max_time)
return if @cache_size <= target_size || (max_time && Concurrent.monotonic_time - start_time > max_time)
end
end
ensure

View File

@ -137,7 +137,7 @@ module ActiveSupport
private
def now
Process.clock_gettime(Process::CLOCK_MONOTONIC)
Concurrent.monotonic_time
end
if clock_gettime_supported?