Instrument the generation of Action Mailer messages

The processing of outbound mail is instrumented with the key
`process.action_mailer`. The payload includes the mailer name as well as
the mailer method.

4 files changed, 29 insertions, 7 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..6357805198 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:
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