4 files changed, 32 insertions, 10 deletions
diff --git a/actionmailer/CHANGELOG.md b/actionmailer/CHANGELOG.md
index 1659696bfb..d84b95e6e9 100644
--- a/actionmailer/CHANGELOG.md
+++ b/actionmailer/CHANGELOG.md
@@ -1,3 +1,8 @@
+* Instrument the generation of Action Mailer messages. The time it takes to
+  generate a message is written to the log.
+
+  *Daniel Schierbeck*
+
 * invoke mailer defaults as procs only if they are procs, do not convert
   with to_proc.  That an object is convertible to a proc does not mean it's
   meant to be always used as a proc.  Fixes #11533
diff --git a/actionmailer/lib/action_mailer/base.rb b/actionmailer/lib/action_mailer/base.rb
index ada86fbc4f..becd4126f4 100644
--- a/actionmailer/lib/action_mailer/base.rb
+++ b/actionmailer/lib/action_mailer/base.rb
@@ -511,11 +511,18 @@ module ActionMailer
       process(method_name, *args) if method_name
     end
 
-    def process(*args) #:nodoc:
-      lookup_context.skip_default_locale!
+    def process(method_name, *args) #:nodoc:
+      payload = {
+        :mailer => self.class.name,
+        :action => method_name
+      }
 
-      super
-      @_message = NullMail.new unless @_mail_was_called
+      ActiveSupport::Notifications.instrument("process.action_mailer", payload) do
+        lookup_context.skip_default_locale!
+
+        super
+        @_message = NullMail.new unless @_mail_was_called
+      end
     end
 
     class NullMail #:nodoc:
@@ -685,9 +692,9 @@ module ActionMailer
       content_type = headers[:content_type]
 
       # Call all the procs (if any)
-      class_default = self.class.default
-      default_values = class_default.merge(class_default) do |k,v|
-        v.is_a?(Proc) ? instance_eval(&v) : v
+      default_values = {}
+      self.class.default.each do |k,v|
+        default_values[k] = v.is_a?(Proc) ? instance_eval(&v) : v
       end
 
       # Handle defaults
diff --git a/actionmailer/lib/action_mailer/log_subscriber.rb b/actionmailer/lib/action_mailer/log_subscriber.rb
index 8467d45986..eb6fb11d81 100644
--- a/actionmailer/lib/action_mailer/log_subscriber.rb
+++ b/actionmailer/lib/action_mailer/log_subscriber.rb
@@ -19,6 +19,13 @@ module ActionMailer
       debug(event.payload[:mail])
     end
 
+    # An email was generated.
+    def process(event)
+      mailer = event.payload[:mailer]
+      action = event.payload[:action]
+      debug("\n#{mailer}##{action}: processed outbound mail in #{event.duration.round(1)}ms")
+    end
+
     # Use the logger configured for ActionMailer::Base
     def logger
       ActionMailer::Base.logger
diff --git a/actionmailer/test/log_subscriber_test.rb b/actionmailer/test/log_subscriber_test.rb
index 5f52a1bd69..5f0bee88fd 100644
--- a/actionmailer/test/log_subscriber_test.rb
+++ b/actionmailer/test/log_subscriber_test.rb
@@ -24,10 +24,13 @@ class AMLogSubscriberTest < ActionMailer::TestCase
   def test_deliver_is_notified
     BaseMailer.welcome.deliver
     wait
+
     assert_equal(1, @logger.logged(:info).size)
     assert_match(/Sent mail to system@test.lindsaar.net/, @logger.logged(:info).first)
-    assert_equal(1, @logger.logged(:debug).size)
-    assert_match(/Welcome/, @logger.logged(:debug).first)
+
+    assert_equal(2, @logger.logged(:debug).size)
+    assert_match(/BaseMailer#welcome: processed outbound mail in [\d.]+ms/, @logger.logged(:debug).first)
+    assert_match(/Welcome/, @logger.logged(:debug).second)
   end
 
   def test_receive_is_notified
@@ -39,4 +42,4 @@ class AMLogSubscriberTest < ActionMailer::TestCase
     assert_equal(1, @logger.logged(:debug).size)
     assert_match(/Jamis/, @logger.logged(:debug).first)
   end
-end
-\ No newline at end of file
+end