Added support for compound data in order to handle partials correctly.

lib/request_log_analyzer/file_format/rails3.rb

@@ -64,10 +64,11 @@ class Rails3 < Base
 
     # Rendered queries/index.html.erb (0.6ms)
     line_definition :rendered do |line|
+      line.compound = [:partial_duration]
       line.teaser = / Rendered /
       line.regexp = / Rendered ([a-zA-Z0-9_\-\/.]+(?:\/[a-zA-Z0-9_\-.]+)+)(?:\ within\ .*?)? \((\d+(?:\.\d+)?)ms\)/
       line.capture(:rendered_file)
-      line.capture(:rendered_duration).as(:duration, :unit => :msec)
+      line.capture(:partial_duration).as(:duration, :unit => :msec)
     end
 
     # # Not parsed at the moment:
@@ -87,7 +88,7 @@ class Rails3 < Base
       analyze.frequency :status, :title => 'HTTP statuses returned'
 
       analyze.duration :duration, :category => REQUEST_CATEGORIZER, :title => "Request duration", :line_type => :completed
-      analyze.duration :rendered_duration, :category => :rendered_file, :title => 'Partials rendering time', :line_type => :rendered
+      analyze.duration :partial_duration, :category => :rendered_file, :title => 'Partials rendering time', :line_type => :rendered
       analyze.duration :view, :category => REQUEST_CATEGORIZER, :title => "View rendering time", :line_type => :completed
       analyze.duration :db, :category => REQUEST_CATEGORIZER, :title => "Database time", :line_type => :completed
 

lib/request_log_analyzer/line_definition.rb

@@ -44,7 +44,7 @@ def as(type, type_options = {})
     end
 
     attr_reader :name
-    attr_accessor :teaser, :regexp, :captures
+    attr_accessor :teaser, :regexp, :captures, :compound
     attr_accessor :header, :footer
 
     alias_method :header?, :header
@@ -56,6 +56,7 @@ def initialize(name, definition = {})
       @name     = name
       @captures = []
       @teaser   = nil
+      @compound = []
       definition.each { |key, value| self.send("#{key.to_s}=".to_sym, value) }
     end
 

lib/request_log_analyzer/request.rb

@@ -116,6 +116,7 @@ def add_parsed_line (parsed_line)
       value_hash[:line_type] = parsed_line[:line_definition].name
       value_hash[:lineno] = parsed_line[:lineno]
       value_hash[:source] = parsed_line[:source]
+      value_hash[:compound] = parsed_line[:line_definition].compound
       add_line_hash(value_hash)
     end
 
@@ -124,7 +125,19 @@ def add_parsed_line (parsed_line)
     # The line should be provides as a hash of the fields parsed from the line.
     def add_line_hash(value_hash)
       @lines << value_hash
-      @attributes = value_hash.merge(@attributes)
+      if value_hash[:compound]
+        value_hash.each do |key, value|
+          if value_hash[:compound].include?(key)
+            @attributes[key] = [] if @attributes[key].nil?
+            @attributes[key] = [@attributes[key]] unless @attributes[key].is_a?(Array)
+            @attributes[key] << value
+          else
+            @attributes[key] = value unless key == :compound || @attributes[key]
+          end
+        end
+      else
+        @attributes = value_hash.merge(@attributes)
+      end
     end
 
     # Adds another line to the request. This method switches automatically between

lib/request_log_analyzer/tracker/numeric_value.rb

@@ -49,11 +49,10 @@ def update(request)
         found_categories.each_with_index do |cat, index|
           update_statistics(cat, found_values[index]) if cat && found_values[index].kind_of?(Numeric)
         end
-
       else
         category = @categorizer.call(request)
         value    = @valueizer.call(request)
-        update_statistics(category, value) if value.kind_of?(Numeric) && category
+        update_statistics(category, value) if (value.kind_of?(Numeric) || value.kind_of?(Array)) && category
       end
     end
 
@@ -227,6 +226,8 @@ def percentile_interval(category, x)
     # <tt>category</tt>:: The category for which to update the running statistics calculations
     # <tt>number</tt>:: The numeric value to update the calculations with.
     def update_statistics(category, number)
