Log duration for various methods in AuthorizedProjectsWorker

What does this MR do and why?

• We are experiencing issues with the AuthorizedProjectsWorker, especially around how long each request is taking.

• The worker calls Users::RefreshAuthorizedProjectsService to calculate which records in the project_authorizations table need to be refreshed and saves those changes.

• This MR adds duration stats to the different steps in this service to figure out which part of the codebase needs to be optimised.

• No changelog needed since it's a developer facing change

MR acceptance checklist

Please evaluate this MR against the MR acceptance checklist. It helps you analyze changes to reduce risks in quality, performance, reliability, security, and maintainability.

Related to #484754 (closed)

app/services/users/refresh_authorized_projects_service.rb

@@ -24,6 +24,9 @@ def initialize(user, source: nil, incorrect_auth_found_callback: nil, missing_au
       @source = source
       @incorrect_auth_found_callback = incorrect_auth_found_callback
       @missing_auth_found_callback = missing_auth_found_callback
+
+      @start_time = current_monotonic_time
+      @duration_statistics = {}
     end
 
     def execute
@@ -37,6 +40,8 @@ def execute
         sleep(0.1)
       end
 
+      reset_timer_and_store_duration(:obtain_redis_lease)
+
       begin
         # We need an up to date User object that has access to all relations that
         # may have been created earlier. The only way to ensure this is to reload
@@ -57,6 +62,8 @@ def execute_without_lease
         missing_auth_found_callback: missing_auth_found_callback
       ).execute
 
+      reset_timer_and_store_duration(:find_records_due_for_refresh)
+
       update_authorizations(remove, add)
     end
 
@@ -65,8 +72,6 @@ def execute_without_lease
     # remove - The project IDs of the authorization rows to remove.
     # add - Rows to insert in the form `[{ user_id: user_id, project_id: project_id, access_level: access_level}, ...]`
     def update_authorizations(remove = [], add = [])
-      log_refresh_details(remove, add)
-
       ProjectAuthorizations::Changes.new do |changes|
         changes.add(add)
         changes.remove_projects_for_user(user, remove)
@@ -74,6 +79,10 @@ def update_authorizations(remove = [], add = [])
 
       user.update!(project_authorizations_recalculated_at: Time.zone.now) if remove.any? || add.any?
 
+      reset_timer_and_store_duration(:update_authorizations)
+
+      log_refresh_details(remove, add)
+
       # Since we batch insert authorization rows, Rails' associations may get
       # out of sync. As such we force a reload of the User object.
       user.reset
@@ -93,8 +102,22 @@ def log_refresh_details(remove, add)
         # most often there's only a few entries in remove and add, but limit it to the first 5
         # entries to avoid flooding the logs
         'authorized_projects_refresh.rows_deleted_slice': remove.first(5),
-        'authorized_projects_refresh.rows_added_slice': add.first(5).map(&:values)
+        'authorized_projects_refresh.rows_added_slice': add.first(5).map(&:values),
+        **@duration_statistics
       )
     end
+
+    def current_monotonic_time
+      ::Gitlab::Metrics::System.monotonic_time
+    end
+
+    def reset_timer_and_store_duration(operation_name)
+      duration_key = :"#{operation_name}_duration_s"
+      duration_value = (current_monotonic_time - @start_time).round(Gitlab::InstrumentationHelper::DURATION_PRECISION)
+
+      @duration_statistics[duration_key] = duration_value
+
+      @start_time = current_monotonic_time
+    end
   end
 end