Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Already on GitHub? Sign in to your account

Partial rendering and fragment hit rate information is available by default in Rails 3 logs, but not parsed #86

Closed
purcell opened this Issue Jan 23, 2011 · 6 comments

Comments

Projects
None yet
4 participants

purcell commented Jan 23, 2011

Hi - first of all, thanks for a great tool!

It occurred to me that fragment hit/miss information can be inferred from Rails 3 production logs without resorting to monkey-patching Rails as suggested on the wiki. Within a block for one request within a log, then if there is a "Read fragment XXXX" line without a following "Write fragment XXXX",there was a cache miss, and if there's no corresponding "Write fragment line", then there was a cache hit. (See the example log snippet below.)

I had a quick look at the code, and I'm not sure if it's possible to implement this using your current parsing scheme.

For my purposes, a breakdown of partial rendering times and fragment cache hit rates are essential to understanding the performance of my app. I was going to write my own tool for this when I came across request-log-analyzer, and concluded that it might do the trick.

Am I missing something? Is there already a way to analyze this data with r-l-a?

Started GET "/news/1664-feed-america-with-george-clooneys-bowl" for 66.249.66.142 at Sun Jan 23 05:28:39 +0000 2011
  Processing by NewsItemsController#show as */*
  Parameters: {"id"=>"1664-feed-america-with-george-clooneys-bowl"}
Read fragment views/mysite.org/news/1664-feed-america-with-george-clooneys-bowl?@ver=2009-09-02+14:30:00 (0.5ms)
Rendered photos/_rotating_thumbs.html.haml (47.1ms)
Rendered common/_share_this_button.html.haml (0.3ms)
Rendered comments/_list.html.haml (5.9ms)
Rendered searches/_mini_form.html.haml (2.0ms)
Rendered layouts/_navbar.html.haml (3.4ms)
Rendered common/_subscribe_by_email.html.haml (0.2ms)
Rendered common/_share_this_button.html.haml (0.2ms)
Rendered ads/_openx_zone.html.haml (0.5ms)
Exist fragment? views/fragments/mysite.org/top-celebrities-and-charities (1.0ms)
Read fragment views/fragments/mysite.org/top-celebrities-and-charities (0.1ms)
Rendered sidebar/_top_celebrities_and_charities.html.haml (3.2ms)
Rendered ads/_openx_zone.html.haml (0.6ms)
Exist fragment? views/fragments/mysite.org/top-causes (0.8ms)
Read fragment views/fragments/mysite.org/top-causes (0.0ms)
Rendered sidebar/_top_causes.html.haml (1.7ms)
Rendered ads/_openx_zone.html.haml (0.6ms)
Rendered ads/_openx_zone.html.haml (0.5ms)
Exist fragment? views/fragments/mysite.org/featured-product-teasers (0.8ms)
Read fragment views/fragments/mysite.org/featured-product-teasers (0.0ms)
Rendered products/_featured.html.haml (1.4ms)
Rendered ads/_openx_zone.html.haml (0.5ms)
Rendered common/_share_this_button.html.haml (0.2ms)
Rendered layouts/_quantcast.html.haml (0.1ms)
Rendered layouts/_google_analytics.html.haml (0.1ms)
Rendered layouts/_tynt_insight.html.haml (0.1ms)
Rendered news_items/show.html.haml within layouts/application (895.4ms)
Write fragment views/mysite.org/news/1664-feed-america-with-george-clooneys-bowl?@ver=2009-09-02+14:30:00 (1.1ms)
Completed 200 OK in 912ms (Views: 784.1ms | ActiveRecord: 146.8ms | Sphinx: 0.0ms)
Collaborator

barttenbrinke commented Jan 24, 2011

Could you provide a failing test? I'm not sure I quite understand your idea...

purcell commented Jan 24, 2011

I can't easily provide a failing test because your unit tests are low-level, and seem to assume line-by-line parsing, which wouldn't allow the cache hit/miss inference I'm suggesting.

I can, however, try to explain myself more clearly.

  1. When there's an "Exist fragment?" or a "Read fragment" line followed (perhaps not immediately) by a corresponding line "Write fragment", that could be included in a report as a cache hit for that fragment. When there's no corresponding "Write fragment" line, that would be reported as a cache miss for that fragment. So then aggregate hit-rate stats could be included in a report block, and ideally one could filter by fragment name.

  2. This is a somewhat unrelated suggestion, which is likely easier to implement: it would be great if the "Rendered xxxx (NNNms)" lines were included in the report, so the slowest-rendering partials could be identified. The following specs for the Rails 3 file format should give the general idea:

it "should parse :rendered lines correctly" do
  line = 'Rendered common/_share_this_button.html.haml (0.2ms)'
  @file_format.should parse_line(line).as(:rendered).and_capture(
      :duration => 0.0002, :template => 'common/_share_this_button.html.haml')
end
it "should parse :rendered lines with layouts correctly" do
  line = 'Rendered news_items/show.html.haml within layouts/application (895.4ms)'
  @file_format.should parse_line(line).as(:rendered).and_capture(
      :duration => 0.8954, :template => 'news_items/show.html.haml', :layout => 'layouts/application')
end
Owner

wvanbergen commented Mar 11, 2011

(Late reply:) This seems like an interesting idea. The approach you describe should be possible with rla. We would be very much interested in a patch that adds this to the Rails 3 format.

Question: do all these lines get logged in production mode? Or do you have to enable that by lowering the log level?

purcell commented Mar 13, 2011

Those lines get logged at the :info level, which is the default.

As described in my previous comment, it's easy to analyze fragment-rendering time, but rla's line-by-line approach makes it tricky to analyze fragment cache hit rates using the logic I described.

I can't offer to provide a patch for the hit rates, then, but here's some code I wrote to perform my own analysis of fragment rendering times, which may be helpful to you:

#!/usr/bin/env ruby

require 'time'
require 'yaml'

def parse_line(line, current_req)
  case line
  when /^Started ([A-Z]+) "([^"]*)" for \d+\.\d+\.\d+\.\d+ at (.*)/
    current_req = { :method => $1, :uri => $2, :time => Time.parse($3) }
  when /^  Processing by ([^\#]+)\#([^ ]+) as (.*)/
    current_req.merge! :controller => $1, :action => $2, :format => $3
  when /^  Parameters: (.*?)/
    current_req.merge! :params => $1
  when /^Completed (\d+) .*? in ([\d\.]+)ms \(Views: ([\d\.]+)ms | ActiveRecord: ([\d\.]+)ms/
    current_req.merge!( :status => $1,
                        :request_time => $2.to_f,
                        :view_time => $3.to_f,
                        :active_record_time => $4.to_f )
  when /^Rendered (\S+)(?: within (\S+))? \(([\d\.]+)ms/
    (current_req[:renders] ||= []).push(:template => $1, :layout => $2, :render_time => $3.to_f)
  end
  current_req
end

def parse_log(line_seq, &block)
  prev_req = nil
  line_seq.each do |line|
    new_req = parse_line(line, prev_req)
    yield prev_req if new_req != prev_req && prev_req
    prev_req = new_req
  end
end


parse_log(ARGF) do |req|
  puts "=================================="
  puts req.to_yaml
end
Contributor

sars commented Nov 2, 2012

Collaborator

barttenbrinke commented Nov 30, 2012

Fixed in Master

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment