Mark the start of rendering in the log #23710

dhh · 2016-02-16T15:00:38Z

It would be helpful to know in the log when rendering of the view templates started, so you can quickly glance and see which SQL and other calls are happening in the controller and which are being triggered in the view. I propose:

Processing by My::Navigation::ChatsController#index as HTML
  Person Load (0.2ms)  SELECT  `people`.* FROM `people` WHERE `people`.`personable_id` = 950737458 AND `people`.`personable_type` = 'User' LIMIT 1
View ->
  Recording Load (0.2ms)  SELECT  `recordings`.* FROM `recordings` WHERE `recordings`.`id` = 9007199254741011 LIMIT 1
  Rendered my/navigation/chats/_bookmark.html.erb (3.6ms)
Completed 200 OK in 529ms (Views: 24.8ms | ActiveRecord: 30.1ms)

The text was updated successfully, but these errors were encountered:

matthewd · 2016-02-16T15:09:45Z

Rendering my/navigation/chats/index.html.erb ?

vipulnsward · 2016-02-16T15:13:35Z

Working on this

dhh · 2016-02-16T15:22:57Z

Like @matthewd's suggestion! That's even better and explains which template kicks things off. Make sure that this log call is set back at the root, not indented 2 chars, btw.

vipulnsward · 2016-02-16T16:05:54Z

This can grow up the logs pretty fast-

[425c28c2-5f2f-4bc0-a5eb-4afc316d7021] Started GET "/" for 127.0.0.1 at 2016-02-16 21:32:53 +0530
[425c28c2-5f2f-4bc0-a5eb-4afc316d7021] Processing by HomeController#index as HTML
[425c28c2-5f2f-4bc0-a5eb-4afc316d7021]   Rendering home/index.html.erb within layouts/application
[425c28c2-5f2f-4bc0-a5eb-4afc316d7021]   Rendering home/_heading.html.erb
[425c28c2-5f2f-4bc0-a5eb-4afc316d7021]   Rendered home/_heading.html.erb (0.1ms)
[425c28c2-5f2f-4bc0-a5eb-4afc316d7021]   Rendering home/_development.html.erb
[425c28c2-5f2f-4bc0-a5eb-4afc316d7021]   Rendered home/_development.html.erb (1.4ms)
[425c28c2-5f2f-4bc0-a5eb-4afc316d7021]   Rendering home/_clients.html.erb
[425c28c2-5f2f-4bc0-a5eb-4afc316d7021]   Rendered home/_clients.html.erb (16.5ms)
[425c28c2-5f2f-4bc0-a5eb-4afc316d7021]   Rendering home/_team.html.erb
[425c28c2-5f2f-4bc0-a5eb-4afc316d7021]    (0.4ms)  SELECT COUNT(*) FROM "videos"
[425c28c2-5f2f-4bc0-a5eb-4afc316d7021]   Rendered home/_team.html.erb (4.8ms)
[425c28c2-5f2f-4bc0-a5eb-4afc316d7021]   Rendered home/index.html.erb within layouts/application (29.6ms)
[425c28c2-5f2f-4bc0-a5eb-4afc316d7021]   Rendering layouts/_header.html.erb
[425c28c2-5f2f-4bc0-a5eb-4afc316d7021]   Rendered layouts/_header.html.erb (1.6ms)
[425c28c2-5f2f-4bc0-a5eb-4afc316d7021]   Rendering layouts/_footer.html.erb
[425c28c2-5f2f-4bc0-a5eb-4afc316d7021]   Rendering layouts/_new_footer.html.erb
[425c28c2-5f2f-4bc0-a5eb-4afc316d7021]   Rendered layouts/_new_footer.html.erb (0.7ms)
[425c28c2-5f2f-4bc0-a5eb-4afc316d7021]   Rendered layouts/_footer.html.erb (2.1ms)
[425c28c2-5f2f-4bc0-a5eb-4afc316d7021]   Rendering layouts/_analytics.html.erb
[425c28c2-5f2f-4bc0-a5eb-4afc316d7021]   Rendered layouts/_analytics.html.erb (0.0ms)
[425c28c2-5f2f-4bc0-a5eb-4afc316d7021] Completed 200 OK in 99ms (Views: 65.7ms | ActiveRecord: 0.4ms)

