LanguageServer(?) runs forever on Revise.jl

[timholy]

We've talked a fair bit about getting Revise to work properly in vscode's terminal, but I've finally noticed that some of my problems with vscode itself may be specific to Revise. All I have to do is dev Revise, navigate to .julia/dev/Revise, and do code . and I get a julia process that seemingly runs forever on my machine at 100% CPU, and all the nice F12 code navigation features of vscode don't work. But vscode is working for the majority of packages I hack on, so it seems something specific to Revise itself.

It should be noted that I start Revise from my startup.jl file. I haven't seriously tested whether that affects anything.

Not sure what info you need.

Revise 2.6.1 Julia 1.4.0

VSCode info: Version: 1.44.1 Commit: a9f8623ec050e5f0b44cc8ce8204a1455884749f Date: 2020-04-13T14:40:29.529Z Electron: 7.1.11 Chrome: 78.0.3904.130 Node.js: 12.8.1 V8: 7.8.279.23-electron.0 OS: Linux x64 4.15.0-1079-oem

[davidanthoff]

That should be fixed on master, it was a generic infinite loop that was not Revise specific :)

[timholy]

How do I check out master? Curiously I don't even have LanguageServer in my .julia/packages directory. This fact gave me some hesitancy in even filing the issue here.

[ZacLN]

The env used by vscode is stored in .vscode/extensions/**julia-vscode**/scripts/languageserver/packages. Pulling master for LanguageServer likely/definitely requires running a master version for StaticLint and probably SymbolServer

[davidanthoff]

Actually, if you want to use pre-release versions I would suggest you just install the Julia Insider extension from the VS Code marketplace. I'm pushing new builds out to there very frequently, so I think there is very, very little delay relative to master typically, and then all the crash reporting etc. is much more useful for us than self-built versions :)

Insider right now for example has the fix alread.

Just make sure you don't install the regular and the insider build at the same time, that will cause trouble.

[timholy]

I'm running Julia Insider but something in vscode starts a Julia process that starts consuming more and more of my RAM; if I don't notice in time and kill it, I routinely have to hard-shutdown my machine by holding the power button.

Doesn't happen with Atom/Juno. Note that in top the process shows as julia rather than code.

It seems to happen most frequently when I edit Revise. It's possible it's related to https://github.com/julia-vscode/CSTParser.jl/issues/180 since that came up in Revise/test/runtests.jl (https://github.com/timholy/Revise.jl/blob/ed7236de87acece0e4f731fae245fa5682c77c9c/test/runtests.jl#L941).

[pfitzseb]

We also have a similar issue with Juno: https://github.com/JunoLab/Juno.jl/issues/524

It's definitely something in CSTParser.jl (or our usage), since it only happens when static analysis is enabled.

[davidanthoff]

Hm, this kind of suggests that we still have an infinite loop somewhere... The best thing would probably be if we could somehow get a reproducable example, because those kinds of bugs won't trigger our crash reporting.

@timholy is there a specific git commit of Revise.jl that would trigger this? Say some version of Revise.jl that we can check out, open it in VS Code and all hell breaks lose?

[davidanthoff]

Also, I'm assigning the Showstopper label, in my mind fixing this is really crucial.

[ZacLN]

I'm going to strip out all the while-loops from CSTParser and StaticLint, that should hopefully catch this

[ZacLN]

@timholy , I assume (hope) this is still halting all functionality?

[timholy]

Agreed it's important, but it is sporadic. It does seem to happen when I use VSCode to hack on Revise, but I haven't quite pinned it down yet. I don't know if it's even related, but even https://github.com/julia-vscode/CSTParser.jl/issues/180 has varied consequences: sometimes all parsing seems to stop beyond that line, other times it peters out more gradually. Here's a screenshot of my current session:

The offending line is near the middle of the window (line 1103). Notice that the yellow underlining of things it doesn't successfully resolve (see the miniature-text panner on the right) continue through the visible region and down as far as line 1337, and then it abruptly stops:

See the dearth of yellow-marked stuff thereafter.

Again, I have no idea if this is even related.

[ZacLN]

Unrelated I think (explanation on that issue).

It's definitely something in CSTParser.jl (or our usage), since it only happens when static analysis is enabled.

@pfitzseb - Juno only loads CSTParser (not StaticLint), right?

[davidanthoff]

