Optimise the manual loading of dependent apps and modules.

[scottming]

I have always felt that the startup of 'lexical' is very slow. After some investigation, I found that this is mainly because we manually load all dependent modules, which takes about 2.4 seconds.

After removing this line: Enum.each(modules, &Code.ensure_loaded!/1), I found that 'lexical' works perfectly fine. Additionally, when we start the :server app,it will automatically load and start the dependent apps, so we don't need to manually load the dependent apps either.

before

CleanShot.2023-10-23.at.22.52.56.mp4

After

CleanShot.2023-10-28.at.10.33.35.mp4

[zachallaun]

I'll have to wait for @scohen for a more definitive answer, but I thought this is there for struct discovery, which happens in the compilation tracer. Or is this redundant and all that compilation happens anyways?

[scohen]

I’m pretty sure that it’s there so elixir sense can see the modules. You can’t see the modules unless they’re loaded.

[scottming]

@zachallaun

but I thought this is there for struct discovery, which happens in the compilation tracer.

yes, happens in the compilation tracer.

Or is this redundant and all that compilation happens anyways?

I think so.

[scottming]

@scohen

I’m pretty sure that it’s there so elixir sense can see the modules.

All of our Elixirsense calls occur in Project node, so it doesn't make sense to load the lx_xx module in the server node.

and I don't quite understand why ElixirSense needs to know about these modules that have already been namespace.

You can’t see the modules unless they’re loaded.

It seems that it doesn't affect the discovery of modules, and auto-completion works well in this branch.

[scohen]

@scottming there's definitely a reason that this is here, I didn't just plop that code in there for fun.

[scohen]

This might have been carried over from the old packaging, I believe releases are started in a mode where all modules need to be explicitly loaded at app start, while the current mode doesn't need that.
The problem is, any speed boost you perceive will be amortized over the life of the VM, the modules will still need to be loaded at some time, so that 2.4 seconds will happen while the user is editing code. It's a judgement call to say that doing this at startup is better or worse than doing this at runtime. I'm on the fence.

[scottming]

I acknowledge that the loading time will be amortized when used. However, when we let Elixir automatically load a small number of modules during usage, users won't perceive this impact. For example, the module Jason.Encode only takes 0.003 seconds.

So, I am more inclined to do this at runtime.

Manually loading

iex(1)> Code.loaded?(Jason.Encode)
false
iex(2)> :timer.tc(fn -> Code.ensure_loaded(Jason.Encode) end)
{3766, {:module, Jason.Encode}}
iex(3)>

Automatically Landing

iex(1)> Code.loaded?(Jason.Encode)
false
iex(2)> Jason.encode(%{})
{:ok, "{}"}
iex(3)> Code.loaded?(Jason.Encode)
true

[scottming]

Okay, today when I was using the commit that no longer performs loading, I did encounter some strange behaviors with autocompletion. For example, in VS Code, the autocompletion was not visible, and in Neovim, snippets were not being autocompleted.

