feat:

- added first version of the tracker that computes the execution time of each file.

- Moved the base tracer logic to a base tracer, so that it can be reused in the two existing tracers

Co-authored-by: Fabio Leandro Janiszevski <[email protected]>

Author: carlosdanielpohlod

lib/rails_tracepoint_stack.rb

@@ -1,6 +1,7 @@
 require 'rails_tracepoint_stack/configuration'
 require 'rails_tracepoint_stack/log_formatter'
 require 'rails_tracepoint_stack/tracer'
+require 'rails_tracepoint_stack/duration_tracer'
 
 $rails_tracer_rtps = nil
 
@@ -36,3 +37,20 @@ def self.enable_trace
     $rails_tracer_rtps.disable
   end
 end
+
+if ENV.fetch("ENABLE_EXECUTION_DURATION", "false") == "true"
+  begin
+    $rails_duration_tracer = RailsTracepointStack::DurationTracer.new
+
+    $rails_duration_tracer.enable
+
+    at_exit do
+      $rails_duration_tracer.disable
+
+      RailsTracepointStack::DurationTracerLogger.new.show_top_files
+    end
+
+  ensure
+    #destroy the tmp file
+  end
+end

lib/rails_tracepoint_stack/duration/output.rb

@@ -0,0 +1,35 @@
+module RailsTracepointStack
+  module Duration
+    class Output
+      attr :file_durations
+      
+      def initialize
+        @file_durations = Hash.new(0)
+        compute_duration!
+      end
+
+      def show_top_files
+        top_10_files.each_with_index do |(file, total_duration), index|
+          puts "#{index + 1}. File: #{file} - Total Duration: #{total_duration.round(6)} seconds"
+        end
+      end
+
+      private
+
+      def compute_duration!
+        File.open("log-boot-4.txt", "r").each_line do |line|
+          data = JSON.parse(line)
+        
+          file = data["file"]
+          duration = data["duration"]
+        
+          file_durations[file] += duration
+        end
+      end
+      #TODO: turn the number of files flexible
+      def top_10_files
+        @top_10_files ||= file_durations.sort_by { |_, total_duration| -total_duration }.first(10)
+      end
+    end
+  end
+end

lib/rails_tracepoint_stack/duration/tmp_save.rb

@@ -0,0 +1,19 @@
+
+module RailsTracepointStack
+  module TmpSave
+    def self.save(trace:, last_time:)
+      duration = current_time - last_time
+      log_obj = {
+        time: current_time,
+        class: trace.class_name,
+        method: trace.method_name,
+        file: trace.file_path,
+        line: trace.line_number,
+        duration: duration
+      }
+      File.open("time_log.json", "a") do |file|
+        file.puts log_obj.to_json
+      end
+    end
+  end
+end

lib/rails_tracepoint_stack/duration_tracer.rb

@@ -0,0 +1,25 @@
+require "rails_tracepoint_stack/tracer_base"
+require "rails_tracepoint_stack/duration/tmp_save"
+
+module RailsTracepointStack
+  class DurationTracer < RailsTracepointStack::TracerBase
+    
+    private
+    
+    def generate_tracer
+     TracePoint.new(:line) do |tracepoint|
+        trace = RailsTracepointStack::Trace.new(trace_point: tracepoint)
+
+        next if ignore_trace?(trace: trace)
+
+        current_time = Process.clock_gettime(Process::CLOCK_MONOTONIC)
+
+        if last_time
+          RailsTracepointStack::TmpSave.save(trace: trace, last_time: last_time)
+        end
+
+        last_time = current_time
+      end
+    end
+  end
+end

lib/rails_tracepoint_stack/tracer.rb

@@ -1,20 +1,7 @@
-# TODO: Move to a loader file
-require "rails_tracepoint_stack/logger"
-require "rails_tracepoint_stack/trace_filter"
-require "rails_tracepoint_stack/trace"
-require "rails_tracepoint_stack/log_formatter"
+require "rails_tracepoint_stack/tracer_base"
 
 module RailsTracepointStack
-  class Tracer
-    include RailsTracepointStack::TraceFilter
-    extend Forwardable
- 
-    def_delegators :@tracer, :enable, :disable
-
-    def initialize
-      generate_tracer
-    end
-
+  class Tracer < RailsTracepointStack::TracerBase
     private
 
     def generate_tracer

lib/rails_tracepoint_stack/tracer_base.rb

@@ -0,0 +1,18 @@
+# TODO: Move to a loader file
+require "rails_tracepoint_stack/logger"
+require "rails_tracepoint_stack/trace_filter"
+require "rails_tracepoint_stack/trace"
+require "rails_tracepoint_stack/log_formatter"
+
+module RailsTracepointStack
+  class TracerBase
+    include RailsTracepointStack::TraceFilter
+    extend Forwardable
+ 
+    def_delegators :@tracer, :enable, :disable
+
+    def initialize
+      generate_tracer
+    end
+  end
+end

spec/rails_tracepoint_stack/duration_tracer/output_spec.rb

@@ -0,0 +1,50 @@
+require "spec_helper"
+require "json"
+
+RSpec.describe RailsTracepointStack::Duration::Output do
+  describe "#show_top_files" do
+    before do
+      allow(File)
+        .to receive(:open)
+        .with("log-boot-4.txt", "r")
+        .and_return(
+          StringIO.new(
+            {file: "file1", duration: 1}.to_json + "\n" +
+            {file: "file1", duration: 2}.to_json + "\n" +
+            {file: "file2", duration: 1}.to_json + "\n" +
+            {file: "file2", duration: 1}.to_json + "\n" +
+            {file: "file2", duration: 1}.to_json + "\n" +
+            {file: "file3", duration: 1}.to_json + "\n" +
+            {file: "file4", duration: 1}.to_json + "\n" +
+            {file: "file5", duration: 1}.to_json + "\n" +
+            {file: "file5", duration: 1}.to_json + "\n" +
+            {file: "file5", duration: 1}.to_json + "\n" + 
+            {file: "file6", duration: 1}.to_json + "\n" +
+            {file: "file7", duration: 1}.to_json + "\n" +
+            {file: "file8", duration: 1}.to_json + "\n" +
+            {file: "file9", duration: 1}.to_json + "\n" +
+            {file: "file10", duration: 1}.to_json + "\n" +
+            {file: "file11", duration: 1}.to_json + "\n"
+          )
+        )
+    end
+
+    it "prints the top 10 files with their total duration" do
+      expect { described_class.new.show_top_files }
+        .to output(
+          <<~OUTPUT
+              1. File: file1 - Total Duration: 3 seconds
+              2. File: file2 - Total Duration: 3 seconds
+              3. File: file5 - Total Duration: 3 seconds
+              4. File: file3 - Total Duration: 1 seconds
+              5. File: file4 - Total Duration: 1 seconds
+              6. File: file6 - Total Duration: 1 seconds
+              7. File: file7 - Total Duration: 1 seconds
+              8. File: file8 - Total Duration: 1 seconds
+              9. File: file9 - Total Duration: 1 seconds
+              10. File: file10 - Total Duration: 1 seconds
+          OUTPUT
+        ).to_stdout
+    end
+  end
+end