We could also add a counter to every while loop, and if it runs more than say 10k times, it throws an error? Or some other large number that makes sense. That would make this show up in crash reporting, which would make it most likely much easier to find the root cause?

[ZacLN]

Thats exactly what I've done (including a 10k limit, weirdly enough)

[aviatesk]

@pfitzseb - Juno only loads CSTParser (not StaticLint), right?

yeah, basically we call CSTParser.parse, and then add bindings by ourselves (mostly equivalent to StaticLint.mark_bindings) and then traverse EXPR, e.g.

[davidanthoff]

Ok, we have a crash report on the insider channel for this, here is the stack trace:

CSTParser.CSTInfiniteLoop:
   at parse_string_or_cmd(::CSTParser.ParseState, ::Bool) (.\julialang.language-julia-insider-0.16.2\scripts\packages\CSTParser\src\components\strings.jl105)
   at parse_string_or_cmd(::CSTParser.ParseState) (.\julialang.language-julia-insider-0.16.2\scripts\packages\CSTParser\src\components\strings.jl25)
   at mLITERAL(::CSTParser.ParseState) (.\julialang.language-julia-insider-0.16.2\scripts\packages\CSTParser\src\spec.jl162)
   at parse_doc(::CSTParser.ParseState) (.\julialang.language-julia-insider-0.16.2\scripts\packages\CSTParser\src\CSTParser.jl182)
   at parse_block(::CSTParser.ParseState, ::Array{CSTParser.EXPR,1}, ::Tuple{Tokenize.Tokens.Kind}, ::Bool) (.\julialang.language-julia-insider-0.16.2\scripts\packages\CSTParser\src\components\internals.jl29)
   at parse_blockexpr(::CSTParser.ParseState, ::CSTParser.Head) (.\julialang.language-julia-insider-0.16.2\scripts\packages\CSTParser\src\components\keywords.jl298)
   at macro expansion (.\julialang.language-julia-insider-0.16.2\scripts\packages\CSTParser\src\utils.jl58)
   at parse_kw(::CSTParser.ParseState) (.\julialang.language-julia-insider-0.16.2\scripts\packages\CSTParser\src\components\keywords.jl45)
   at parse_expression(::CSTParser.ParseState) (.\julialang.language-julia-insider-0.16.2\scripts\packages\CSTParser\src\CSTParser.jl46)
   at parse_doc(::CSTParser.ParseState) (.\julialang.language-julia-insider-0.16.2\scripts\packages\CSTParser\src\CSTParser.jl199)
   at parse(::CSTParser.ParseState, ::Bool) (.\julialang.language-julia-insider-0.16.2\scripts\packages\CSTParser\src\CSTParser.jl225)
   at parse(::String, ::Bool) (.\julialang.language-julia-insider-0.16.2\scripts\packages\CSTParser\src\CSTParser.jl171)
   at LanguageServer.Document(::String, ::String, ::Bool, ::LanguageServerInstance) (.\julialang.language-julia-insider-0.16.2\scripts\packages\LanguageServer\src\document.jl16)
   at load_folder(::String, ::LanguageServerInstance) (.\julialang.language-julia-insider-0.16.2\scripts\packages\LanguageServer\src\requests\init.jl109)
   at initialized_notification(::LanguageServer.InitializedParams, ::LanguageServerInstance, ::JSONRPC.JSONRPCEndpoint) (.\julialang.language-julia-insider-0.16.2\scripts\packages\LanguageServer\src\requests\init.jl170)
   at (::LanguageServer.var"#19#50"{LanguageServerInstance})(::JSONRPC.JSONRPCEndpoint, ::LanguageServer.InitializedParams) (.\julialang.language-julia-insider-0.16.2\scripts\packages\LanguageServer\src\languageserverinstance.jl281)
   at dispatch_msg(::JSONRPC.JSONRPCEndpoint, ::JSONRPC.MsgDispatcher, ::Dict{String,Any}) (.\julialang.language-julia-insider-0.16.2\scripts\packages\JSONRPC\src\typed.jl63)
   at run(::LanguageServerInstance) (.\julialang.language-julia-insider-0.16.2\scripts\packages\LanguageServer\src\languageserverinstance.jl305)
   at top-level scope (.\julialang.language-julia-insider-0.16.2\scripts\languageserver\main.jl59)
   at include(::Module, ::String) (Base.jl377)
   at exec_options(::Base.JLOptions) (client.jl288)
   at _start() (client.jl484)