kaspth · 2016-02-16T16:08:48Z

Think @dhh just wanted to mark when rendering began once. So it can be viewed as a separate step in the request, not tiny pebbles of rendering.

matthewd · 2016-02-16T16:13:52Z

Possibly relevant/related:

rails/actionpack/lib/action_controller/metal/implicit_render.rb

Line 24 in b0b61b6

    
           logger.info "No template found for #{self.class.name}\##{action_name}, rendering head :no_content" if logger

bogdan · 2016-02-16T16:32:21Z

Current log format of rendering is terrible. We can make it far better because we already have nicely formed example of SQL logging.

I have cooler format suggestion that I am using in my project to make a group of start and finish event more obvious.

Full screen example: https://monosnap.com/file/VPv1JekywXEpVePm85o8HHHpfmoCHE.png

It makes it easier to catch the beginning and end of a rendering:

Use a format similar to SQL that use to dominate the log and make it more organic
Use contrast color to distinguish from SQL
Try to align view name to the same console column so that begin and end event packed together look beautiful

So the format I propose is:

Render (Start)  home/_development.html.erb
Render (1.4ms)  home/_development.html.erb
Render (Start)  home/_clients.html.erb
Render (16.5ms) home/_clients.html.erb

dhh · 2016-02-16T17:07:06Z

Yeah, I was only looking for start of rendering when the controller first
calls the template. Not for all the partial renderings.

On Tue, Feb 16, 2016 at 5:33 PM, Bogdan Gusiev notifications@github.com
wrote:

Current log format of rendering is terrible. We can make it far better
because we already have nicely formed example of SQL logging.

I have cooler format suggestion that I am using in my project to make a
group of start and finish event more obvious.

[image: image]
https://cloud.githubusercontent.com/assets/122436/13082752/a60131ea-d4da-11e5-956e-2f0e69759d61.png

It makes it easier to catch the beginning and end of a rendering:

Use a format similar to SQL that use to dominate the log and make it
more organic

Use contrast color to distinguish from SQL

Try to align view name to the same console column so that begin and
end event packed together look beautiful

So the format I propose is:

Render (Start) home/_development.html.erb
Render (1.4ms) home/_development.html.erb
Render (Start) home/_clients.html.erb
Render (16.5ms) home/_clients.html.erb

—
Reply to this email directly or view it on GitHub
#23710 (comment).

vipulnsward · 2016-02-16T17:25:18Z

How does this look?

[380bbb21-79d8-426f-a570-72f3f71b13fd] Processing by HomeController#index as HTML
[380bbb21-79d8-426f-a570-72f3f71b13fd]    (0.4ms)  SELECT COUNT(*) FROM "videos" ,<- This was called from controller
[380bbb21-79d8-426f-a570-72f3f71b13fd]   Rendering home/index.html.erb within layouts/application
[380bbb21-79d8-426f-a570-72f3f71b13fd]   Rendered home/_heading.html.erb (0.1ms)
[380bbb21-79d8-426f-a570-72f3f71b13fd]   Rendered home/_development.html.erb (0.2ms)
[380bbb21-79d8-426f-a570-72f3f71b13fd]   Rendered home/_clients.html.erb (5.2ms)
[380bbb21-79d8-426f-a570-72f3f71b13fd]   CACHE (0.0ms)  SELECT COUNT(*) FROM "videos" <- This was called from view
[380bbb21-79d8-426f-a570-72f3f71b13fd]   Rendered home/_team.html.erb (0.9ms)
[380bbb21-79d8-426f-a570-72f3f71b13fd]   Rendered home/index.html.erb within layouts/application (11.6ms)
[380bbb21-79d8-426f-a570-72f3f71b13fd]   Rendered layouts/_header.html.erb (0.5ms)
[380bbb21-79d8-426f-a570-72f3f71b13fd]   Rendered layouts/_new_footer.html.erb (0.5ms)
[380bbb21-79d8-426f-a570-72f3f71b13fd]   Rendered layouts/_footer.html.erb (1.7ms)
[380bbb21-79d8-426f-a570-72f3f71b13fd]   Rendered layouts/_analytics.html.erb (0.0ms)
[380bbb21-79d8-426f-a570-72f3f71b13fd] Completed 200 OK in 75ms (Views: 40.9ms | ActiveRecord: 1.2ms)

