Merge pull request #23915 from sikachu/pr-23710-update

Revise #23717 (Add "Rendering ..." message) using proper ActiveSupport::LogSubscriber#start

3 files changed, 30 insertions, 3 deletions

diff --git a/actionview/CHANGELOG.md b/actionview/CHANGELOG.md
index d084f2b1e0..6b77fd44f1 100644
--- a/actionview/CHANGELOG.md
+++ b/actionview/CHANGELOG.md
@@ -1,3 +1,9 @@
+*  Added log "Rendering ...", when starting to render a template to log that
+   we have started rendering something. This helps to easily identify the origin
+   of queries in the log whether they came from controller or views.
+
+   *Vipul A M and Prem Sichanugrist*
+
 ## Rails 5.0.0.beta3 (February 24, 2016) ##
 
 *   Collection rendering can cache and fetch multiple partials at once.
diff --git a/actionview/lib/action_view/log_subscriber.rb b/actionview/lib/action_view/log_subscriber.rb
index aa38db2a3a..5a29c68214 100644
--- a/actionview/lib/action_view/log_subscriber.rb
+++ b/actionview/lib/action_view/log_subscriber.rb
@@ -30,6 +30,14 @@ module ActionView
       end
     end
 
+    def start(name, id, payload)
+      if name == "render_template.action_view"
+        log_rendering_start(payload)
+      end
+
+      super
+    end
+
     def logger
       ActionView::Base.logger
     end
@@ -54,6 +62,16 @@ module ActionView
         "[#{payload[:count]} times]"
       end
     end
+
+  private
+
+    def log_rendering_start(payload)
+      info do
+        message = "  Rendering #{from_rails_root(payload[:identifier])}"
+        message << " within #{from_rails_root(payload[:layout])}" if payload[:layout]
+        message
+      end
+    end
   end
 end
 
diff --git a/actionview/test/template/log_subscriber_test.rb b/actionview/test/template/log_subscriber_test.rb
index 93a0701dcc..7683444bf0 100644
--- a/actionview/test/template/log_subscriber_test.rb
+++ b/actionview/test/template/log_subscriber_test.rb
@@ -35,7 +35,8 @@ class AVLogSubscriberTest < ActiveSupport::TestCase
       @view.render(:file => "test/hello_world")
       wait
 
-      assert_equal 1, @logger.logged(:info).size
+      assert_equal 2, @logger.logged(:info).size
+      assert_match(/Rendering test\/hello_world\.erb/, @logger.logged(:info).first)
       assert_match(/Rendered test\/hello_world\.erb/, @logger.logged(:info).last)
     end
   end
@@ -45,7 +46,8 @@ class AVLogSubscriberTest < ActiveSupport::TestCase
       @view.render(:text => "TEXT")
       wait
 
-      assert_equal 1, @logger.logged(:info).size
+      assert_equal 2, @logger.logged(:info).size
+      assert_match(/Rendering text template/, @logger.logged(:info).first)
       assert_match(/Rendered text template/, @logger.logged(:info).last)
     end
   end
@@ -55,7 +57,8 @@ class AVLogSubscriberTest < ActiveSupport::TestCase
       @view.render(:inline => "<%= 'TEXT' %>")
       wait
 
-      assert_equal 1, @logger.logged(:info).size
+      assert_equal 2, @logger.logged(:info).size
+      assert_match(/Rendering inline template/, @logger.logged(:info).first)
       assert_match(/Rendered inline template/, @logger.logged(:info).last)
     end
   end