[timholy]

Yesterday I had it jump into 100% CPU time twice but still wasn't able to detect any kind of pattern. A difference, though, is that memory usage stayed constant, and in neither case was LanguageServer indexing (if the lack of an "indexing..." indicator at the bottom of a window is an indication). I left the process running for almost 3 hours once.

In both cases I killed the process. Does that generate a crash report? Is there something better I can do?

[ZacLN]

Woop! I had a suspicion it was in that area as there's a call to seek in the mix. It may take me a short while to work out what the issue is as I don't think I wrote this code

[davidanthoff]

@timholy are you on the insider channel for the extension? I pushed an update that now crashes the LS process if it ends up in an infinite loop. In theory it should be enough that you run that version, and then it should not stay at 100% for long, but instead it should crash and then send a crash report.

If that is not happening, but you're still running at a 100% for long, then that might indicate another problem... Killing the process won't send a crash report.

In general there are two Julia processes involved here: the language server (LS) process and the symbol server process. The status bar with the "indexing" tests corresponds to the symbol server process. Right now we think the problem is in the LS process, though (where the CSTParsing happens). Is there a way that you can see what the command line args were for the process that is at 100%? That should tell us exactly whether it is the LS or the symserv process.

[timholy]

@timholy are you on the insider channel for the extension?

I am indeed. Thanks for the debug commit!

Is there a way that you can see what the command line args were for the process that is at 100%?

top just says code.

[davidanthoff]

@ZacLN do we know who wrote the code originally? Should we ping that person to try to help out? This is one of two showstoppers we have right now.

[non-Jedi]

Git blame says that section of code was largely written/rewritten in https://github.com/julia-vscode/CSTParser.jl/pull/24

[davidanthoff]

@timholy we published v0.16.5 to the insider channel yesterday. It has more diagnostic code to figure out what is going on here. Could you try to open the offending project again? And ideally, hopefully, it will crash and send us a crash report with more information than we had before that will allow us to fix this.

[kdheepak]

@timholy you probably already know this, but you can run the following to find the exact command that vscode spun up as a child process.

$ ps -ex | grep julia
63591 ttys000  101:49.94 julia --project=/Users/USER/.cache/nvim/nvim_lsp/julials --startup-file=no --history-file=no -e         using Pkg;\012        Pkg.instantiate()\012        using LanguageServer; using SymbolServer;\012        depot_path = get(ENV, "JULIA_DEPOT_PATH", "")\012        project_path = dirname(something(Base.current_project(pwd()), Base.load_path_expand(LOAD_PATH[2])))\012        # Make sure that we only load packages from this environment specifically.\012        empty!(LOAD_PATH)\012        push!(LOAD_PATH, "@")\012        @info "Running language server" env=Base.load_path()[1] pwd() project_path depot_path\012        server = LanguageServer.LanguageServerInstance(stdin, stdout, project_path, depot_path);\012        server.runlinter = true;\012        run(server);\012
66420 ttys000    0:00.00 grep julia

I learnt this on #vim and it was useful in debugging what was going on.

[davidanthoff]

We've got a new crash report here. It has the new diagnostics filled in.

[ZacLN]

I messed up the loop checks (fix here).

[timholy]

I've got all the new versions running, so we'll see if it catches anything. Thanks folks!

[aminya]

Not sure if related to this but I get these warnings until I stop julia.

using LanguageServer

