100% CPU usage

[tsvallender]

Description

I am fairly regularly (probably about once a day at a full-time job) having ruby-lsp hit 100% CPU and stay there until I restart the process. I’m using the latest ruby-lsp with the Rails extension, in Neovim. I’ve seen this behaviour in multiple Ruby versions but am mostly in 3.3.4 currently.

I’m more than happy to do some work trying to figure out what’s causing this but am unsure where to start, any pointers appreciated.

[andyw8]

@tsvallender if you are able to share the LSP logs from just before it causes the CPU to peak, then that may help us to diagnose the problem.

Also, are you are on the latest release? (v0.17.13)

[tsvallender]

@tsvallender if you are able to the LSP logs from just before it causes the CPU to peak, then that may help us to diagnose the problem.

Also, are you are on the latest release? (v0.17.13)

There hasn't been anything extra in the logs, and yes latest release. A colleague suggested stracing the process next time it happens so will see if that suggests anything. Always the way it doesn't happen when you're waiting for it...

[Earlopain]

I've had a hang somewhat recently (like maybe 1 month ago) as well but strace didn't show a thing. Process just kept doing things even after vscode was gone. Seems like this happens relativly often for you. How about you try adding the following to the ruby-lsp script:

Signal.trap("SIGUSR1") do
  output = +""
  Thread.list.each do |thr|
    output << ("-" * 40) << "\n"
    output << thr.inspect << "\n"
    output << thr.backtrace.join("\n") << "\n"
  end
  File.write("ruby-lsp-trace.log", output)
end if Signal.list.include?("USR1")

You can then do kill -USR1 pid where pid is somewhere in the output from ps -aux | grep ruby-lsp. I'm not sure how useful the output would actually be, its just something I used elsewhere. This should create a file with backtraces in the root of the project as long as you are not on windows.

This is all a bit awkward with the server auto-updating and all that, I wonder if this would be a generally useful addition for debugging things like this. There have been a few other issues with CPU pegging as their topic.

[tsvallender]

So it’s happened again, strace output is:

