Slow startup

[laughedelic]

I noticed that it takes around 40s to launch the server and it wasn't like this before (I remember times <10s before we renamed it to metals). I tried to narrow down the problem but so far don't know much. Here's what I see in the Atom logs (cleaned up for clarity):

18:38:26.679 Scala (Metals) Server starting "/Users/laughedelic/dev/laughedelic/metals/"
18:38:27.174 Scala (Metals) rpc.sendRequest initialize sending Object
18:38:27.477 Scala (Metals) stderr �[2K

[ long wait, then first logging messages from the server ]

18:39:09.290 Scala (Metals) rpc.onNotification (2) ["window/logMessage", Object]

[ >400 logMessage notifications ]

18:39:11.744 Scala (Metals) rpc.sendRequest initialize received (44568ms) Object {capabilities: Object}
18:39:11.776 Scala (Metals) rpc.sendNotification initialized Object {}
18:39:11.779 Scala (Metals) rpc.sendNotification workspace/didChangeConfiguration Object {settings: Object}
18:39:11.797 Scala (Metals) rpc.sendNotification textDocument/didOpen Object {textDocument: Object}
18:39:11.824 Scala (Metals) Server started "/Users/laughedelic/dev/laughedelic/metals/" (pid 7203)

Similarly in VSCode you can see open the Output panel for Log (Extension Host) and compare the time between

[2018-03-25 18:48:12.368] [exthost8] [info] ExtensionService#_doActivateExtension gabro.vscode-metals {"startup":false,"activationEvent":"onLanguage:scala"}

and the first message in .metals/metals.log:

18:48:46.179 INFO  s.meta.metals.Main$ - Starting server in /Users/laughedelic/dev/laughedelic/metals

You can notice in the Atom log that [2K thing emitted by coursier when it starts. It happens immediately, so the time is spent between the moment coursier process started and the first Starting server message. Which is very confusing, because the main method doesn't do anything special before that first log. Also if I try to start server manually calling cousier launch ..., it starts almost instantly.

Does anybody have a clue what could be the reason?

[olafurpg]

Hmmm. I am unable to reproduce, the server typically starts instantly for me 🤔

Have you noticed slow startup @gabro ?

[gabro]

I haven't noticed it, but I'll pay more attention from now on.

[laughedelic]

OK, this is a useful feedback. I'll try to investigate what's wrong with my setup 🤔

[laughedelic]

I figured out where is the problem, but haven't found a solution yet. The issue is related to Node's child process spawn and the way it works with stdin redirection. If stdin is ignored

cp.spawn(
  'coursier', ['launch', 'org.scalameta:metals_2.12:0.1-SNAPSHOT', '-M', 'scala.meta.metals.Main'], 
  { stdio: ['ignore', 'pipe', 'pipe'] }
)

it takes ~4s to start. But if it's piped to the parent process (which is needed for the LSP communication)

cp.spawn(
  'coursier', ['launch', 'org.scalameta:metals_2.12:0.1-SNAPSHOT', '-M', 'scala.meta.metals.Main'], 
  { stdio: ['pipe', 'pipe', 'pipe'] }
)

it takes ~34s.

Probably, only the Node on macOS is affected. I'll write later some snippet that you can paste into the Node REPL and test it. Meanwhile I'm trying to make some workaround.

Related issues:

• child_process: async spawn methods not closing stdin nodejs/node#2339
• child_process.spawn execution is significantly slower than running command directly from shell nodejs/node#7652
• Slow execution of phpcbf soderlind/vscode-phpcbf#2
• Very slow child_process.spawn stdout stream performance on macOS nodejs/node#3429 (similar, but with stdout)

In some similar cases it's recommended to call .stdin.end() on the spawned process, but it doesn't work and I think it cannot/shouldn't be used in our case anyway.

[jvican]

I cannot reproduce the issue, server startup in atom is instant for me.

[laughedelic]

@jvican I'm glad that it doesn't affect you 😄 I think it's macOS-specific. Could you paste here output of apm -v? Just to see which version of Node is used in your Atom.

[jvican]

jvican in ~/Downloads                                                                  [21:57:40] 
> $ apm -v
(node:26497) [DEP0022] DeprecationWarning: os.tmpDir() is deprecated. Use os.tmpdir() instead.
apm  1.19.0
npm  5.7.1
node 9.10.1 x64
atom 1.25.0
python 2.7.14
git 2.16.3

[olafurpg]

In #332, we introduce a Scala source file indexer that processes ~800k loc/s and enables at least goto definition to work. For "find all references" we may still need more expensive indexing but I am optimistic we can implement it in a much more lightweight manner than before. Every new feature will at least need to meet certain performance requirements.