Status `C:\Users\yahyaaba\Documents\GitHub\Julia\Project.toml`   
  [00ebfdb7] CSTParser v2.3.1
  [ffa9a821] DocumentFormat v2.2.0
  [2b0e0bc5] LanguageServer v3.0.0
  [b3cc710f] StaticLint v4.3.0
  [cf896787] SymbolServer v4.4.0
 Activating environment at `C:\Users\yahyaaba\Documents\GitHub\Julia\Project.toml`
   Updating registry at `C:\Users\yahyaaba\.julia\registries\General`
   Updating git-repo `https://github.com/JuliaRegistries/General.git`
   Updating `C:\Users\yahyaaba\Documents\GitHub\Julia\Project.toml`
  [2b0e0bc5] + LanguageServer v3.0.0
   Updating `C:\Users\yahyaaba\Documents\GitHub\Julia\Manifest.toml`
  [00ebfdb7] + CSTParser v2.3.1
  [ffa9a821] + DocumentFormat v2.2.0
  [48062228] + FilePathsBase v0.9.3
  [682c06a0] + JSON v0.21.0
  [2b0e0bc5] + LanguageServer v3.0.0
  [69de0a69] + Parsers v1.0.5
  [b3cc710f] + StaticLint v4.3.0
  [cf896787] + SymbolServer v4.4.0
  [0796e94c] + Tokenize v0.5.8
  [30578b45] + URIParser v0.4.1
  [2a0f44e3] + Base64 
  [ade2ca70] + Dates 
  [8ba89e20] + Distributed 
  [b77e0a4c] + InteractiveUtils 
  [76f85450] + LibGit2 
  [8f399da3] + Libdl 
  [56ddb016] + Logging 
  [d6f4376e] + Markdown 
  [a63ad114] + Mmap 
  [44cfe95a] + Pkg 
  [de0858da] + Printf 
  [3fa0cd96] + REPL 
  [9a3f8284] + Random 
  [ea8e919c] + SHA 
  [9e88b42a] + Serialization 
  [6462fe0b] + Sockets 
  [8dfed614] + Test 
  [cf7118a7] + UUIDs 
  [4ec0a83e] + Unicode 

[ Info: Precompiling LanguageServer [2b0e0bc5-e4fd-59b4-8912-456d1b03d8d7]
WARNING: Threads.Mutex is deprecated, use ReentrantLock instead.
  likely near C:\Users\yahyaaba\.julia\packages\SymbolServer\vTGsB\src\SymbolServer.jl:201
WARNING: Threads.RecursiveSpinLock is deprecated, use ReentrantLock instead.    
  likely near C:\Users\yahyaaba\.julia\packages\SymbolServer\vTGsB\src\SymbolServer.jl:201
WARNING: Threads.Mutex is deprecated, use ReentrantLock instead.
  likely near C:\Users\yahyaaba\.julia\packages\SymbolServer\vTGsB\src\SymbolServer.jl:201
WARNING: Threads.RecursiveSpinLock is deprecated, use ReentrantLock instead.    
  likely near C:\Users\yahyaaba\.julia\packages\SymbolServer\vTGsB\src\SymbolServer.jl:201

[aminya]

I checked the #master, and this does not happen. So I guess I should ask for registration of a new version instead :smile:

[davidanthoff]

@ZacLN so that means we might not have any crash report for this yet, right? Because the previous one was probably spurious?

[ZacLN]

No crash reports we've had so far represent the real bug

[davidanthoff]

I'm removing the showstopper label because it seems we can't really manage to get a crash report for this easily, and so I think this shouldn't block our next release. It also isn't a regression in any case.

I'd say we leave all the diagnostic code we added in there and hope that it gets triggered once we ship the next version to everyone, not just the insider channel.

[timholy]

I've not seen this in some time, but this evening I triggered it again.

tim@diva:~/.julia/dev/Colors$ ps ax | grep julia
 3787 ?        Sl     0:39 /home/tim/src/julia-1/usr/bin/julia --startup-file=no --history-file=no --depwarn=no --project=/home/tim/.vscode/extensions/julialang.language-julia-insider-0.16.5/scripts/environments/languageserver main.jl /home/tim/.julia/dev/Revise --debug=no /tmp/vsc-jl-cr-3707  /home/tim/.config/Code/User/globalStorage/julialang.language-julia-insider
12261 ?        Sl     0:40 /home/tim/src/julia-1/usr/bin/julia --startup-file=no --history-file=no --depwarn=no --project=/home/tim/.vscode/extensions/julialang.language-julia-insider-0.16.6/scripts/environments/languageserver main.jl /home/tim/.julia/dev/SnoopCompile --debug=no /tmp/vsc-jl-cr-12186  /home/tim/.config/Code/User/globalStorage/julialang.language-julia-insider
13178 ?        Sl     0:43 /home/tim/src/julia-1/usr/bin/julia --startup-file=no --history-file=no --depwarn=no --project=/home/tim/.vscode/extensions/julialang.language-julia-insider-0.16.6/scripts/environments/languageserver main.jl /home/tim/.julia/environments/v1.4 --debug=no /tmp/vsc-jl-cr-13064  /home/tim/.config/Code/User/globalStorage/julialang.language-julia-insider
17460 ?        Sl     1:30 /home/tim/src/julia-1/usr/bin/julia --startup-file=no --history-file=no --depwarn=no --project=/home/tim/.vscode/extensions/julialang.language-julia-insider-0.16.6/scripts/environments/languageserver main.jl /home/tim/.julia/environments/v1.6 --debug=no /tmp/vsc-jl-cr-17382  /home/tim/.config/Code/User/globalStorage/julialang.language-julia-insider
24032 ?        Sl     0:41 /home/tim/src/julia-1/usr/bin/julia --startup-file=no --history-file=no --depwarn=no --project=/home/tim/.vscode/extensions/julialang.language-julia-insider-0.16.6/scripts/environments/languageserver main.jl /home/tim/.julia/environments/v1.4 --debug=no /tmp/vsc-jl-cr-23909  /home/tim/.config/Code/User/globalStorage/julialang.language-julia-insider
27511 pts/12   S+     0:00 grep --color=auto julia

I have 5 separate code windows open, to Revise, FixedPointNumbers, ColorTypes, ColorVectorSpace, and SnoopCompile. Interestingly, I noticed the CPU load when editing ColorVectorSpace's README (!). Also perhaps not coincidentally, spell-checking has never worked for me.

I am heading to bed but if there are diagnostics I can run, I will leave all my windows open through the morning.

[davidanthoff]

This is definitely in the LS... I take it that it didn't crash, though, right?

@ZacLN we didn't add these loop traps to LanguageServer.jl and StaticLint.jl, or did we? Maybe we need to have them everywhere to get to the bottom of this?

@timholy I don't know what we could do further with this particular run... The most likely explanation is that Julia is stuck in some endless while loop in the LS, but I don't know how we might be able to figure out which one without adding additional debug code... But you might have an idea :)