strace: Process 96120 attached with 5 threads
[pid 96259] wait4(96258,  <unfinished ...>
[pid 96256] futex(0x2d26bd40, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY <unfinished ...>
[pid 96239] epoll_wait(4,  <unfinished ...>
[pid 96120] read(0,

which is nigh-on ungrokkable to me I’m afraid, is it of any use to anyone else?

I've had a hang somewhat recently (like maybe 1 month ago) as well but strace didn't show a thing. Process just kept doing things even after vscode was gone. Seems like this happens relativly often for you. How about you try adding the following to the ruby-lsp script:
…

Great idea, I’ve just added that and verified it’s working so will try it next time…

[tsvallender]

Okay, so with that bit of code added in, I get the below, which to me seems to be pointing at this loop becoming infinite?

----------------------------------------
#<Thread:0x00007f2b0aa2a9e0 run>
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/ruby-lsp-0.17.13/lib/ruby_lsp/base_server.rb:28:in `backtrace'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/ruby-lsp-0.17.13/lib/ruby_lsp/base_server.rb:28:in `block (2 levels) in initialize'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/ruby-lsp-0.17.13/lib/ruby_lsp/base_server.rb:25:in `each'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/ruby-lsp-0.17.13/lib/ruby_lsp/base_server.rb:25:in `block in initialize'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/language_server-protocol-3.17.0.3/lib/language_server/protocol/transport/io/reader.rb:16:in `gets'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/language_server-protocol-3.17.0.3/lib/language_server/protocol/transport/io/reader.rb:16:in `read'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/ruby-lsp-0.17.13/lib/ruby_lsp/base_server.rb:48:in `start'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/sorbet-runtime-0.5.11525/lib/types/private/methods/_methods.rb:279:in `bind_call'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/sorbet-runtime-0.5.11525/lib/types/private/methods/_methods.rb:279:in `block in _on_method_added'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/ruby-lsp-0.17.13/exe/ruby-lsp:135:in `<top (required)>'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/bin/ruby-lsp:25:in `load'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/bin/ruby-lsp:25:in `<top (required)>'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/bundler-2.5.5/lib/bundler/cli/exec.rb:58:in `load'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/bundler-2.5.5/lib/bundler/cli/exec.rb:58:in `kernel_load'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/bundler-2.5.5/lib/bundler/cli/exec.rb:23:in `run'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/bundler-2.5.5/lib/bundler/cli.rb:451:in `exec'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/bundler-2.5.5/lib/bundler/vendor/thor/lib/thor/command.rb:28:in `run'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/bundler-2.5.5/lib/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/bundler-2.5.5/lib/bundler/vendor/thor/lib/thor.rb:527:in `dispatch'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/bundler-2.5.5/lib/bundler/cli.rb:34:in `dispatch'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/bundler-2.5.5/lib/bundler/vendor/thor/lib/thor/base.rb:584:in `start'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/bundler-2.5.5/lib/bundler/cli.rb:28:in `start'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/bundler-2.5.5/exe/bundle:28:in `block in <top (required)>'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/bundler-2.5.5/lib/bundler/friendly_errors.rb:117:in `with_friendly_errors'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/bundler-2.5.5/exe/bundle:20:in `<top (required)>'
/home/tsv/.rbenv/versions/3.3.4/bin/bundle:25:in `load'
/home/tsv/.rbenv/versions/3.3.4/bin/bundle:25:in `<main>'
----------------------------------------
#<Thread:0x00007f2aee8307c8 /home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/ruby-lsp-0.17.13/lib/ruby_lsp/base_server.rb:124 run>
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/ruby-lsp-0.17.13/lib/ruby_lsp/document.rb:236:in `=='
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/ruby-lsp-0.17.13/lib/ruby_lsp/document.rb:236:in `=='
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/ruby-lsp-0.17.13/lib/ruby_lsp/document.rb:236:in `find_char_position'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/ruby-lsp-0.17.13/lib/ruby_lsp/document.rb:114:in `locate_node'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/ruby-lsp-0.17.13/lib/ruby_lsp/requests/signature_help.rb:54:in `initialize'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/sorbet-runtime-0.5.11525/lib/types/private/abstract/declare.rb:37:in `new'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/sorbet-runtime-0.5.11525/lib/types/private/abstract/declare.rb:37:in `block in declare_abstract'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/ruby-lsp-0.17.13/lib/ruby_lsp/server.rb:638:in `text_document_signature_help'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/ruby-lsp-0.17.13/lib/ruby_lsp/server.rb:68:in `process_message'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/ruby-lsp-0.17.13/lib/ruby_lsp/base_server.rb:137:in `block in new_worker'
----------------------------------------
#<Thread:0x00007f2aee8afd20 /home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/ruby-lsp-0.17.13/lib/ruby_lsp/base_server.rb:33 sleep_forever>
<internal:thread_sync>:18:in `pop'
/home/tsv/.rbenv/versions/3.3.4/lib64/ruby/gems/3.3.0/gems/ruby-lsp-0.17.13/lib/ruby_lsp/base_server.rb:35:in `block in initialize'
----------------------------------------
#<Process::Waiter:0x00007f2aeeba6600 sleep>

[Earlopain]

Certainly looks like something that could happen there, thought the only way I can think of is when edits are received out-of-order.

I coincidentally had another case today myself, though I failed to capture a stacktrace (oops). I'm going to add some logging to that method should we be running into the same thing.

[vinistock]

We received other reports of this and the thread is quite helpful. The referenced loop essentially turns a line + character position into the index that represents that position in the string we use to store the document's source code.

I'm not sure how we wouldn't be able to find the requested line and end up in an infinite loop though. We process text edits under a mutex lock, exactly to avoid having a feature request like signature help landing in between a thread switch (and thus trying to execute in a partially updated document).

If anyone can reproduce this reliably, we need to understand what piece of code triggers the problem.

Alternatively, we can also raise from that method if we reached the end of the document without finding anything and then include the state of the document and the position we were looking for. That might help diagnose it.

[adam12]

I've been chasing this one for a few months now as well. An alternative method I've used to capture the stack trace reliably is the rbspy tool.

I've observed two things when this has triggered:

1. Many times the ruby-lsp process has no ppid (parent). I am not sure this is connected tho.
2. Frequently, the task eventually completes and CPU usage returns to normal, so it's not likely to be an infinite loop.

I theorized that we were thrashing the GC somehow but wasn't able to get any deeper. It's near impossible to trigger by hand or via ruby-lsp doctor. It would be nice to be able to get Vernier enabled in a reproduction to see what the GC activity is like in order to rule it out.

[denvermullets]

if it's helpful, this triggers on my machine almost always now - to the point i've had to uninstall and i reinstall when i see an update is pushed - but if there are commands or anything that you would like me to run to help diagnose i am more than willing to help.

i'm on an intel mac still, if that matters. i uninstalled it because i just got tired of it melting my battery down so quickly with bash processes that run 100%.

[vinistock]

I think adding an explicit error message if the scanner fails to find the right position will help diagnose this. I'll put something up for this.

@denvermullets meanwhile, a few questions to try to understand what's going on:

1. What editor are you using?
2. What's the editor's encoding? UTF-8, UTF-16 or UTF-32?
3. Which line breaks do you use? \n or \r\n?
4. Do you notice this happening when doing something specific in your code? Like for example, does it always happen when you use multibyte characters like emojis or japanese characters?

[denvermullets]

@denvermullets meanwhile, a few questions to try to understand what's going on:

1. What editor are you using?
2. What's the editor's encoding? UTF-8, UTF-16 or UTF-32?
3. Which line breaks do you use? \n or \r\n?
4. Do you notice this happening when doing something specific in your code? Like for example, does it always happen when you use multibyte characters like emojis or japanese characters?

sorry, missed this.

1. VS Code
2. UTF-8
3. none, the only line breaks in the small repos i see it happening only have the default \n in the rails setup files
4. i'm doing neither of those options

[Earlopain]

I've just had this happen to me again and the window I had open at the time was a git diff, and that file is just boring utf8. I noticed this while benchmarking and the average went way up so I'm confident it happened then.

I unfortunatly had no way to debug this since the server updated and I didn't put my things back in. strace only showed this:
futex(0x563c18caca04, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY, same as above.

[Aesthetikx]

This one happens to me essentially every day, neovim, M2 MacOS. I can help diagnose if someone points me in the right direction, no strace on MacOS so I can take a look with dtrace or equivalent perhaps.