Skip to content
Permalink
Browse files

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 7c45421
  • Loading branch information...
bogdanvlviv committed Dec 4, 2018
1 parent b67d5c6 commit dda9452314bb904a3e2c850bd23f118eb80e3356
@@ -185,7 +185,7 @@ def no_wait_poll
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 @@ def wait_poll(timeout)

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 @@ def attempt_to_checkout_all_existing_connections(raise_on_acquisition_timeout =
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
@@ -166,9 +166,9 @@ def clear_cache!

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
@@ -62,13 +62,13 @@ def prune(target_size, max_time = nil)
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
@@ -137,7 +137,7 @@ def parent_of?(event)

private
def now
Process.clock_gettime(Process::CLOCK_MONOTONIC)
Concurrent.monotonic_time
end

if clock_gettime_supported?

0 comments on commit dda9452

Please sign in to comment.
You can’t perform that action at this time.