[timholy]

Yes, this time (and for the last several times) it's not growing in its memory consumption. Also, closing the code window terminates the CPU-intensive process (something that hasn't always happened in the past).

[ZacLN]

@davidanthoff, no we left it at CSTParser and StaticLint. I'll widen our net

[timholy]

Happened again today (the growing-memory variant). Got this from ps ax | grep code:

15673 ?        Rl     3:56 /home/tim/src/julia-1/usr/bin/julia --startup-file=no --history-file=no --depwarn=no --project=/home/tim/.vscode/extensions/julialang.language-julia-insider-0.16.8/scripts/environments/languageserver main.jl /home/tim/.julia/dev/Revise --debug=no /tmp/vsc-jl-cr-15590  /home/tim/.config/Code/User/globalStorage/julialang.language-julia-insider

I was editing test/runtests.jl and test/common.jl, though I had the whole package open.

The pattern seems to be: if it's the growing-memory version, I have to kill the process manually (just shutting down vscode doesn't stop it). If it's not growing in memory consumption, then quitting vscode terminates the job.

[davidanthoff]

I always thought VS Code was actually killing the LS process when you shut it down, but this suggests it is not, and instead is relying on the LS shutting down in response to a shutdown request. Which of course won't be processed anymore once we are in that infinite loop... I think the only hope we have here is to add more of these while loop checks that @ZacLN started.

[ZacLN]

Coincidentally, we've had a few hits on Azure for the existing loop checks in CSTParser

[timholy]

I'm getting slightly more convinced that the offending file might be Revise/test/common.jl. Is there something I can do to test this theory?

In case it helps, got this today:

 4654 ?        Rl    16:59 /home/tim/src/julia-1/usr/bin/julia --startup-file=no --history-file=no --depwarn=no --project=/home/tim/.vscode/extensions/julialang.language-julia-insider-0.16.8/scripts/environments/languageserver main.jl /home/tim/.julia/dev/Revise --debug=no /tmp/vsc-jl-cr-4560  /home/tim/.config/Code/User/globalStorage/julialang.language-julia-insider

and it was not of the memory-growing variety, but it didn't quit when I closed vscode. So much for the patterns I thought I'd observed above :shrug:.

[davidanthoff]

@ZacLN we're getting a number of hits in crash reporting on the latest version, e.g. here. Does that help?

[timholy]

I can't access those reports but one caution: I noticed a number of crashes occurring while I was in the middle of a make clean && make on master while also running vscode. If those happen to be me (I have enabled telemetry), probably worth ignoring.

[davidanthoff]

I think we should never crash, regardless of what you are doing :) I think the reports came from someone else, though.