FEATURE: track duration of AI calls (#1082)

* FEATURE: track duration of AI calls

* annotate

app/models/ai_api_audit_log.rb

@@ -46,6 +46,7 @@ def prev_log_id
 #  language_model       :string(255)
 #  feature_context      :jsonb
 #  cached_tokens        :integer
+#  duration_msecs       :integer
 #
 # Indexes
 #

db/migrate/20250122003035_add_duration_to_ai_api_log.rb

@@ -0,0 +1,6 @@
+# frozen_string_literal: true
+class AddDurationToAiApiLog < ActiveRecord::Migration[7.2]
+  def change
+    add_column :ai_api_audit_logs, :duration_msecs, :integer
+  end
+end

lib/completions/endpoints/base.rb

@@ -66,6 +66,7 @@ def perform_completion!(
           &blk
         )
           LlmQuota.check_quotas!(@llm_model, user)
+          start_time = Time.now
 
           @partial_tool_calls = partial_tool_calls
           model_params = normalize_model_params(model_params)
@@ -212,6 +213,9 @@ def perform_completion!(
                 log.raw_response_payload = response_raw
                 final_log_update(log)
                 log.response_tokens = tokenizer.size(partials_raw) if log.response_tokens.blank?
+                log.created_at = start_time
+                log.updated_at = Time.now
+                log.duration_msecs = (Time.now - start_time) * 1000
                 log.save!
                 LlmQuota.log_usage(@llm_model, user, log.request_tokens, log.response_tokens)
                 if Rails.env.development?

spec/lib/completions/endpoints/open_ai_spec.rb

@@ -319,6 +319,7 @@ def request_body(prompt, stream: false, tool_call: false)
       log = AiApiAuditLog.order(:id).last
       expect(log.request_tokens).to eq(55)
       expect(log.response_tokens).to eq(13)
+      expect(log.duration_msecs).not_to be_nil
 
       expected =
         DiscourseAi::Completions::ToolCall.new(