Timeouts on querying search store

[katafrakt]

On a fairly large codabase, I very often see timeouts like this in the logs:

09:15:13.016 [error] Task #PID<0.243.0> started from XPExpert terminating
** (stop) {:exception, {:timeout, {GenServer, :call, [XPEngine.Search.Store, {:exact, "JumpWeb.Admin.FeatureFlagDefinitionsLive.rollout_state_badge/2", [subtype: :definition]}, 5000]}}}
    (kernel 10.2.7.3) erpc.erl:1366: :erpc.call/5
    (xp_expert 0.1.0) lib/expert/provider/handlers/go_to_definition.ex:21: XPExpert.Provider.Handlers.GoToDefinition.handle/2
    (xp_expert 0.1.0) lib/expert.ex:121: XPExpert.handle_request/2
    (xp_gen_lsp 0.11.2) lib/gen_lsp.ex:369: anonymous fn/2 in XPGenLSP.loop/3
    (xp_telemetry 1.3.0) /Users/pawel.sw/dev/expert/apps/expert/deps/telemetry/src/telemetry.erl:324: :xp_telemetry.span/3
    (xp_gen_lsp 0.11.2) lib/gen_lsp.ex:368: anonymous fn/5 in XPGenLSP.loop/3
    (xp_gen_lsp 0.11.2) lib/gen_lsp.ex:592: anonymous fn/4 in XPGenLSP.attempt/4
    (elixir 1.19.4) lib/task/supervised.ex:105: Task.Supervised.invoke_mfa/2
Function: #Function<0.130722175/0 in XPGenLSP.attempt/4>
    Args: []
09:15:13.018 [error] Child :undefined of Supervisor :expert_task_queue terminated
** (exit) {:exception, {:timeout, {GenServer, :call, [XPEngine.Search.Store, {:exact, "JumpWeb.Admin.FeatureFlagDefinitionsLive.rollout_state_badge/2", [subtype: :definition]}, 5000]}}}

After seeing this, functions like go to definition and hover seem to be severely impaired in the project (although definition sometimes works, I assume by falling back to ElixirSense).

I'm seeing this for :exact, :find_by_subject and :delete_by_path.

Looking at ets.ex this corresponds to GenServer calls that do not have :infinity timeout set. Indeed, adding :infinity to all the calls inside Ets backend makes the error go away and things generally work.

However, I'm not sure it's a desirable solution. Perhaps a better approach would be to catch the timeout, return error tuple or empty results and just log the warning about timeout exceeded?

[doorgan]

Do we know why it times out or why it takes so much time?
Preferably we would have Expert work on large codebases before having to degrade its functionality

[katafrakt]

I added some additional logging, like this:

  @impl Backend
  def find_by_subject(subject, type, subtype) do
    GenServer.call(genserver_name(), {:find_by_subject, [subject, type, subtype]})
  catch
    :exit, {:timeout, _} = reason ->
      {time_us, result} = :timer.tc(fn -> GenServer.call(genserver_name(), {:find_by_subject, [subject, type, subtype]}, :infinity) end)
      Logger.warning("find_by_subject/3 timed out, retried in #{div(time_us, 1000)}ms, result: #{inspect(result)}")
      exit(reason)
  end

... and I see that the queries simply sometimes take longer than the default timeout of 5 seconds. Is it possible that ETS lookups are just so slow on larger codebases?

10:30:09.504 [warning] find_by_subject/3 timed out, retried in 6406ms, result: []

[katafrakt]

Ok, I debugged some more and it seems it's because the Ets GenServer is blocked by match_delete operation on ets. I think it's this one, where there is query_by_subject with only path provided - the path is 4th field in the structure, so the query needs to to a full scan of the ets table. At least that's how I understand https://www.erlang.org/doc/apps/stdlib/ets.html#module-table-traversal

For reference, in my case the expert_search_v3 table has 1,541,638 entries.

I actually have a code change that replaces this query_by_subject with a number of more performant queries to avoid the full scan. And I cannot reproduce the timeout anymore. So if this explanation sounds plausible to you, I can push it.

[doorgan]

@katafrakt that sounds reasonable, if you confirmed we can get better performance and no regressions, let's go with that!

[katafrakt]

On it. Although I think there might be more to it. For example, looking at this:

❯ la -lah api/.expert/indexes/ets/28.3/1.19.4/3/
total 2544784
drwxr-xr-x@ 4 pawel.sw  staff   128B Jan 15 16:49 ./
drwxr-xr-x@ 3 pawel.sw  staff    96B Jan  8 17:14 ../
-rw-r--r--@ 1 pawel.sw  staff   1.2G Jan 15 16:49 07417183988248211507.checkpoint
-rw-r--r--@ 1 pawel.sw  staff    17M Jan 15 16:49 updates.wal

The checkpoint file has more than 1GB. Just writing it to disk will take time (and block). Same with replaying 17M WAL probably.

[doorgan]

I guess that's one more point in favor of doing the migration to an SQLite index. I have some of that work started in dorgan/sqlite but I hit a road block because namespacing doesn't play nice with NIFs(it doesn't rename references to the Elixir modules in the C source, and causes runtime crashes), and we basically need to vendor Exqlite and have our own release CI pipeline

Edit: I'm not suggesting we do this now, but my understanding is that it should help quite a bit

[katafrakt]

It probably could!

For now, I measured that loading my checkpoint file takes more than 8 seconds, during which the GenServer is blocked. Any request to it with timeout 5000 will fail. I think it would help to check the loaded? of the Search.Store.State and not make requests to the Ets GenServer if it's false.

[katafrakt]

I wonder if measuring all ets calls and logging a warning if they take longer than, say, 2 seconds would be useful in general for future debugging.

[mkaput]

I wonder if measuring all ets calls and logging a warning if they take longer than, say, 2 seconds would be useful in general for future debugging.

Makes sense to me in this particular case. In general, this could quickly become too noisy