measure record instantiation time in AS::Notifications

emit an event when we instantiate AR objects so we can see how many
records were instantiated and how long it took

2 files changed, 22 insertions, 4 deletions

diff --git a/activerecord/lib/active_record/associations/join_dependency.rb b/activerecord/lib/active_record/associations/join_dependency.rb
index ec5c189cd3..c5c4edd090 100644
--- a/activerecord/lib/active_record/associations/join_dependency.rb
+++ b/activerecord/lib/active_record/associations/join_dependency.rb
@@ -142,11 +142,20 @@ module ActiveRecord
         parents = model_cache[join_root]
         column_aliases = aliases.column_aliases join_root
 
-        result_set.each { |row_hash|
-          parent = parents[row_hash[primary_key]] ||= join_root.instantiate(row_hash, column_aliases)
-          construct(parent, join_root, row_hash, result_set, seen, model_cache, aliases)
+        message_bus = ActiveSupport::Notifications.instrumenter
+
+        payload = {
+          record_count: result_set.length,
+          class_name: join_root.base_klass.name
         }
 
+        message_bus.instrument('instantiation.active_record', payload) do
+          result_set.each { |row_hash|
+            parent = parents[row_hash[primary_key]] ||= join_root.instantiate(row_hash, column_aliases)
+            construct(parent, join_root, row_hash, result_set, seen, model_cache, aliases)
+          }
+        end
+
         parents.values
       end
 
diff --git a/activerecord/lib/active_record/querying.rb b/activerecord/lib/active_record/querying.rb
index 45b6b1c925..e8de4db3a7 100644
--- a/activerecord/lib/active_record/querying.rb
+++ b/activerecord/lib/active_record/querying.rb
@@ -39,7 +39,16 @@ module ActiveRecord
       result_set = connection.select_all(sanitize_sql(sql), "#{name} Load", binds)
       column_types = result_set.column_types.dup
       columns_hash.each_key { |k| column_types.delete k }
-      result_set.map { |record| instantiate(record, column_types) }
+      message_bus = ActiveSupport::Notifications.instrumenter
+
+      payload = {
+        record_count: result_set.length,
+        class_name: name
+      }
+
+      message_bus.instrument('instantiation.active_record', payload) do
+        result_set.map { |record| instantiate(record, column_types) }
+      end
     end
 
     # Returns the result of an SQL statement that should only include a COUNT(*) in the SELECT part.