Use the same timer for execution and its sections to increase accurancy

Author: alexisbernard

lib/rorvswild/agent.rb

@@ -113,12 +113,10 @@ def measure_job(name, parameters: nil, &block)
 
     def start_execution(execution)
       Thread.current[:rorvswild_execution] ||= execution
-      RorVsWild::Section.start
     end
 
     def stop_execution
       return unless execution = current_execution
-      RorVsWild::Section.stop
       execution.stop
       case execution
       when Execution::Job then queue_job

lib/rorvswild/execution.rb

@@ -2,21 +2,21 @@
 
 module RorVsWild
   class Execution
-    attr_reader :parameters, :sections, :section_stack, :error_context, :runtime
+    attr_reader :parameters, :sections, :section_stack, :error_context, :runtime, :root_section, :queue_section
 
     attr_accessor :error, :name
 
     def initialize(name, parameters)
+      @root_section = Section::Root.new
+
       @name = name
       @parameters = parameters
       @runtime = nil
       @error = nil
       @error_context = nil
 
-      @started_at = RorVsWild.clock_milliseconds
-      @gc_section = Section::GarbageCollection.new
       @environment = Host.to_h
-      @section_stack = []
+      @section_stack = [@root_section]
       @sections = []
     end
 
@@ -30,20 +30,18 @@ def add_section(section)
 
     def add_queue_time(queue_time_ms)
       return unless queue_time_ms
-      @started_at -= queue_time_ms
-      section = Section.new
-      section.total_ms = queue_time_ms
-      section.gc_time_ms = 0
-      section.file = "queue"
-      section.line = 0
-      section.kind = "queue"
-      add_section(section)
+      @queue_section = Section::Queue.new(queue_time_ms)
+      add_section(@queue_section)
+      @queue_section
     end
 
     def stop
-      @gc_section.stop
-      @sections << @gc_section if @gc_section.calls > 0 && @gc_section.total_ms > 0
-      @runtime = RorVsWild.clock_milliseconds - @started_at
+      Section.stop # root section
+      if @root_section.gc_time_ms > 0
+        add_section(Section::GarbageCollection.new(@root_section.gc_time_ms, @root_section.gc_calls))
+      end
+      @runtime = @root_section.total_ms + @root_section.gc_time_ms
+      @runtime += @queue_section.total_ms if @queue_section
     end
 
     def as_json(options = nil)

lib/rorvswild/plugin/rails_engine.rb

@@ -58,12 +58,11 @@ def call(env)
         execution = RorVsWild::Execution::Request.new(env["REQUEST_URI"])
         execution.add_queue_time(calculate_queue_time(env))
         RorVsWild.agent.start_execution(execution)
-        section = RorVsWild::Section.start
+        section = execution.root_section
         section.file, section.line = method(:call).super_method.source_location
         section.commands << "Rails::Engine#call"
         super
       ensure
-        RorVsWild::Section.stop
         RorVsWild.agent.stop_execution
       end
 

lib/rorvswild/section.rb

@@ -97,21 +97,44 @@ def command
       string.size > COMMAND_MAX_SIZE ? string[0, COMMAND_MAX_SIZE] + " [TRUNCATED]" : string
     end
 
-    class GarbageCollection < Section
+    class Root < Section
+      attr_reader :gc_calls
+
       def initialize
+        super
         @gc_count = GC.count
+      end
+
+      def stop
         super
-        @calls = 0
+        @gc_calls = GC.count - @gc_count
+      end
+    end
+
+    class GarbageCollection < Section
+      def initialize(total_ms, calls)
+        @total_ms = total_ms
+        @calls = calls > 0 ? calls : 1
         @kind = "gc"
         @file, @line = "ruby/gc.c", 0
+        @commands = Set.new
+        @children_ms = 0
+        @async_ms = 0
         add_command("GC.start")
       end
+    end
 
-      def stop
-        super
-        @total_ms = @gc_time_ms
-        @calls = GC.count - @gc_count
-        @calls = 1 if @gc_time_ms > 0 && @calls == 0
+    class Queue < Section
+      def initialize(total_ms)
+        @total_ms = total_ms
+        @gc_time_ms = 0
+        @file = "queue"
+        @line = 0
+        @kind = "queue"
+        @calls = 1
+        @children_ms = 0
+        @gc_time_ms = 0
+        @async_ms = 0
       end
     end
   end

test/execution_test.rb

@@ -13,8 +13,8 @@ def test_format_header_name
   def test_add_queue_time
     agent
     execution = RorVsWild::Execution.new("name", nil)
-    old_started_at = execution.instance_variable_get(:@started_at)
     execution.add_queue_time(1)
+    execution.stop
     assert(section = execution.sections[0])
     assert_equal("queue", section.kind)
     assert_equal("queue", section.file)
@@ -24,7 +24,7 @@ def test_add_queue_time
     assert_equal(0, section.children_ms)
     assert_equal(0, section.gc_time_ms)
     assert_equal(0, section.async_ms)
-    assert_equal(old_started_at - 1, execution.instance_variable_get(:@started_at))
+    assert_equal(execution.root_section.total_ms + execution.queue_section.total_ms, execution.runtime)
   end
 
   def test_as_json

test/helper.rb

@@ -41,9 +41,13 @@ def client.transmit(request)
     agent
   end
 
-  # Returns all section except the GC and the root one which is the last
+  # Returns all section except the GC and root
   def current_user_sections
-    agent.current_execution.sections.select { |s| s.kind != "gc" }[0..-2]
+    agent.current_execution.sections.select { |s| s.kind != "gc" && !s.is_a?(RorVsWild::Section::Root) }
+  end
+
+  def current_sections_without_gc
+    agent.current_execution.sections.select { |s| s.kind != "gc" }
   end
 
   def start_request(path = "/")

test/plugin/rails_engine_test.rb

@@ -6,14 +6,14 @@ class RorVsWild::Plugin::RailsEngineTest < Minitest::Test
   def test_callback
     middleware.call("REQUEST_URI" => "/foo/bar")
     assert_equal("/foo/bar", agent.current_execution.path)
-    assert_equal(1, (sections = current_user_sections).size)
+    assert_equal(1, (sections = current_sections_without_gc).size)
     assert_equal("Rails::Engine#call", sections[0].command)
   end
 
   def test_queue_time_section
     middleware.call("HTTP_X_REQUEST_START" => unix_timestamp_seconds.to_s)
 
-    sections = current_user_sections
+    sections = current_sections_without_gc
     assert_equal(2, sections.size)
     queue_time_section = sections[0]
     assert_equal "queue", queue_time_section.file
@@ -25,23 +25,23 @@ def test_queue_time_section
   def test_queue_time_secs
     middleware.call("HTTP_X_REQUEST_START" => (unix_timestamp_seconds - 0.123).to_s)
 
-    sections = current_user_sections
+    sections = current_sections_without_gc
     assert_equal(2, sections.size)
     assert_operator(123, :<=, sections[0].total_ms)
   end
 
   def test_queue_time_millis
     middleware.call("HTTP_X_QUEUE_START" => (unix_timestamp_seconds * 1000 - 234).to_s)
 
-    sections = current_user_sections
+    sections = current_sections_without_gc
     assert_equal(2, sections.size)
     assert_operator(234, :<=, sections[0].total_ms)
   end
 
   def test_queue_time_micros
     middleware.call("HTTP_X_MIDDLEWARE_START" => (unix_timestamp_seconds * 1_000_000 - 345_000).to_s)
 
-    sections = current_user_sections
+    sections = current_sections_without_gc
     assert_equal(2, sections.size)
     assert_operator(345, :<=, sections[0].total_ms)
   end