Benchmark and send telemetry events for indexing and resolution (#4074)

Author: vinistock

lib/ruby_lsp/server.rb

@@ -436,8 +436,11 @@ def text_document_did_change(message)
 
       if [:ruby, :rbs].include?(language_id)
         graph = @global_state.graph
-        graph.index_source(text_document[:uri].to_s, document.source, language_id.to_s)
-        graph.resolve
+
+        benchmark("index_source") do
+          graph.index_source(text_document[:uri].to_s, document.source, language_id.to_s)
+        end
+        benchmark("incremental_resolve") { graph.resolve }
       end
     end
 
@@ -1070,8 +1073,8 @@ def workspace_did_change_watched_files(message)
           acc << path
         end
       end
-      graph.index_all(additions_and_changes)
-      graph.resolve
+      benchmark("index_all") { graph.index_all(additions_and_changes) }
+      benchmark("incremental_resolve") { graph.resolve }
 
       index = @global_state.index
       changes.each do |change|
@@ -1269,10 +1272,10 @@ def shutdown
     #: -> void
     def perform_initial_indexing
       progress("indexing-progress", message: "Indexing workspace...")
-      @global_state.graph.index_workspace
+      benchmark("index_workspace") { @global_state.graph.index_workspace }
 
       progress("indexing-progress", message: "Resolving graph...")
-      @global_state.graph.resolve
+      benchmark("full_resolve") { @global_state.graph.resolve }
 
       # The begin progress invocation happens during `initialize`, so that the notification is sent before we are
       # stuck indexing files
@@ -1572,5 +1575,28 @@ def code_lens_resolve(message)
         response: code_lens,
       ))
     end
+
+    #: [T] (String) { () -> T } -> T
+    def benchmark(label, &block)
+      start = Process.clock_gettime(Process::CLOCK_MONOTONIC, :float_millisecond)
+      result = block.call
+      duration = Process.clock_gettime(Process::CLOCK_MONOTONIC, :float_millisecond) - start
+
+      send_message(Notification.telemetry({
+        type: "data",
+        eventName: "ruby_lsp.response_time",
+        data: {
+          type: "histogram",
+          value: duration,
+          attributes: {
+            message: label,
+            lspVersion: RubyLsp::VERSION,
+            rubyVersion: RUBY_VERSION,
+          },
+        },
+      }))
+
+      result
+    end
   end
 end

test/server_test.rb

@@ -194,8 +194,7 @@ def test_initialized_recovers_from_indexing_failures
       @server.process_message({ method: "initialized" })
     end
 
-    notification = @server.pop_response
-    assert_equal("window/showMessage", notification.method)
+    notification = find_message(RubyLsp::Notification, "window/showMessage")
     expected_message = "Error while indexing (see [troubleshooting steps]" \
       "(https://shopify.github.io/ruby-lsp/troubleshooting#indexing)): boom!"
     assert_equal(
@@ -576,7 +575,7 @@ def version
         },
       })
 
-      message = @server.pop_response.params.message
+      message = find_message(RubyLsp::Notification, "window/logMessage").params.message
       assert_match("Error in Foo add-on while processing watched file notifications", message)
       assert_match("boom", message)
     ensure