Its called once on (render_template with layouts)[https://github.com/vipulnsward/rails/blob/b7758b40fc035a47f6843158155606d455314c42/actionview/lib/action_view/renderer/template_renderer.rb#L52-L52]

dhh · 2016-02-16T17:33:26Z

Just need to not indent that Rendering home/index.html.erb line.

On Tue, Feb 16, 2016 at 6:26 PM, Vipul A M notifications@github.com wrote:

How does this look?

[380bbb21-79d8-426f-a570-72f3f71b13fd] Processing by HomeController#index as HTML
380bbb21-79d8-426f-a570-72f3f71b13fd SELECT COUNT(_) FROM "videos" ,<- This was called from controller
[380bbb21-79d8-426f-a570-72f3f71b13fd] Rendering home/index.html.erb within layouts/application
[380bbb21-79d8-426f-a570-72f3f71b13fd] Rendered home/_heading.html.erb (0.1ms)
[380bbb21-79d8-426f-a570-72f3f71b13fd] Rendered home/_development.html.erb (0.2ms)
[380bbb21-79d8-426f-a570-72f3f71b13fd] Rendered home/clients.html.erb (5.2ms)
[380bbb21-79d8-426f-a570-72f3f71b13fd] CACHE (0.0ms) SELECT COUNT() FROM "videos" <- This was called from view
[380bbb21-79d8-426f-a570-72f3f71b13fd] Rendered home/_team.html.erb (0.9ms)
[380bbb21-79d8-426f-a570-72f3f71b13fd] Rendered home/index.html.erb within layouts/application (11.6ms)
[380bbb21-79d8-426f-a570-72f3f71b13fd] Rendered layouts/_header.html.erb (0.5ms)
[380bbb21-79d8-426f-a570-72f3f71b13fd] Rendered layouts/_new_footer.html.erb (0.5ms)
[380bbb21-79d8-426f-a570-72f3f71b13fd] Rendered layouts/_footer.html.erb (1.7ms)
[380bbb21-79d8-426f-a570-72f3f71b13fd] Rendered layouts/_analytics.html.erb (0.0ms)
[380bbb21-79d8-426f-a570-72f3f71b13fd] Completed 200 OK in 75ms (Views: 40.9ms | ActiveRecord: 1.2ms)

Its called once on (render_template with layouts)[
https://github.com/vipulnsward/rails/blob/b7758b40fc035a47f6843158155606d455314c42/actionview/lib/action_view/renderer/template_renderer.rb#L52-L52
]

—
Reply to this email directly or view it on GitHub
#23710 (comment).

dhh · 2016-02-16T17:35:35Z

@bogdan I think have two lines for every partial is too busy for my taste, and I don't think having the timing inbetween helps the readability either.

… that we have started to render something, at the very beginning. This helps to easily identify queries from controller vs views Fixes rails#23710

bogdan · 2016-02-16T18:35:39Z

@dhh why do you think SQL timing is better upfront and partial timing at the end?

dhh · 2016-02-16T18:46:50Z

Just reads better to me: "Rendered THIS in THAT amount of time".

On Feb 16, 2016, at 19:37, Bogdan Gusiev notifications@github.com wrote:

@dhh why do you think SQL timing is better upfront and partial timing at the end?

—
Reply to this email directly or view it on GitHub.

bogdan · 2016-02-16T18:49:14Z

Ok, so why SQL is different from that? Why it is not Executed <query> in THAT amount of time ? What is the conceptual difference?

dhh · 2016-02-16T19:07:12Z

Because for SQL it's not trying to be a sentence. There's no logging verb. Also, SQL statements are often long, possibly multiline (which could make it unclear re: timing stamp). Rendering doesn't have that problem.

On Feb 16, 2016, at 19:50, Bogdan Gusiev notifications@github.com wrote:

Ok, so why SQL is different from that? Why it is not Executed in THAT amount of time ? What is the conceptual difference?

—
Reply to this email directly or view it on GitHub.

bogdan · 2016-02-16T19:34:30Z

That sounds as a pretty weak argument. SQL is trying to be a sentence more than any other language.
Logging verb is either select, update, delete or commit. Even ruby is not that readable.

I think we put timing upfront in SQL because we care more because in most cases this is what causing a slow performance.
View timing is a more rare issue. But I argue that you will get to know a lot about your rendering if you put it upfront.

dhh · 2016-02-16T20:03:23Z

Guess we will just have to agree to disagree on this one.

On Feb 16, 2016, at 20:36, Bogdan Gusiev notifications@github.com wrote:

That sounds as a pretty weak argument. SQL is trying to be a sentence more than any other language.
Logging verb is either select, update, delete or commit. Even ruby is not that readable.

I think we put timing upfront in SQL because we care more because in most cases this is what causing a slow performance.
View timing is a more rare issue. But I argue that you will get to know a lot about your rendering if you put it upfront.

—
Reply to this email directly or view it on GitHub.

… that we have started to render something, at the very beginning. This helps to easily identify queries from controller vs views Fixes rails#23710

rafaelfranca · 2016-02-26T19:08:27Z

Done

dhh added the actionpack label Feb 16, 2016

vipulnsward mentioned this issue Feb 16, 2016

Added log "Rendering ...", when starting to render a template #23717

Closed

vipulnsward added the attached PR label Feb 16, 2016

rafaelfranca closed this as completed Feb 26, 2016

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Mark the start of rendering in the log #23710

Mark the start of rendering in the log #23710

dhh commented Feb 16, 2016

matthewd commented Feb 16, 2016

vipulnsward commented Feb 16, 2016

dhh commented Feb 16, 2016

vipulnsward commented Feb 16, 2016

kaspth commented Feb 16, 2016

matthewd commented Feb 16, 2016

bogdan commented Feb 16, 2016

dhh commented Feb 16, 2016

vipulnsward commented Feb 16, 2016

dhh commented Feb 16, 2016

dhh commented Feb 16, 2016

bogdan commented Feb 16, 2016

dhh commented Feb 16, 2016

bogdan commented Feb 16, 2016

dhh commented Feb 16, 2016

bogdan commented Feb 16, 2016

dhh commented Feb 16, 2016

rafaelfranca commented Feb 26, 2016

Mark the start of rendering in the log #23710

Mark the start of rendering in the log #23710

Comments

dhh commented Feb 16, 2016

matthewd commented Feb 16, 2016

vipulnsward commented Feb 16, 2016

dhh commented Feb 16, 2016

vipulnsward commented Feb 16, 2016

kaspth commented Feb 16, 2016

matthewd commented Feb 16, 2016

bogdan commented Feb 16, 2016

dhh commented Feb 16, 2016

vipulnsward commented Feb 16, 2016

dhh commented Feb 16, 2016

dhh commented Feb 16, 2016

bogdan commented Feb 16, 2016

dhh commented Feb 16, 2016

bogdan commented Feb 16, 2016

dhh commented Feb 16, 2016

bogdan commented Feb 16, 2016

dhh commented Feb 16, 2016

rafaelfranca commented Feb 26, 2016