VEBT-5053/archiving benchmark (#1613)

* fix csv

* bump devise

* devise change

* add logging to archive process

* add start finish

* add clear at end to clear variable

* bump bcrypt

Author: jefftmarks

Gemfile

@@ -8,7 +8,7 @@ gem 'active_model_serializers', '~> 0.10.15' # JSON API
 gem 'activerecord-import' # Mass importing of CSV data
 gem 'activerecord-session_store' # Switch to AR session storage in case of failure pushing to GIBCT
 gem 'base64', '~> 0.2.0' # ruby 3.4.0 warning said to add
-gem 'bcrypt', '~> 3.1.20'
+gem 'bcrypt', '>= 3.1.22'
 gem 'bootsnap', require: false
 gem 'cancancan', '~> 3.6' # Use cancancan for authorization
 gem 'cgi', '>= 0.4.2'

Gemfile.lock

@@ -103,7 +103,7 @@ GEM
       ice_nine (~> 0.11.0)
       thread_safe (~> 0.3, >= 0.3.1)
     base64 (0.2.0)
-    bcrypt (3.1.20)
+    bcrypt (3.1.22)
     benchmark (0.4.0)
     better_errors (2.10.1)
       erubi (>= 1.0.0)
@@ -602,7 +602,7 @@ DEPENDENCIES
   activerecord-import
   activerecord-session_store
   base64 (~> 0.2.0)
-  bcrypt (~> 3.1.20)
+  bcrypt (>= 3.1.22)
   better_errors
   binding_of_caller
   bootsnap

app/models/archiver.rb

@@ -1,7 +1,7 @@
 # frozen_string_literal: true
 
 # TODO: refactor line #6 when we write new ratings code
-module Archiver
+module Archiver # rubocop:disable Metrics/ModuleLength
   ARCHIVE_TYPES = [
     { source: InstitutionRating, archive: InstitutionRatingsArchive },
     { source: InstitutionProgram, archive: InstitutionProgramsArchive },
@@ -13,13 +13,55 @@ module Archiver
     { source: CalculatorConstantVersion, archive: CalculatorConstantVersionsArchive }
   ].freeze
 
-  def self.archive_previous_versions
+  def self.metrics
+    @metrics ||= {}
+  end
+
+  def self.benchmark_start(metric_name)
+    metrics[metric_name] ||= {}
+    metrics[metric_name]['start'] = Time.now.utc
+  end
+
+  def self.benchmark_end(metric_name, count = nil)
+    metrics[metric_name] ||= {}
+    metric = metrics[metric_name]
+    metric['finish'] = Time.now.utc
+    metric['duration'] = metric['finish'] - metric['start']
+    if count
+      metric['records'] = count
+      metric['avg_per_record'] = metric['duration'] / metric['records'] unless count.zero?
+    end
+  end
+
+  def self.print_metrics_report
+    total = metrics.delete('archive_total')['duration']
+    report = metrics.map do |name, values|
+      <<~HERE
+        + #{name}:
+          - start: #{values['start']}
+          - end: #{values['finish']}
+          - duration: #{values['duration']}
+          - records: #{values['records']}
+          - avg_per_record: #{values.fetch('avg_per_record', 'N/A')}
+      HERE
+    end.join("\n")
+    Rails.logger.info(<<~HERE)
+      ========== ARCHIVE BENCHMARKS ==========
+      + Total Archive Time: #{total}
+
+      #{report}
+    HERE
+    metrics.clear
+  end
+
+  def self.archive_previous_versions # rubocop:disable Metrics/AbcSize
     # don't bother if nothing to archive. Also note that during the initial buildout, there is no previous version
     # The below previous_version will exception out and cause all the work to be rolled back.
     return unless Version.current_production && Version.previous_production
 
     production_version = Version.current_production.number
 
+    benchmark_start('archive_total')
     Rails.logger.info "\n\n\n*** Starting Archive process"
     Rails.logger.info 'Getting default timeout parameter'
     get_timeout_parameter
@@ -37,8 +79,12 @@ def self.archive_previous_versions
                    else
                      archivable[:source].joins(:version)
                    end
-
-          source.where('number < ?', production_version).in_batches.delete_all
+          source.where('number < ?', production_version).tap do |records|
+            count = records.count
+            benchmark_start("delete_#{source.table_name}")
+            records.in_batches.delete_all
+            benchmark_end("delete_#{source.table_name}", count)
+          end
         end
       end
     rescue ActiveRecord::StatementInvalid => e
@@ -49,9 +95,11 @@ def self.archive_previous_versions
       process_exception(notice, e, production_version)
     end
 
+    benchmark_end('archive_total')
     Rails.logger.info 'Done archiving, getting default timeout parameter'
     get_timeout_parameter
     Rails.logger.info "*** End of Archiving process\n\n\n"
+    print_metrics_report
   end
 
   def self.create_archives(source, archive, production_version)
@@ -65,12 +113,16 @@ def self.create_archives(source, archive, production_version)
     Rails.logger.info "query as sql: #{base_query.to_sql}"
     archive_columns = archive.column_names
 
+    benchmark_start("create_#{archive.table_name}")
+    orig_count = archive.count
     base_query.find_in_batches(batch_size: 1000) do |records|
       attributes = records.map { |record| record.attributes.slice(*archive_columns) }
       # rubocop:disable Rails/SkipsModelValidations
       archive.insert_all(attributes) if attributes.present?
       # rubocop:enable Rails/SkipsModelValidations
     end
+
+    benchmark_end("create_#{archive.table_name}", archive.count - orig_count)
     Rails.logger.info "*** Done archiving #{source.table_name}"
   end