Global search: eleven seconds to under one

Between migration runs, a user told me two things about the app's global search: it was slow, and its loading state was not interactive. The second complaint turned out to be a symptom of the first. This is the diagnosis of the first, with the numbers, and the two traps I fell into on the way to a ten-fold fix.

Measure from the log, by request id

Rails logs a request's path on its Started line and its duration on its Completed line, and the two can be dozens of lines apart under load. The request id tag on each line is what pairs them. One awk over the web log:

awk '
  /Started GET "\/api\/v1\/search/ {
    match($0, /^\[[^]]+\]/); id = substr($0, RSTART, RLENGTH)
    match($0, /"[^"]+"/);    path[id] = substr($0, RSTART + 1, RLENGTH - 2)
  }
  /\] Completed / {
    match($0, /^\[[^]]+\]/); id = substr($0, RSTART, RLENGTH)
    if (id in path) { sub(/^\[[^]]+\] Completed /, ""); print path[id] "  ->  " $0; delete path[id] }
  }
' web.log

/api/v1/search?q=sikandar               -> 200 OK in 242ms (ActiveRecord: 214.5ms, 40 queries)
/api/v1/search?q=ANNA+B+LARSEN+DEAL     -> 200 OK in 8300ms
/api/v1/search?q=ANNA+B+LARSEN+DEAL%22  -> 200 OK in 11334ms

One word: a quarter of a second. Four words: eight to eleven seconds. That ratio is the first clue — the cost is not "search", it is something that compounds per token.

The shape of the query

Global search matches five sections — deals, leads, contacts, companies, tasks — and each section ANDs one predicate per token, where each predicate is an OR of leading-wildcard ILIKE across the section's columns:

WHERE (title ILIKE '%anna%' OR first_name ILIKE '%anna%' OR ...)
  AND (title ILIKE '%b%'    OR first_name ILIKE '%b%'    OR ...)
  AND ...

A leading wildcard is unindexable by a b-tree, so the columns carry gin_trgm_ops indexes, and Postgres can serve an OR of indexable arms as a BitmapOr. Every section had those indexes. Four of the five sections answered in under twelve milliseconds for the four-token query.

The fifth was deals, and it was different in one way: its OR spanned three tables.

SELECT deals.id FROM deals
  LEFT JOIN contacts  ON contacts.id  = deals.contact_id
  LEFT JOIN companies ON companies.id = deals.company_id
WHERE deals.tenant_id = $1 AND deals.discarded_at IS NULL
  AND (deals.title ILIKE '%anna%' OR contacts.first_name ILIKE '%anna%'
       OR contacts.last_name ILIKE '%anna%' OR companies.name ILIKE '%anna%')
  AND ( ... same for each token ... )

Postgres builds a BitmapOr only from arms on the same relation. An OR across a join is evaluated after the join, so every trigram index on all three tables goes unused, and the plan is a hash join over a sequential scan of every contact in the tenant, per token:

->  Parallel Seq Scan on contacts  (actual time=0.021..1935.145 rows=172920 loops=3)
Execution Time: 2423.819 ms

2.4 seconds for the section alone, in isolation, on a quiet database. Under load, eight to eleven.

Fix one: one arm per table

The cure is to give the planner arms it can index: one single-table subquery per column group, combined with UNION, and the AND across tokens applied on the outer relation so that the caller's authorisation scope and its result cap still apply to the fully-ANDed set:

DEAL_MATCH_UNION = <<~SQL.squish.freeze
  SELECT d.id FROM deals d
   WHERE d.tenant_id = :t AND d.discarded_at IS NULL
     AND d.title ILIKE :p
  UNION
  SELECT d2.id FROM deals d2
    JOIN contacts c ON c.id = d2.contact_id
   WHERE d2.tenant_id = :t AND d2.discarded_at IS NULL
     AND c.discarded_at IS NULL
     AND (c.first_name ILIKE :p OR c.last_name ILIKE :p)
  UNION
  SELECT d3.id FROM deals d3
    JOIN companies co ON co.id = d3.company_id
   WHERE d3.tenant_id = :t AND d3.discarded_at IS NULL
     AND co.discarded_at IS NULL
     AND co.name ILIKE :p
SQL

def deals
  tokens.reduce(@scope) do |scope, token|
    scope.where("deals.id IN (#{DEAL_MATCH_UNION})", t: @tenant_id, p: "%#{sanitize(token)}%")
  end
end

Trap one: the partial index predicate

My first draft of that union measured 12.6 seconds — five times slower than the join it replaced. The plan showed the contacts arm still sequentially scanning. The reason was one predicate: every trigram index in this schema is partial, defined WHERE discarded_at IS NULL, and my joined arms filtered discarded_at on the outer table but not on the joined one. A partial index is usable only when the query's predicate implies the index's. Add c.discarded_at IS NULL and co.discarded_at IS NULL, and the arms go to their indexes.