+      return number.map {|n| update_statistics(category, n)} if number.is_a?(Array)
+
       @categories[category] ||= { :hits => 0, :sum => 0, :mean => 0.0, :sum_of_squares => 0.0, :min => number, :max => number, 
                                   :buckets => Array.new(@number_of_buckets, 0) }
 

spec/fixtures/rails_3_partials.log

@@ -0,0 +1,13 @@
+Started GET "/foobartest" for 127.0.0.1 at 2012-11-21 15:21:13 +0100
+Processing by HomeController#foobartest as */*
+  Rendered home/foobartest_partial.html.slim (10.0ms)
+  Rendered home/foobartest_partial.html.slim (10.0ms)
+  Rendered home/foobartest_partial.html.slim (10.0ms)
+Completed 200 OK in 58ms (Views: 44.6ms | ActiveRecord: 0.0ms)
+
+
+Started GET "/foobartest" for 127.0.0.1 at 2012-11-21 15:21:31 +0100
+Processing by HomeController#foobartest as */*
+  Rendered home/foobartest_partial.html.slim (100.0ms)
+  Rendered home/foobartest_partial.html.slim (0.0ms)
+Completed 200 OK in 2ms (Views: 0.6ms | ActiveRecord: 0.0ms)

spec/integration/command_line_usage_spec.rb

@@ -20,6 +20,10 @@
     output.any? { |line| /^Parsed requests\:\s*2\s/ =~ line }.should be_true
   end
 
+  it "should find 5 partials in a rails3 fragment with partials" do
+    output = run("#{log_fixture(:rails_3_partials)}")
+    output.any? { |line| /^home\/foobartest_partial\.html\.slim.*5/ =~ line}.should eql true
+  end
 
   it "should skip 1 requests with a --select option" do
     output = run("#{log_fixture(:rails_1x)} --select controller PeopleController")

spec/unit/file_format/rails3_format_spec.rb

@@ -82,9 +82,9 @@
           :file    => '/Users/willem/Code/warehouse/app/views/queries/execute.csv.erb')
     end
 
-    it "should parse :rendered lines correctly" do
+    it "should parse :rendered lines as an array" do
       line = " Rendered queries/index.html.erb (0.6ms)"
-      subject.should parse_line(line).as(:rendered).and_capture(:rendered_duration => 0.0006)
+      subject.should parse_line(line).as(:rendered).and_capture(:partial_duration => [0.0006])
     end
   end
 
@@ -105,7 +105,19 @@
       log_parser.should_not_receive(:warn)
       log_parser.parse_string(log)
     end
-
+
+    it "should count partials correctly" do
+      log = <<-EOLOG
+        Started GET "/stream_support" for 127.0.0.1 at 2012-11-21 15:21:31 +0100
+        Processing by HomeController#stream_support as */*
+          Rendered home/stream_support.html.slim (33.2ms)
+          Rendered home/stream_support.html.slim (0.0ms)
+        Completed 200 OK in 2ms (Views: 0.6ms | ActiveRecord: 0.0ms)
+      EOLOG
+
+      log_parser.parse_string(log)
+    end
+
     it "should parse an unroutable request correctly" do
       log = <<-EOLOG
         Started GET "/404" for 127.0.0.1 at Fri Mar 19 06:40:57 -0700 2010
@@ -121,7 +133,7 @@
       log_parser.should_receive(:warn).once
       log_parser.parse_string(log)
     end
-    
+
     it "should parse a failing request correctly" do
       log = <<-EOLOG
         Started POST "/queries/397638749/execute.csv" for 127.0.0.1 at Mon Mar 01 18:44:33 -0800 2010

spec/unit/tracker/duration_tracker_spec.rb

@@ -24,6 +24,13 @@
       lambda { @tracker.report(mock_output) }.should_not raise_error
     end
 
+    it "should generate a report with arrays of durations are present" do
+      @tracker.update(request(:category => 'a', :duration => [0.1, 0.2]))
+      @tracker.update(request(:category => 'a', :duration => [0.2, 0.3]))
+      lambda { @tracker.report(mock_output) }.should_not raise_error
+      @tracker.to_yaml_object['a'].should include(:min => 0.1, :hits => 4, :max => 0.3, :mean => 0.2, :sum => 0.8)
+    end
+
     it "should generate a YAML output" do
       @tracker.update(request(:category => 'a', :duration => 0.2))
       @tracker.update(request(:category => 'b', :duration => 0.2))