Skip to content
Browse files

Merge commit 'mainstream/master'

  • Loading branch information...
2 parents af04ea8 + 227ee2e commit 1990f815bc624a95d447cdb7de3e0f42bcd81db9 @lifo lifo committed Sep 5, 2008
View
12 actionpack/CHANGELOG
@@ -1,5 +1,17 @@
*Edge*
+* Changed the X-Runtime header to report in milliseconds [DHH]
+
+* Changed BenchmarkHelper#benchmark to report in milliseconds [DHH]
+
+* Changed logging format to be millisecond based and skip misleading stats [DHH]. Went from:
+
+ Completed in 0.10000 (4 reqs/sec) | Rendering: 0.04000 (40%) | DB: 0.00400 (4%) | 200 OK [http://example.com]
+
+ ...to:
+
+ Completed in 100ms (View: 40, DB: 4) | 200 OK [http://example.com]
+
* Add support for shallow nesting of routes. #838 [S. Brent Faulkner]
Example :
View
60 actionpack/lib/action_controller/benchmarking.rb
@@ -24,7 +24,7 @@ def benchmark(title, log_level = Logger::DEBUG, use_silence = true)
if logger && logger.level == log_level
result = nil
seconds = Benchmark.realtime { result = use_silence ? silence { yield } : yield }
- logger.add(log_level, "#{title} (#{'%.5f' % seconds})")
+ logger.add(log_level, "#{title} (#{('%.1f' % (seconds * 1000))}ms)")
result
else
yield
@@ -42,53 +42,65 @@ def silence
protected
def render_with_benchmark(options = nil, extra_options = {}, &block)
- unless logger
- render_without_benchmark(options, extra_options, &block)
- else
- db_runtime = ActiveRecord::Base.connection.reset_runtime if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected?
+ if logger
+ if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected?
+ db_runtime = ActiveRecord::Base.connection.reset_runtime
+ end
render_output = nil
- @rendering_runtime = Benchmark::realtime{ render_output = render_without_benchmark(options, extra_options, &block) }
+ @view_runtime = Benchmark::realtime { render_output = render_without_benchmark(options, extra_options, &block) }
if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected?
@db_rt_before_render = db_runtime
@db_rt_after_render = ActiveRecord::Base.connection.reset_runtime
- @rendering_runtime -= @db_rt_after_render
+ @view_runtime -= @db_rt_after_render
end
render_output
+ else
+ render_without_benchmark(options, extra_options, &block)
end
end
private
def perform_action_with_benchmark
- unless logger
- perform_action_without_benchmark
- else
- runtime = [ Benchmark::measure{ perform_action_without_benchmark }.real, 0.0001 ].max
+ if logger
+ seconds = [ Benchmark::measure{ perform_action_without_benchmark }.real, 0.0001 ].max
+ logging_view = defined?(@view_runtime)
+ logging_active_record = Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected?
+
+ log_message = "Completed in #{sprintf("%.0f", seconds * 1000)}ms"
+
+ if logging_view || logging_active_record
+ log_message << " ("
+ log_message << view_runtime if logging_view
+
+ if logging_active_record
+ log_message << ", " + active_record_runtime + ")"
+ else
+ ")"
+ end
+ end
- log_message = "Completed in #{sprintf("%.5f", runtime)} (#{(1 / runtime).floor} reqs/sec)"
- log_message << rendering_runtime(runtime) if defined?(@rendering_runtime)
- log_message << active_record_runtime(runtime) if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected?
log_message << " | #{headers["Status"]}"
log_message << " [#{complete_request_uri rescue "unknown"}]"
logger.info(log_message)
- response.headers["X-Runtime"] = sprintf("%.5f", runtime)
+ response.headers["X-Runtime"] = "#{sprintf("%.0f", seconds * 1000)}ms"
+ else
+ perform_action_without_benchmark
end
end
- def rendering_runtime(runtime)
- percentage = @rendering_runtime * 100 / runtime
- " | Rendering: %.5f (%d%%)" % [@rendering_runtime, percentage.to_i]
+ def view_runtime
+ "View: %.0f" % (@view_runtime * 1000)
end
- def active_record_runtime(runtime)
- db_runtime = ActiveRecord::Base.connection.reset_runtime
- db_runtime += @db_rt_before_render if @db_rt_before_render
- db_runtime += @db_rt_after_render if @db_rt_after_render
- db_percentage = db_runtime * 100 / runtime
- " | DB: %.5f (%d%%)" % [db_runtime, db_percentage.to_i]
+ def active_record_runtime
+ db_runtime = ActiveRecord::Base.connection.reset_runtime
+ db_runtime += @db_rt_before_render if @db_rt_before_render
+ db_runtime += @db_rt_after_render if @db_rt_after_render
+ "DB: %.0f" % (db_runtime * 1000)
end
end
end
View
6 actionpack/lib/action_view/helpers/benchmark_helper.rb
@@ -15,15 +15,15 @@ module BenchmarkHelper
# <%= expensive_files_operation %>
# <% end %>
#
- # That would add something like "Process data files (0.34523)" to the log,
+ # That would add something like "Process data files (345.2ms)" to the log,
# which you can then use to compare timings when optimizing your code.
#
# You may give an optional logger level as the second argument
# (:debug, :info, :warn, :error); the default value is :info.
def benchmark(message = "Benchmarking", level = :info)
if controller.logger
- real = Benchmark.realtime { yield }
- controller.logger.send(level, "#{message} (#{'%.5f' % real})")
+ seconds = Benchmark.realtime { yield }
+ controller.logger.send(level, "#{message} (#{'%.1f' % (seconds * 1000)}ms)")
else
yield
end
View
2 activerecord/CHANGELOG
@@ -1,5 +1,7 @@
*Edge*
+* Changed benchmarks to be reported in milliseconds [DHH]
+
* Connection pooling. #936 [Nick Sieger]
* Merge scoped :joins together instead of overwriting them. May expose scoping bugs in your code! #501 [Andrew White]
View
2 activerecord/lib/active_record/base.rb
@@ -1313,7 +1313,7 @@ def benchmark(title, log_level = Logger::DEBUG, use_silence = true)
if logger && logger.level <= log_level
result = nil
seconds = Benchmark.realtime { result = use_silence ? silence { yield } : yield }
- logger.add(log_level, "#{title} (#{'%.5f' % seconds})")
+ logger.add(log_level, "#{title} (#{'%.1f' % (seconds * 1000)}ms)")
result
else
yield
View
11 activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb
@@ -35,7 +35,6 @@ module ConnectionAdapters
# * +wait_timeout+: number of seconds to block and wait for a connection
# before giving up and raising a timeout error (default 5 seconds).
class ConnectionPool
- delegate :verification_timeout, :to => "::ActiveRecord::Base"
attr_reader :spec
def initialize(spec)
@@ -60,7 +59,6 @@ def initialize(spec)
# held in a hash keyed by the thread id.
def connection
if conn = @reserved_connections[current_connection_id]
- conn.verify!(verification_timeout)
conn
else
@reserved_connections[current_connection_id] = checkout
@@ -118,7 +116,7 @@ def clear_reloadable_connections!
def verify_active_connections! #:nodoc:
clear_stale_cached_connections!
@connections.each do |connection|
- connection.verify!(verification_timeout)
+ connection.verify!
end
end
@@ -147,7 +145,7 @@ def checkout
if @queue.wait(@timeout)
checkout_existing_connection
else
- raise ConnectionTimeoutError, "could not obtain a database connection in a timely fashion"
+ raise ConnectionTimeoutError, "could not obtain a database connection within #{@timeout} seconds. The pool size is currently #{@size}, perhaps you need to increase it?"
end
end
end
@@ -166,8 +164,7 @@ def checkin(conn)
private
def new_connection
- config = spec.config.reverse_merge(:allow_concurrency => true)
- ActiveRecord::Base.send(spec.adapter_method, config)
+ ActiveRecord::Base.send(spec.adapter_method, spec.config)
end
def current_connection_id #:nodoc:
@@ -200,8 +197,8 @@ def checkout_existing_connection
end
def checkout_and_verify(c)
+ c.verify!
c.run_callbacks :checkout
- c.verify!(verification_timeout)
@checked_out << c
c
end
View
15 activerecord/lib/active_record/connection_adapters/abstract/connection_specification.rb
@@ -7,11 +7,6 @@ def initialize (config, adapter_method)
end
end
- # Check for activity after at least +verification_timeout+ seconds.
- # Defaults to 0 (always check.)
- cattr_accessor :verification_timeout, :instance_writer => false
- @@verification_timeout = 0
-
# The connection handler
cattr_accessor :connection_handler, :instance_writer => false
@@connection_handler = ConnectionAdapters::ConnectionHandler.new
@@ -101,6 +96,16 @@ def allow_concurrency=(flag)
ActiveSupport::Deprecation.warn("ActiveRecord::Base.allow_concurrency= has been deprecated and no longer has any effect. Please remove all references to allow_concurrency=.")
end
+ # Deprecated and no longer has any effect.
+ def verification_timeout
+ ActiveSupport::Deprecation.warn("ActiveRecord::Base.verification_timeout has been deprecated and no longer has any effect. Please remove all references to verification_timeout.")
+ end
+
+ # Deprecated and no longer has any effect.
+ def verification_timeout=(flag)
+ ActiveSupport::Deprecation.warn("ActiveRecord::Base.verification_timeout= has been deprecated and no longer has any effect. Please remove all references to verification_timeout=.")
+ end
+
# Returns the connection currently associated with the class. This can
# also be used to "borrow" the connection to do database work unrelated
# to any of the specific Active Records.
View
22 activerecord/lib/active_record/connection_adapters/abstract_adapter.rb
@@ -112,9 +112,7 @@ def disconnect!
# ROLLBACK and swallows any exceptions which is probably not enough to
# ensure the connection is clean.
def reset!
- silence_stderr do # postgres prints on stderr when you do this w/o a txn
- execute "ROLLBACK" rescue nil
- end
+ # this should be overridden by concrete adapters
end
# Returns true if its safe to reload the connection between requests for development mode.
@@ -123,14 +121,10 @@ def requires_reloading?
false
end
- # Lazily verify this connection, calling <tt>active?</tt> only if it
- # hasn't been called for +timeout+ seconds.
- def verify!(timeout)
- now = Time.now.to_i
- if (now - @last_verification) > timeout
- reconnect! unless active?
- @last_verification = now
- end
+ # Verify this connection by calling <tt>active?</tt> and reconnecting if
+ # the connection is no longer active.
+ def verify!(*ignored)
+ reconnect! unless active?
end
# Provides access to the underlying database connection. Useful for
@@ -153,10 +147,10 @@ def decrement_open_transactions
@open_transactions -= 1
end
- def log_info(sql, name, runtime)
+ def log_info(sql, name, seconds)
if @logger && @logger.debug?
- name = "#{name.nil? ? "SQL" : name} (#{sprintf("%f", runtime)})"
- @logger.debug format_log_entry(name, sql.squeeze(' '))
+ name = "#{name.nil? ? "SQL" : name} (#{sprintf("%.1f", seconds * 1000)}ms)"
+ @logger.debug(format_log_entry(name, sql.squeeze(' ')))
end
end
View
2 activerecord/lib/active_record/connection_adapters/mysql_adapter.rb
@@ -286,8 +286,6 @@ def reset!
# reset the connection is to change the user to the same user.
@connection.change_user(@config[:username], @config[:password], @config[:database])
configure_connection
- else
- super
end
end
View
39 activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb
@@ -518,6 +518,45 @@ def rollback_db_transaction
execute "ROLLBACK"
end
+ # ruby-pg defines Ruby constants for transaction status,
+ # ruby-postgres does not.
+ PQTRANS_IDLE = defined?(PGconn::PQTRANS_IDLE) ? PGconn::PQTRANS_IDLE : 0
+
+ # Check whether a transaction is active.
+ def transaction_active?
+ @connection.transaction_status != PQTRANS_IDLE
+ end
+
+ # Wrap a block in a transaction. Returns result of block.
+ def transaction(start_db_transaction = true)
+ transaction_open = false
+ begin
+ if block_given?
+ if start_db_transaction
+ begin_db_transaction
+ transaction_open = true
+ end
+ yield
+ end
+ rescue Exception => database_transaction_rollback
+ if transaction_open && transaction_active?
+ transaction_open = false
+ rollback_db_transaction
+ end
+ raise unless database_transaction_rollback.is_a? ActiveRecord::Rollback
+ end
+ ensure
+ if transaction_open && transaction_active?
+ begin
+ commit_db_transaction
+ rescue Exception => database_transaction_rollback
+ rollback_db_transaction
+ raise
+ end
+ end
+ end
+
+
# SCHEMA STATEMENTS ========================================
def recreate_database(name) #:nodoc:
View
15 activerecord/lib/active_record/test_case.rb
@@ -43,5 +43,20 @@ def assert_queries(num = 1)
def assert_no_queries(&block)
assert_queries(0, &block)
end
+
+ def self.use_concurrent_connections
+ setup :connection_allow_concurrency_setup
+ teardown :connection_allow_concurrency_teardown
+ end
+
+ def connection_allow_concurrency_setup
+ @connection = ActiveRecord::Base.remove_connection
+ ActiveRecord::Base.establish_connection(@connection.merge({:allow_concurrency => true}))
+ end
+
+ def connection_allow_concurrency_teardown
+ ActiveRecord::Base.clear_all_connections!
+ ActiveRecord::Base.establish_connection(@connection)
+ end
end
end
View
2 activerecord/test/cases/base_test.rb
@@ -880,7 +880,7 @@ def test_mass_assignment_protection
def test_mass_assignment_protection_against_class_attribute_writers
[:logger, :configurations, :primary_key_prefix_type, :table_name_prefix, :table_name_suffix, :pluralize_table_names, :colorize_logging,
- :default_timezone, :schema_format, :verification_timeout, :lock_optimistically, :record_timestamps].each do |method|
+ :default_timezone, :schema_format, :lock_optimistically, :record_timestamps].each do |method|
assert Task.respond_to?(method)
assert Task.respond_to?("#{method}=")
assert Task.new.respond_to?(method)
View
2 activerecord/test/cases/connection_test_mysql.rb
@@ -24,7 +24,7 @@ def test_successful_reconnection_after_timeout_with_verify
assert @connection.active?
@connection.update('set @@wait_timeout=1')
sleep 2
- @connection.verify!(0)
+ @connection.verify!
assert @connection.active?
end
end
View
2 activerecord/test/cases/locking_test.rb
@@ -257,6 +257,8 @@ def test_sane_lock_method
end
if current_adapter?(:PostgreSQLAdapter, :OracleAdapter)
+ use_concurrent_connections
+
def test_no_locks_no_wait
first, second = duel { Person.find 1 }
assert first.end > second.end
View
4 activerecord/test/cases/schema_authorization_test_postgresql.rb
@@ -18,8 +18,8 @@ def setup
@connection.execute "SET search_path TO '$user',public"
set_session_auth
USERS.each do |u|
- @connection.execute "CREATE USER #{u}"
- @connection.execute "CREATE SCHEMA AUTHORIZATION #{u}"
+ @connection.execute "CREATE USER #{u}" rescue nil
+ @connection.execute "CREATE SCHEMA AUTHORIZATION #{u}" rescue nil
set_session_auth u
@connection.execute "CREATE TABLE #{TABLE_NAME} (#{COLUMNS.join(',')})"
@connection.execute "INSERT INTO #{TABLE_NAME} (name) VALUES ('#{u}')"
View
3 activerecord/test/cases/transactions_test.rb
@@ -216,6 +216,7 @@ def test_manually_rolling_back_a_transaction
uses_mocha 'mocking connection.commit_db_transaction' do
def test_rollback_when_commit_raises
Topic.connection.expects(:begin_db_transaction)
+ Topic.connection.expects(:transaction_active?).returns(true) if current_adapter?(:PostgreSQLAdapter)
Topic.connection.expects(:commit_db_transaction).raises('OH NOES')
Topic.connection.expects(:rollback_db_transaction)
@@ -283,6 +284,8 @@ def remove_exception_raising_after_create_callback_to_topic
if current_adapter?(:PostgreSQLAdapter)
class ConcurrentTransactionTest < TransactionTest
+ use_concurrent_connections
+
# This will cause transactions to overlap and fail unless they are performed on
# separate database connections.
def test_transaction_per_thread
View
2 activesupport/CHANGELOG
@@ -1,5 +1,7 @@
*Edge*
+* Changed cache benchmarking to be reported in milliseconds [DHH]
+
* Fix Ruby's Time marshaling bug in pre-1.9 versions of Ruby: utc instances are now correctly unmarshaled with a utc zone instead of the system local zone [#900 state:resolved] [Luca Guidi, Geoff Buesing]
* Add Array#in_groups which splits or iterates over the array in specified number of groups. #579. [Adrian Mugnolo] Example:
View
2 activesupport/lib/active_support/cache.rb
@@ -62,7 +62,7 @@ def fetch(key, options = {})
write(key, value, options)
@logger_off = false
- log("write (will save #{'%.5f' % seconds})", key, nil)
+ log("write (will save #{'%.2f' % (seconds * 1000)}ms)", key, nil)
value
end
View
2 activesupport/lib/active_support/core_ext/time.rb
@@ -15,7 +15,7 @@ class << self
alias_method :_original_load, :_load
def _load(marshaled_time)
time = _original_load(marshaled_time)
- utc = time.send(:remove_instance_variable, '@marshal_with_utc_coercion')
+ utc = time.instance_variable_get('@marshal_with_utc_coercion')
utc ? time.utc : time
end
end
View
9 activesupport/lib/active_support/vendor/i18n-0.0.1/i18n/backend/simple.rb
@@ -4,6 +4,7 @@ module I18n
module Backend
class Simple
INTERPOLATION_RESERVED_KEYS = %w(scope default)
+ DEPRECATED_INTERPOLATORS = { '%d' => '{{count}}', '%s' => '{{value}}' }
MATCH = /(\\\\)?\{\{([^\}]+)\}\}/
# Accepts a list of paths to translation files. Loads translations from
@@ -107,7 +108,7 @@ def pluralize(locale, entry, count)
raise InvalidPluralizationData.new(entry, count) unless entry.has_key?(key)
entry[key]
end
-
+
# Interpolates values into a given string.
#
# interpolate "file {{file}} opened by \\{{user}}", :file => 'test.txt', :user => 'Mr. X'
@@ -119,7 +120,11 @@ def pluralize(locale, entry, count)
def interpolate(locale, string, values = {})
return string unless string.is_a?(String)
- string = string.gsub(/%d/, '{{count}}').gsub(/%s/, '{{value}}')
+ string = string.gsub(/%d|%s/) do |s|
+ instead = DEPRECATED_INTERPOLATORS[s]
+ ActiveSupport::Deprecation.warn "using #{s} in messages is deprecated; use #{instead} instead."
+ instead
+ end
if string.respond_to?(:force_encoding)
original_encoding = string.encoding
View
14 activesupport/test/core_ext/time_ext_test.rb
@@ -524,13 +524,12 @@ def test_time_with_datetime_fallback
assert_equal Time.time_with_datetime_fallback(:utc, 2039, 2, 21, 17, 44, 30), DateTime.civil(2039, 2, 21, 17, 44, 30, 0, 0)
assert_equal Time.time_with_datetime_fallback(:local, 2039, 2, 21, 17, 44, 30), DateTime.civil(2039, 2, 21, 17, 44, 30, DateTime.local_offset, 0)
assert_equal Time.time_with_datetime_fallback(:utc, 1900, 2, 21, 17, 44, 30), DateTime.civil(1900, 2, 21, 17, 44, 30, 0, 0)
- assert_equal Time.time_with_datetime_fallback(:local, 1900, 2, 21, 17, 44, 30), DateTime.civil(1900, 2, 21, 17, 44, 30, DateTime.local_offset, 0)
assert_equal Time.time_with_datetime_fallback(:utc, 2005), Time.utc(2005)
assert_equal Time.time_with_datetime_fallback(:utc, 2039), DateTime.civil(2039, 1, 1, 0, 0, 0, 0, 0)
assert_equal Time.time_with_datetime_fallback(:utc, 2005, 2, 21, 17, 44, 30, 1), Time.utc(2005, 2, 21, 17, 44, 30, 1) #with usec
# This won't overflow on 64bit linux
- expected_to_overflow = Time.time_with_datetime_fallback(:utc, 2039, 2, 21, 17, 44, 30, 1)
- unless expected_to_overflow.is_a?(Time)
+ unless time_is_64bits?
+ assert_equal Time.time_with_datetime_fallback(:local, 1900, 2, 21, 17, 44, 30), DateTime.civil(1900, 2, 21, 17, 44, 30, DateTime.local_offset, 0)
assert_equal Time.time_with_datetime_fallback(:utc, 2039, 2, 21, 17, 44, 30, 1),
DateTime.civil(2039, 2, 21, 17, 44, 30, 0, 0)
assert_equal ::Date::ITALY, Time.time_with_datetime_fallback(:utc, 2039, 2, 21, 17, 44, 30, 1).start # use Ruby's default start value
@@ -546,7 +545,10 @@ def test_utc_time
def test_local_time
assert_equal Time.local_time(2005, 2, 21, 17, 44, 30), Time.local(2005, 2, 21, 17, 44, 30)
assert_equal Time.local_time(2039, 2, 21, 17, 44, 30), DateTime.civil(2039, 2, 21, 17, 44, 30, DateTime.local_offset, 0)
- assert_equal Time.local_time(1901, 2, 21, 17, 44, 30), DateTime.civil(1901, 2, 21, 17, 44, 30, DateTime.local_offset, 0)
+
+ unless time_is_64bits?
+ assert_equal Time.local_time(1901, 2, 21, 17, 44, 30), DateTime.civil(1901, 2, 21, 17, 44, 30, DateTime.local_offset, 0)
+ end
end
def test_next_month_on_31st
@@ -624,6 +626,10 @@ def with_env_tz(new_tz = 'US/Eastern')
ensure
old_tz ? ENV['TZ'] = old_tz : ENV.delete('TZ')
end
+
+ def time_is_64bits?
+ Time.time_with_datetime_fallback(:utc, 2039, 2, 21, 17, 44, 30, 1).is_a?(Time)
+ end
end
class TimeExtMarshalingTest < Test::Unit::TestCase
View
7 release.rb
@@ -3,8 +3,11 @@
VERSION = ARGV.first
PACKAGES = %w(activesupport activerecord actionpack actionmailer activeresource)
-# Checkout source
-# `rm -rf release && svn export http://dev.rubyonrails.org/svn/rails/trunk release`
+# Copy source
+`mkdir release`
+(PACKAGES + %w(railties)).each do |p|
+ `cp -R #{p} release/#{p}`
+end
# Create Rails packages
`cd release/railties && rake template=jamis package`

0 comments on commit 1990f81

Please sign in to comment.
Something went wrong with that request. Please try again.