10:54:29.581 [info] Local completions are [%LXical.RemoteControl.Completion.Candidate.Module{full_name: "Dummy.Application", metadata: %{}, name: "Application", summary: ""}, %LXical.RemoteControl.Completion.Candidate.Module{full_name: "Dummy.MixProject", metadata: %{}, name: "MixProject", summary: ""}, %LXical.RemoteControl.Completion.Candidate.Function{argument_names: ["atom"], arity: 1, name: "__info__", origin: "Dummy", type: :function, visibility: :public, spec: "@spec __info__(:attributes) :: keyword()\n@spec __info__(:compile) :: [term()]\n@spec __info__(:functions) :: [{atom, non_neg_integer}]\n@spec __info__(:macros) :: [{atom, non_neg_integer}]\n@spec __info__(:md5) :: binary()\n@spec __info__(:module) :: module()", metadata: %{builtin: true}}, %LXical.RemoteControl.Completion.Candidate.Function{argument_names: [], arity: 0, name: "hello", origin: "Dummy", type: :function, visibility: :public, spec: "", metadata: %{}}, %LXical.RemoteControl.Completion.Candidate.Function{argument_names: [], arity: 0, name: "module_info", origin: "Dummy", type: :function, visibility: :public, spec: "@spec module_info :: [{:module | :attributes | :compile | :exports | :md5 | :native, term}]", metadata: %{builtin: true}}, %LXical.RemoteControl.Completion.Candidate.Function{argument_names: ["key"], arity: 1, name: "module_info", origin: "Dummy", type: :function, visibility: :public, spec: "@spec module_info(:module) :: atom\n@spec module_info(:attributes | :compile) :: [{atom, term}]\n@spec module_info(:md5) :: binary\n@spec module_info(:exports | :functions | :nifs) :: [{atom, non_neg_integer}]\n@spec module_info(:native) :: boolean", metadata: %{builtin: true}}, %LXical.RemoteControl.Completion.Candidate.Function{argument_names: ["s"], arity: 1, name: "print_hello", origin: "Dummy", type: :function, visibility: :public, spec: "", metadata: %{}}]
10:54:29.607 [info] Emitting completions: [#Protocol.Types.Completion.Item<[detail: "Dummy.Application", kind: :module, label: "Application", sort_text: "079_Application", text_edit: %LXical.Document.Changes{document: #LXical.Document<path: "/Users/scottming/Code/dummy/test/dummy_test.exs", version: 16, dirty?: true, lines: %Lines<"defmodule DummyTest do..."(9 lines)>, ...>, edits: %LXical.Document.Edit{text: "Application", range: %LXical.Document.Range{start: %LXical.Document.Position{line: 6, character: 11, valid?: true, context_line: {:line, "    Dummy.", "\n", 6, true}, document_line_count: 9, starting_index: 1}, end: %LXical.Document.Position{line: 6, character: 11, valid?: true, context_line: {:line, "    Dummy.", "\n", 6, true}, document_line_count: 9, starting_index: 1}}}}]>, #Protocol.Types.Completion.Item<[detail: "Dummy.MixProject", kind: :module, label: "MixProject", sort_text: "079_MixProject", text_edit: %LXical.Document.Changes{document: #LXical.Document<path: "/Users/scottming/Code/dummy/test/dummy_test.exs", version: 16, dirty?: true, lines: %Lines<"defmodule DummyTest do..."(9 lines)>, ...>, edits: %LXical.Document.Edit{text: "MixProject", range: %LXical.Document.Range{start: %LXical.Document.Position{line: 6, character: 11, valid?: true, context_line: {:line, "    Dummy.", "\n", 6, true}, document_line_count: 9, starting_index: 1}, end: %LXical.Document.Position{line: 6, character: 11, valid?: true, context_line: {:line, "    Dummy.", "\n", 6, true}, document_line_count: 9, starting_index: 1}}}}]>, #Protocol.Types.Completion.Item<[insert_text_format: :snippet, kind: :function, label: "__info__(atom)", sort_text: "099___info__(atom)", text_edit: %LXical.Document.Changes{document: #LXical.Document<path: "/Users/scottming/Code/dummy/test/dummy_test.exs", version: 16, dirty?: true, lines: %Lines<"defmodule DummyTest do..."(9 lines)>, ...>, edits: %LXical.Document.Edit{text: "__info__(${1:atom})", range: %LXical.Document.Range{start: %LXical.Document.Position{line: 6, character: 11, valid?: true, context_line: {:line, "    Dummy.", "\n", 6, true}, document_line_count: 9, starting_index: 1}, end: %LXical.Document.Position{line: 6, character: 11, valid?: true, context_line: {:line, "    Dummy.", "\n", 6, true}, document_line_count: 9, starting_index: 1}}}}]>, #Protocol.Types.Completion.Item<[insert_text_format: :snippet, kind: :function, label: "hello()", sort_text: "094_hello()", text_edit: %LXical.Document.Changes{document: #LXical.Document<path: "/Users/scottming/Code/dummy/test/dummy_test.exs", version: 16, dirty?: true, lines: %Lines<"defmodule DummyTest do..."(9 lines)>, ...>, edits: %LXical.Document.Edit{text: "hello()", range: %LXical.Document.Range{start: %LXical.Document.Position{line: 6, character: 11, valid?: true, context_line: {:line, "    Dummy.", "\n", 6, true}, document_line_count: 9, starting_index: 1}, end: %LXical.Document.Position{line: 6, character: 11, valid?: true, context_line: {:line, "    Dummy.", "\n", 6, true}, document_line_count: 9, starting_index: 1}}}}]>, #Protocol.Types.Completion.Item<[insert_text_format: :snippet, kind: :function, label: "module_info()", sort_text: "099_module_info()", text_edit: %LXical.Document.Changes{document: #LXical.Document<path: "/Users/scottming/Code/dummy/test/dummy_test.exs", version: 16, dirty?: true, lines: %Lines<"defmodule DummyTest do..."(9 lines)>, ...>, edits: %LXical.Document.Edit{text: "module_info()", range: %LXical.Document.Range{start: %LXical.Document.Position{line: 6, character: 11, valid?: true, context_line: {:line, "    Dummy.", "\n", 6, true}, document_line_count: 9, starting_index: 1}, end: %LXical.Document.Position{line: 6, character: 11, valid?: true, context_line: {:line, "    Dummy.", "\n", 6, true}, document_line_count: 9, starting_index: 1}}}}]>, #Protocol.Types.Completion.Item<[insert_text_format: :snippet, kind: :function, label: "module_info(key)", sort_text: "099_module_info(key)", text_edit: %LXical.Document.Changes{document: #LXical.Document<path: "/Users/scottming/Code/dummy/test/dummy_test.exs", version: 16, dirty?: true, lines: %Lines<"defmodule DummyTest do..."(9 lines)>, ...>, edits: %LXical.Document.Edit{text: "module_info(${1:key})", range: %LXical.Document.Range{start: %LXical.Document.Position{line: 6, character: 11, valid?: true, context_line: {:line, "    Dummy.", "\n", 6, true}, document_line_count: 9, starting_index: 1}, end: %LXical.Document.Position{line: 6, character: 11, valid?: true, context_line: {:line, "    Dummy.", "\n", 6, true}, document_line_count: 9, starting_index: 1}}}}]>, #Protocol.Types.Completion.Item<[insert_text_format: :snippet, kind: :function, label: "print_hello(s)", sort_text: "094_print_hello(s)", text_edit: %LXical.Document.Changes{document: #LXical.Document<path: "/Users/scottming/Code/dummy/test/dummy_test.exs", version: 16, dirty?: true, lines: %Lines<"defmodule DummyTest do..."(9 lines)>, ...>, edits: %LXical.Document.Edit{text: "print_hello(${1:s})", range: %LXical.Document.Range{start: %LXical.Document.Position{line: 6, character: 11, valid?: true, context_line: {:line, "    Dummy.", "\n", 6, true}, document_line_count: 9, starting_index: 1}, end: %LXical.Document.Position{line: 6, character: 11, valid?: true, context_line: {:line, "    Dummy.", "\n", 6, true}, document_line_count: 9, starting_index: 1}}}}]>]

It's really weird, When I have time, I will further investigate.

[scohen]

part of the contract of the call to boot is that when it's done, the app is ready to use. Making things async breaks this contract.

[scottming]

Today I tried to pinpoint the real cause of the autocompletion failure. I discovered that ElixirSense does not cause it. Simply loading modules that start with LXical.Protocol.Types can resolve this issue.

But do you know why? @scohen

[scohen]

It's likely because it can't find the protocol modules can't be found because they're not loaded. I'm not sure why this is happening, but it worries me that it is, and I wonder what other issues we're not finding.

This change seems very risky to me.

[zachallaun]

My 2 cents: It's better to amortize load time during usage instead of up-front. Everyone will have their own preference, but I think that, as a general rule, time-to-things-working should be kept as low as possible.

I don't love the idea of special-casing LXical.Prototype.Types. What if we just eagerly load all of Lexical? It will still be much less than loading everything, but ensures that no Lexical plumbing is missing.

[scottming]

@zachallaun

I mostly agree with your point. However, loading all the modules starting with LXical is still too many.

I have been using this branch for two days now, and I haven't encountered any other issues so far.

I speculate that manually loading all the modules starting with LXical.Prototype.Types is successful because there might be some issue with deftype preventing Elixir from loading them when they are used, or there might be a problem with the automatic loading process. By the way, these modules all contain deftype.

[scottming]

I explored this further, and it may be a problem with defenum, which doesn't encode the atom into a number when Jason.encode, but instead turns it into string

{
  "label":"print_hello(s)",
  "kind":3,
  "sortText":"094_print_hello(s)",
  "textEdit":{
    "range":{
      "start":{
        "line":6,
        "character":10
      },
      "end":{
        "line":6,
        "character":10
      }
    },
    "newText":"print_hello(${1:s})"
  },
  "insertTextFormat":"snippet" # this line
}

[scohen]

I mostly agree with your point. However, loading all the modules starting with LXical is still too many.

Zach was suggesting loading modules starting with LXical.Protocol.Types, not LXical. How does that perform?

[scohen]

I explored this further, and it may be a problem with defenum, which doesn't encode the atom into a number

The problem must be elsewhere, this seems to work correctly:

iex(2)> Lexical.Protocol.Types.Completion.Item.new(insert_text_format: :snippet, label: "yep") |> Jason.encode
{:ok, "{\"insertTextFormat\":2,\"label\":\"yep\"}"}

[scohen]

@scottming I think this points to a bigger problem with this PR.
I suspect what's happening is that the Jason.Encoder implementation for the type isn't being found, and it's reverting back to the map implementation, thus atoms are encoded as strings.

Protocols are another thing that i believe need to be loaded before we have a functional app.

...this PR continues to worry me.

[scottming]

I suspect what's happening is that the Jason.Encoder implementation for the type isn't being found, and it's reverting back to the map implementation, thus atoms are encoded as strings.

Your guess is correct. Thank you for this guidance.

@scohen @zachallaun

I think I have identified the root cause of the problem. In these lines, when the module is not loaded, it falls back to the previous value.

A module will be automatically loaded when used, but these lines

lexical/apps/proto/lib/lexical/proto/field.ex

Lines 277 to 280 in ba21277

	if function_exported?(module, :encode, 1) do
	module.encode(field_value)
	else
	{:ok, field_value}

prevent the module from being used, resulting in this strange issue.

However, for this kind of situation, I'm not sure how to write unit tests. How can I define a module within a test that is initially not loaded, but can still be ensure_loaded? later on?

[scohen]

I'm R- on this PR. It's too dangerous.

I looked for function_exported? and it occurs in modules we don't control (like Future.Code and Code).

[scottming]

I'm R- on this PR. It's too dangerous.

I looked for function_exported? and it occurs in modules we don't control (like Future.Code and Code).

@scohen I understand your concern. If we really must use load_all_modules of all the dep apps, could we place load_all_modules after the :server app starts, similar to --preload-modules in mix app.start?

Since load_all_modules is not a necessary condition for starting the server, this could also allow us to see the progress message more quickly(For people who launch nvim dozens of times a day, like me, this is a much better experience).

[scohen]

could we place load_all_modules after the :server app starts

The app can start, but the modules need to be loaded before it's initialized

[scohen]

Since load_all_modules is not a necessary condition for starting the server

You have no idea if this is true or not. It might be true today (and i'm not sure it is), but it's possible that it might not be true tomorrow. This is why this change is so risky.

[scottming]

I still prefer to initialize as fast as possible.

The changes in the last two commits should have very low risk. However, if you still perceive some risk, let's keep only the commit with Code.ensure_all_loaded!(modules), as that alone can speed up by approximately 1.5 seconds.

[scohen]

My suggestion is to switch back to the erlang functions and use ensure_modules_loaded and see if that's faster. It might be, since each call to Code in the previous each function requires a trip in and out of the code server.

It might also be faster to collect all the modules that need to be loaded from each application and load them all once

[scottming]

It might also be faster to collect all the modules that need to be loaded from each application and load them all once

The test results indicate that individually loading all modules for each app is faster compared to loading all modules of all apps at once.

each app loading

    Application.ensure_loaded(app_name)
    modules = Application.spec(app_name, :modules)
    Code.ensure_all_loaded!(modules)

results:

~/Code/lexical @3a2c5e68 !1 ❯ ./_build/dev/package/lexical/bin/start_lexical.sh                  5s   25.3.2.7  1.15.7-otp-25
Detected Elixir through asdf: /Users/scottming/.asdf/installs/elixir/1.15.7-otp-25/bin/elixir
[(server 0.3.0) lib/lexical/server/boot.ex:26: Lexical.Server.Boot.start/0]
time #=> 613491

^C
BREAK: (a)bort (A)bort with dump (c)ontinue (p)roc info (i)nfo
       (l)oaded (v)ersion (k)ill (D)b-tables (d)istribution
^C%                                                                                                                             
~/Code/lexical @3a2c5e68 !1 ❯ ./_build/dev/package/lexical/bin/start_lexical.sh                       25.3.2.7  1.15.7-otp-25
Detected Elixir through asdf: /Users/scottming/.asdf/installs/elixir/1.15.7-otp-25/bin/elixir
[(server 0.3.0) lib/lexical/server/boot.ex:26: Lexical.Server.Boot.start/0]
time #=> 630133

^C
BREAK: (a)bort (A)bort with dump (c)ontinue (p)roc info (i)nfo
       (l)oaded (v)ersion (k)ill (D)b-tables (d)istribution
^C%                                                                                                                             
~/Code/lexical @3a2c5e68 !1 ❯ ./_build/dev/package/lexical/bin/start_lexical.sh                       25.3.2.7  1.15.7-otp-25
Detected Elixir through asdf: /Users/scottming/.asdf/installs/elixir/1.15.7-otp-25/bin/elixir
[(server 0.3.0) lib/lexical/server/boot.ex:26: Lexical.Server.Boot.start/0]
time #=> 613521

load all at once

  modules =
    Enum.flat_map(app_names, fn app_name ->
      Application.ensure_loaded(app_name)
      Application.spec(app_name, :modules)
    end)

  Code.ensure_all_loaded!(modules)

results

~/Code/lexical cancel-manually-load-deps ⇡1 !1 ❯ ./_build/dev/package/lexical/bin/start_lexical.sh
Detected Elixir through asdf: /Users/scottming/.asdf/installs/elixir/1.15.7-otp-25/bin/elixir
[(server 0.3.0) lib/lexical/server/boot.ex:26: Lexical.Server.Boot.start/0]
time #=> 658426

^C
BREAK: (a)bort (A)bort with dump (c)ontinue (p)roc info (i)nfo
      (l)oaded (v)ersion (k)ill (D)b-tables (d)istribution
^C%                                                                                                                             
~/Code/lexical cancel-manually-load-deps ⇡1 !1 ❯ ./_build/dev/package/lexical/bin/start_lexical.sh    25.3.2.7  1.15.7-otp-25
Detected Elixir through asdf: /Users/scottming/.asdf/installs/elixir/1.15.7-otp-25/bin/elixir
[(server 0.3.0) lib/lexical/server/boot.ex:26: Lexical.Server.Boot.start/0]
time #=> 655624

^C
BREAK: (a)bort (A)bort with dump (c)ontinue (p)roc info (i)nfo
      (l)oaded (v)ersion (k)ill (D)b-tables (d)istribution
^C%                                                                                                                             
~/Code/lexical cancel-manually-load-deps ⇡1 !1 ❯ ./_build/dev/package/lexical/bin/start_lexical.sh    25.3.2.7  1.15.7-otp-25
Detected Elixir through asdf: /Users/scottming/.asdf/installs/elixir/1.15.7-otp-25/bin/elixir
[(server 0.3.0) lib/lexical/server/boot.ex:26: Lexical.Server.Boot.start/0]
time #=> 656506

^C
BREAK: (a)bort (A)bort with dump (c)ontinue (p)roc info (i)nfo
      (l)oaded (v)ersion (k)ill (D)b-tables (d)istribution
^C%