That is also the right semantics — a deleted contact should not surface a deal — but I did not choose it for semantics. I chose it because the plan said so.

Trap two: the one-letter token

With the predicate in place, the four-token query still took three seconds, and the plan still had one sequential scan on contacts: the arm for the token B. A trigram index needs three characters to match a %pattern%; a one- or two-character token cannot use it at all, and the planner falls back to scanning the whole table for that arm. The query's minimum length of three applied to the whole string, not to each token.

So tokens under three characters are dropped from the match — the other tokens still AND — unless the query has nothing else:

MAX_TOKENS       = 5
MIN_TOKEN_LENGTH = 3

def self.tokens(q)
  tokens = q.split(/\s+/).first(MAX_TOKENS)
  long   = tokens.select { |t| t.length >= MIN_TOKEN_LENGTH }
  long.empty? ? tokens : long
end

"ANNA LARSEN DEAL" still finds the deal. "B" never reaches Postgres.

The numbers

Measured on the real tenant with EXPLAIN (ANALYZE), same four-token query:

The 787 ms is honest work rather than a defect: in this tenant a particular word appears in nearly every deal title, so that token alone matches the whole tenant, and the AND has a hundred thousand ids to intersect. The two-token and one-token cases are the shape most searches take.

Where the code lives

Both unions — the old contacts one and the new deals one — started life in the controller, next to the params parsing and the response shaping. My first instinct was to leave the new one beside the old one for consistency. A reviewer asked, reasonably, whether a query belongs in a controller at all. It does not; the existing one was debt, not precedent.

So the matching layer is now a query object: it takes a scope the controller has already authorised, and returns a relation. The controller keeps what a controller owns — params, policy_scope, the per-section cap and ordering, and the response — and lost 119 lines.

class SearchMatchQuery
  def initialize(scope, q, tenant_id:)
    @scope, @q, @tenant_id = scope, q.to_s, tenant_id
  end

  def tokenized(columns)    # single-table sections: AND of ORs across `columns`
  def contacts              # UNION arms on contacts, emails, companies
  def deals                 # UNION arms on deals, contacts, companies
end

# in the controller
def matcher(scope, q) = SearchMatchQuery.new(scope, q, tenant_id: current_tenant.id)
capped(matcher(id_scope, q).deals, :deals)

The unions carry tenant_id themselves, because they are subqueries on other tables and a matcher must never widen what the outer scope allows; tenant isolation is one of the request specs.

The guards, and a third trap

The request spec captures every SQL statement the endpoint issues and asserts the shape — the deals scan contains UNION and no LEFT OUTER JOIN "contacts" — plus behaviour: a deal is found by title, by its contact's name and by its company's name; two tokens landing on different tables still AND; another tenant's deals never leak through the subquery; and the one-letter token never reaches Postgres.

That last assertion cost me a failing test. I wrote it as "the captured SQL must not contain '%b%'" and "must contain '%anna%'" — and the second failed, because where("… ILIKE :p", p: …) sends the pattern as a bind, not as text. The SQL contained $1. Which means the first assertion was passing vacuously. The fix reads the binds from the notification payload:

sub = lambda do |_name, _start, _finish, _id, payload|
  binds = payload[:type_casted_binds]
  binds = binds.call if binds.respond_to?(:call)
  seen << payload[:sql] << Array(binds).flatten.map(&:to_s).join(" ")
end
ActiveSupport::Notifications.subscribed(sub, "sql.active_record") { get "/api/v1/search", params: { q: "anna b larsen", type: "deals" } }

expect(seen.join("\n")).to include("%anna%")
expect(seen.join("\n")).not_to include("%b%")

A negative assertion on captured SQL text is only as good as its positive twin. Always write the pair.

The loading state that read as frozen

The client side of the complaint was real too, and cheap. During a slow search the launcher showed three skeleton rows and swallowed Enter for the whole wait, so an eleven-second search looked like a hung app. Past a second and a half it now says it is still searching and that Enter opens the full results page, and Enter does so whenever there is a real query and nothing to pick yet. The same afternoon fixed a mailbox list that flickered on "load older": a bigger page size was a new query key with no placeholder data, so the list unmounted into its skeleton and rebuilt — keepPreviousData and it holds still.

Both are the same class of defect: a loading state that gives the user nothing to do. Server fixes shrink the wait; the client still has to be honest about the wait that remains.

What generalises

• Pair Started and Completed by request id. The duration line never carries the path. Any per-endpoint latency question starts with that awk.
• An OR across a join is a sequential scan however many indexes the columns have. Split it into single-table arms and UNION them.
• Partial indexes need their predicate in every arm that wants them. EXPLAIN will tell you; the plan is the only thing that will.
• Trigram matching has a per-token floor. A length check on the whole query does not protect you from %b%.
• Queries belong in query objects, even when the file they'd join is already doing it wrong.
• Assert on binds, not on SQL text, and never write a not_to include without the to include that proves the capture works.