search: time each step as a Sentry span
A search was one transaction, its time a single lump with nothing to say;
now the read, the groups, the match, and the render each get a span of their own to weigh.
The spans hold counts and never the query, since a query is a name someone typed,
and the gem's Sequel patch stays off because its SQL would carry a card's text inside.
Assisted-by: Claude Opus 5.5 via Claude Code
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
diff --git a/lib/pro_tacts/web/search.rb b/lib/pro_tacts/web/search.rb
index 550bea0..cb960d3 100644
--- a/lib/pro_tacts/web/search.rb
+++ b/lib/pro_tacts/web/search.rb
@@ -11,20 +11,26 @@ module ProTacts
# stays in Admin::Search, the one place it is decided, rather than
# a second copy in the page's script
# (docs/plans/2026-09-30-live-search.md).
+ #
+ # Each step is a span on the request's Sentry transaction, so a slow
+ # search names its slow step. A span carries counts and never the
+ # query, which is a name typed into a field.
hash_branch("search") do |r|
query = r.params["q"].to_s.strip
r.is do
r.get do
response["Content-Type"] = "text/html; charset=utf-8"
- Admin::SearchPage.call(login: @login, query:, results: search_results(query))
+ results = search_results(query)
+ search_span("render") { Admin::SearchPage.call(login: @login, query:, results:) }
end
end
# The results alone, put under the input whole.
r.get "results" do
response["Content-Type"] = "text/html; charset=utf-8"
- search_results(query).call
+ results = search_results(query)
+ search_span("render") { results.call }
end
end
@@ -35,16 +41,25 @@ module ProTacts
# word is typed.
#: (String query) -> Admin::SearchResults
def search_results(query)
- recent = store.contacts_by_recency
+ recent = search_span("contacts_by_recency") { |span|
+ store.contacts_by_recency.tap { span&.set_data("rows", it.length) }
+ }
if query.empty?
return Admin::SearchResults.new(contacts: recent.first(Admin::Dashboard::RECENT_LIMIT), groups: [], recent: true)
end
- groups = store.all_groups
- Admin::SearchResults.new(
- contacts: Admin::Search.contacts(recent, query:, groups:),
- groups: Admin::Search.groups(groups, query:),
- )
+ groups = search_span("all_groups") { |span| store.all_groups.tap { span&.set_data("rows", it.length) } }
+ search_span("match") { |span|
+ contacts = Admin::Search.contacts(recent, query:, groups:)
+ span&.set_data("words", query.split.length)
+ span&.set_data("contacts", contacts.length)
+ Admin::SearchResults.new(contacts:, groups: Admin::Search.groups(groups, query:))
+ }
+ end
+
+ #: [T] (String step) { (Sentry::Span?) -> T } -> T
+ def search_span(step, &)
+ Sentry.with_child_span(op: "search.#{step}", description: step, &)
end
end
end
diff --git a/sig/gems/sentry.rbs b/sig/gems/sentry.rbs
index 0618afc..2747a73 100644
--- a/sig/gems/sentry.rbs
+++ b/sig/gems/sentry.rbs
@@ -2,8 +2,16 @@
# exception-capturing middleware web.rb mounts, the refusal warnings
# RefusalAlerts sends, the arrival messages dav.rb and store.rb send,
# and the photo decode refusal contact.rb captures. ExchangeLog tags the
-# request's scope and reads whether anything was reported under it.
+# request's scope and reads whether anything was reported under it, and
+# the search times its steps as spans.
module Sentry
+ # Yields nil outside a transaction, as under a nil DSN.
+ def self.with_child_span: [T] (op: String, description: String) { (Span?) -> T } -> T
+
+ class Span
+ def set_data: (String key, Integer value) -> void
+ end
+
def self.capture_message: (String message, ?level: Symbol, ?fingerprint: Array[String], ?tags: Hash[Symbol, String]) -> untyped
def self.capture_exception: (Exception exception, ?level: Symbol) -> untyped
diff --git a/test/pro_tacts/admin/test_contacts_pages.rb b/test/pro_tacts/admin/test_contacts_pages.rb
index f0f7261..1252d9a 100644
--- a/test/pro_tacts/admin/test_contacts_pages.rb
+++ b/test/pro_tacts/admin/test_contacts_pages.rb
@@ -14,6 +14,7 @@ require "pro_tacts/web"
# date.
class AdminContactsPagesTest < Minitest::Test
include Rack::Test::Methods
+ include Sentry::TestHelper
include ThrowawayContacts
def app
@@ -397,6 +398,25 @@ class AdminContactsPagesTest < Minitest::Test
end
end
+ # Each step of a search is a span on the request's transaction, and
+ # none of them carries the query (Web's search branch).
+ def test_search_times_its_steps_without_the_query
+ setup_sentry_test { it.traces_sample_rate = 1.0 }
+ with_contacts({"ada" => ADA}) do
+ get "/search/results", q: "lovelace"
+
+ transactions = sentry_events.grep(Sentry::TransactionEvent)
+ assert_equal 1, transactions.length
+ transaction = transactions.first
+ spans = transaction.spans.select { it[:op].start_with?("search.") }
+ assert_equal %w[search.contacts_by_recency search.all_groups search.match search.render], spans.map { it[:op] }
+ assert_equal({"words" => 1, "contacts" => 1}, spans.find { it[:op] == "search.match" }[:data])
+ refute_includes JSON.generate(transaction.to_h), "lovelace"
+ end
+ ensure
+ teardown_sentry_test
+ end
+
# A blank query answers the recently updated list, the search page
# showing it before a word is typed and again once the input is
# cleared.