close
Skip to content

Caching never completes and solargraph uses 100% CPU #1169

@gongfarmer

Description

@gongfarmer

Symptoms

  • Solargraph constantly runs caching threads for system gems.
  • Neovim constantly displays notifications that say "Caching gem" and "done Caching gem".
  • Solargraph in this state takes 100% of one CPU.
  • Multiple nvim sessions in different terminals can create multiple instances of this

This is happening daily for me, for several months now.
The problem is intermittent, it may happen several times a day but rarely skips a day.
On one particularly bad day, my entire system locked up from this problem, I couldn't ssh in and the root cause appeared to be solargraph using all available CPU.

I have previously commented about this same issue:
#971 (comment)

System details

  • solargraph v0.58.2 running within neovim 0.11
  • debian 13
  • running on debian-packaged system ruby v3.3.8
  • my project source code has no Gemfile

Investigation

The existing log messages didn't explain what was going on, so I added some more detailed log messages so get some visibility into what threads were running and when.
All log messages are from Library#sync_catalog and Library#cache_next_gemspec, plus one in the Library constructor.
The log message context is clear as I added the method name to the start of the log message.
Most log messages are now prefixed with a thread id (Thread.current.object_id).

Some observations:

  • this constant caching loop only happens with system-installed gems (eg. /usr/share/rubygems-integration/all/gems/mail-2.8.1), never with my own source code
  • multiple threads are spawned to cache the same gems
  • the number of threads spawned varies, but eventually ends up growing to around 8-10
  • each thread runs to completion and then spawns a new thread!

Solargraph's thread management code is difficult to follow, mainly due to this pattern:

  • Library#sync_catalog calls #cache_gemspec
  • Library#cache_next_gemspec creates new Thread
  • Library#cache_next_gemspec then calls #sync_catalog from within the new child thread
    This looks like an infinite loop, and behaves like one on my system.

New threads for caching the same gem are constantly being created, and the older threads are constantly completing.
This can be seen in the logging I captured. The number in [] is the Thread.current.object_id.

This set of log messages repeats forever:

I, [2026-02-15T14:19:46.697306 #666259]  INFO -- : ==== Solargraph::Library.initialize(workspace: /home/fhanson/git3/build/build/src, name: nil)
I, [2026-02-15T14:19:48.166105 #666210]  INFO -- :   [543800] Cached mail 2.8.1
I, [2026-02-15T14:19:48.166384 #666210]  INFO -- : [543800] #sync_catalog, @sync_count == 1 called on thread 543800
I, [2026-02-15T14:19:48.166403 #666210]  INFO -- : Cataloging /home/fhanson/git3/build
I, [2026-02-15T14:19:48.205427 #666210]  INFO -- : [543800] #sync_catalog Catalog complete (235 files, 26338 pins)
I, [2026-02-15T14:19:48.205515 #666210]  INFO -- : [543800] #sync_catalog 5 uncached YARD gemspecs (["mail", "mini_mime", "net-imap", "date", "net-pop"])
I, [2026-02-15T14:19:48.205534 #666210]  INFO -- : [543800] #sync_catalog 5 uncached RBS collection gemspecs ["mail", "mini_mime", "net-imap", "date", "net-pop"]
I, [2026-02-15T14:19:48.205544 #666210]  INFO -- : [543800] #cache_next_gemspec
I, [2026-02-15T14:19:48.205564 #666210]  INFO -- : [543800] #cache_next_gemspec These 10 cachable specs exist: ["mail", "mini_mime", "net-imap", "date", "net-pop", "mail", "mini_mime", "net-imap", "date", "net-pop"]
I, [2026-02-15T14:19:48.205617 #666210]  INFO -- : [543800] #cache_next_gemspec: Caching mail 2.8.1
I, [2026-02-15T14:19:48.205795 #666210]  INFO -- : [543800] #cache_next_gemspec created new Thread for caching mail (which may or may not have run yet)
I, [2026-02-15T14:19:48.205941 #666210]  INFO -- : [543800] Active threads in this process: 10
I, [2026-02-15T14:19:48.205987 #666210]  INFO -- :      538120 status: sleep, alive?: true
I, [2026-02-15T14:19:48.206024 #666210]  INFO -- :      464800 status: sleep, alive?: true
I, [2026-02-15T14:19:48.206062 #666210]  INFO -- :      2680 status: sleep, alive?: true
I, [2026-02-15T14:19:48.206096 #666210]  INFO -- :      538140 status: sleep, alive?: true
I, [2026-02-15T14:19:48.206131 #666210]  INFO -- :      543740 status: sleep, alive?: true
I, [2026-02-15T14:19:48.206164 #666210]  INFO -- :      543780 status: sleep, alive?: true
I, [2026-02-15T14:19:48.206199 #666210]  INFO -- :      543820 status: sleep, alive?: true
I, [2026-02-15T14:19:48.206233 #666210]  INFO -- :      543800 status: run, alive?: true
I, [2026-02-15T14:19:48.206268 #666210]  INFO -- :      543860 status: sleep, alive?: true
I, [2026-02-15T14:19:48.206301 #666210]  INFO -- :      543840 status: sleep, alive?: true
I, [2026-02-15T14:19:48.206335 #666210]  INFO -- : [543800] #sync_catalog -> method finished
I, [2026-02-15T14:19:48.206370 #666210]  INFO -- :   [543800] #cache_next_gemspec thread finished (caching "mail")
I, [2026-02-15T14:19:48.205866 #666210]  INFO -- :   [543840] #cache_next_gemspec New thread 543840 for caching("mail")
I, [2026-02-15T14:19:48.206457 #666210]  INFO -- : report_cache_progress("mail", 4)
I, [2026-02-15T14:19:48.206520 #666210]  INFO -- : report_cache_progress["mail"] @cache_progress.begin("mail (+4)", 0)
I, [2026-02-15T14:19:48.206576 #666210]  INFO -- : report_cache_progress["mail"] notify_observers(#<Solargraph::LanguageServer::Progress:0x00007f251f6a6cd8 @title="Caching gem", @uuid="2d426d2f-9a6a-4c50-8f5d-3c3b8ff02678", @percen>
I, [2026-02-15T14:19:48.206784 #666210]  INFO -- : report_cache_progress["mail"] @cache_progress.report("mail (+4)",  0)
I, [2026-02-15T14:19:48.206859 #666210]  INFO -- : report_cache_progress["mail"] true})
I, [2026-02-15T14:19:48.206994 #666210]  INFO -- : report_cache_progress["mail"] notify_observers

In my captured logging, the block of messages above is followed by this block:

I, [2026-02-15T14:19:48.960269 #666266]  INFO -- : ==== Solargraph::Library.initialize(workspace: /home/fhanson/git3/build/build/src, name: nil)
I, [2026-02-15T14:19:50.413861 #666210]  INFO -- :   [543840] Cached mail 2.8.1
I, [2026-02-15T14:19:50.414031 #666210]  INFO -- : [543840] #sync_catalog, @sync_count == 1 called on thread 543840
I, [2026-02-15T14:19:50.414048 #666210]  INFO -- : Cataloging /home/fhanson/git3/build
I, [2026-02-15T14:19:50.435622 #666210]  INFO -- : [543840] #sync_catalog Catalog complete (235 files, 26338 pins)
I, [2026-02-15T14:19:50.435695 #666210]  INFO -- : [543840] #sync_catalog 5 uncached YARD gemspecs (["mail", "mini_mime", "net-imap", "date", "net-pop"])
I, [2026-02-15T14:19:50.435712 #666210]  INFO -- : [543840] #sync_catalog 5 uncached RBS collection gemspecs ["mail", "mini_mime", "net-imap", "date", "net-pop"]
I, [2026-02-15T14:19:50.435722 #666210]  INFO -- : [543840] #cache_next_gemspec
I, [2026-02-15T14:19:50.435743 #666210]  INFO -- : [543840] #cache_next_gemspec These 10 cachable specs exist: ["mail", "mini_mime", "net-imap", "date", "net-pop", "mail", "mini_mime", "net-imap", "date", "net-pop"]
I, [2026-02-15T14:19:50.435796 #666210]  INFO -- : [543840] #cache_next_gemspec: Caching mail 2.8.1
I, [2026-02-15T14:19:50.435890 #666210]  INFO -- : [543840] #cache_next_gemspec created new Thread for caching mail (which may or may not have run yet)
I, [2026-02-15T14:19:50.436026 #666210]  INFO -- : [543840] Active threads in this process: 10
I, [2026-02-15T14:19:50.436068 #666210]  INFO -- :      538120 status: sleep, alive?: true
I, [2026-02-15T14:19:50.436102 #666210]  INFO -- :      464800 status: sleep, alive?: true
I, [2026-02-15T14:19:50.436135 #666210]  INFO -- :      2680 status: sleep, alive?: true
I, [2026-02-15T14:19:50.436168 #666210]  INFO -- :      538140 status: sleep, alive?: true
I, [2026-02-15T14:19:50.436201 #666210]  INFO -- :      543780 status: sleep, alive?: true
I, [2026-02-15T14:19:50.436225 #666210]  INFO -- :      543820 status: sleep, alive?: true
I, [2026-02-15T14:19:50.436257 #666210]  INFO -- :      543860 status: sleep, alive?: true
I, [2026-02-15T14:19:50.436288 #666210]  INFO -- :      543840 status: run, alive?: true
I, [2026-02-15T14:19:50.436320 #666210]  INFO -- :      543900 status: sleep, alive?: true
I, [2026-02-15T14:19:50.436360 #666210]  INFO -- :      543880 status: sleep, alive?: true
I, [2026-02-15T14:19:50.436394 #666210]  INFO -- : [543840] #sync_catalog -> method finished
I, [2026-02-15T14:19:50.436595 #666210]  INFO -- :   [543840] #cache_next_gemspec thread finished (caching "mail")
I, [2026-02-15T14:19:50.435965 #666210]  INFO -- :   [543880] #cache_next_gemspec New thread 543880 for caching("mail")
I, [2026-02-15T14:19:50.436671 #666210]  INFO -- : report_cache_progress("mail", 4)
I, [2026-02-15T14:19:50.436711 #666210]  INFO -- : report_cache_progress["mail"] @cache_progress.begin("mail (+4)", 0)
I, [2026-02-15T14:19:50.436749 #666210]  INFO -- : report_cache_progress["mail"] notify_observers(#<Solargraph::LanguageServer::Progress:0x00007f251da502a0 @title="Caching gem", @uuid="98db6738-afad-4753-b112-7526385aa119", @percen>
I, [2026-02-15T14:19:50.436906 #666210]  INFO -- : report_cache_progress["mail"] @cache_progress.report("mail (+4)",  0)
I, [2026-02-15T14:19:50.437062 #666210]  INFO -- : report_cache_progress["mail"] true})
I, [2026-02-15T14:19:50.437143 #666210]  INFO -- : report_cache_progress["mail"] notify_observers

Notice that the thread created in the first block:

I, [2026-02-15T14:19:48.205866 #666210]  INFO -- :   [543840] #cache_next_gemspec New thread 543840 for caching("mail")

.... becomes the parent thread which calls #sync_catalog in the second block...

I, [2026-02-15T14:19:50.414031 #666210]  INFO -- : [543840] #sync_catalog, @sync_count == 1 called on thread 543840

... which then creates a new thread...

I, [2026-02-15T14:19:50.436595 #666210]  INFO -- :   [543840] #cache_next_gemspec thread finished (caching "mail")
I, [2026-02-15T14:19:50.435965 #666210]  INFO -- :   [543880] #cache_next_gemspec New thread 543880 for caching("mail")

... which repeats forever.

These threads seem to believe that they have succeeded in caching, based on this log message:

fhanson@fhanson-dev-2:~/git3/build/build/src (container-build)$ grep 'Cached' /tmp/solargraph.log | head
I, [2026-02-15T13:43:54.049132 #661783]  INFO -- :   [540060] Cached mail 2.8.1
I, [2026-02-15T13:43:56.304329 #661783]  INFO -- :   [548200] Cached mail 2.8.1
I, [2026-02-15T13:43:58.549340 #661783]  INFO -- :   [548240] Cached mail 2.8.1
I, [2026-02-15T13:44:00.812749 #661783]  INFO -- :   [548280] Cached mail 2.8.1
I, [2026-02-15T13:44:03.064978 #661783]  INFO -- :   [548320] Cached mail 2.8.1
I, [2026-02-15T13:44:05.347251 #661783]  INFO -- :   [548360] Cached mail 2.8.1
I, [2026-02-15T13:44:07.632284 #661783]  INFO -- :   [548400] Cached mail 2.8.1
I, [2026-02-15T13:44:09.913369 #661783]  INFO -- :   [548440] Cached mail 2.8.1
I, [2026-02-15T13:44:12.190615 #661783]  INFO -- :   [548480] Cached mail 2.8.1
I, [2026-02-15T13:44:14.515045 #661783]  INFO -- :   [548520] Cached mail 2.8.1

That message comes from the if s.success? case within the caching thread.
So, it seems no termination condition is ever applied.

Full log capture is available here:
https://gist.github.com/gongfarmer/d7247fd0f475adac1f74f4c5e6e1f548

Workaround

In Library#cache_next_gemspec there is a Thread creation block.
I added a .join to the end of the block to make sure it finishes before more threads are created.

This solves the problem for me:

  • logging shows that #sync_catalog is called, runs a single thread, and then stops
  • solargraph is not using 100% CPU or sending constant editor notifications
    I am not recommending this as the correct solution, there may be downsides here that I have not noticed. It's possible that this breaks some other required updating. This is just included as a data point.

The thread handling logic looks like an infinite loop to me, I suspect that the real solution is to refactor this code to eliminate the pattern of "Thread calls #sync_catalog which calls #cache_next_gemspec which creates Thread which calls #sync_catalog... and so on.

It may also be useful to permanently update the Logger formatter to include the Thread.current.object_id in the log messages.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions