https://toitlang.org/ logo
Join Discord
Powered by
Toit VS Code extension high CPU usage (MacOS)
# help
b
I'm not really able to use the VS Code extension on my MacOS machine as it causes huge CPU spikes and makes VS Code pretty much unusable. It works fine on my linux machine. Here's what I see in the output panel in VS Code
Copy code
sh
2023-03-19T14:50:17.591-0500    ERROR    Compiler.compiler_protocol    compiler/compiler_fs_protocol.go:135    read failed    {"error": "io: read/write on closed pipe"}
github.com/toitware/toit.git/toitlsp/lsp/compiler.(*CompilerFSProtocol).HandleConn
    /Users/runner/work/toit/toit/tools/toitlsp/lsp/compiler/compiler_fs_protocol.go:135
github.com/toitware/toit.git/toitlsp/lsp/compiler.(*PipeFileServer).handleConn
    /Users/runner/work/toit/toit/tools/toitlsp/lsp/compiler/file_server_pipe.go:52
Also created an issue: https://github.com/toitware/ide-tools/issues/212
f
😦
Do you know if the error message is related?
Is the CPU spiking after such a message?
Is the error message showing up continuously?
b
Yeah the error is showing up continuously
CPU spikes almost immediately after I open a toit file and the error appears
Ah there is a bit more at the top! Sorry
f
I will have a look at the code, but without a reproduction it's going to be a long shot. (Especially since I'm on Linux).
b
Hmm... This time, the errors appeared and CPU usage was quite low and after 3 minutes or so (and connecting my device, running 
jag monitor / jag watch
) it got slow
No worries. I have a Linux machine so I'm happy to use that
f
Fyi: a short description of the architecture: the client (vscode) communicates with a Go program (toit.go) which then launches the compiler in a special mode for every request. Normally, you should see the compiler see up in 'top', as this is the process that does the most work. However, it's also short-lived. If the Go program is spiking in CPU, it means that we are doing something wrong. Potentially continuously trying to read from a dead sub process, wasting all CPU. We already had such an issue... (A missed 
if error != null
).
Do you, by chance, have 
delve
installed (Go's debugger).
b
No, but I'l happy to install it.\
f
If you attach to it 
dlv attach pid
you might be able to see which function it is continuously calling, and why it doesn't stop.
I'm not sure if it works without the sources, but this is how we found the issue last time.
b
To the pid for 
toit.lsp
?
f
yes.
b
Sure. Giving this a shot now
I'm afraid I don't know where to go from here:
Copy code
sh
➜  bin dlv attach 61015
Type 'help' for list of commands.
(dlv)
f
not too familiar with Golang/delve either, but let me look it up.
can you start by 
threads
?
b
Copy code
Thread 3792956 at :0
  Thread 3792960 at :0
* Thread 3792961 at 0x108d200 /Users/runner/hostedtoolcache/go/1.17.13/x64/src/sort/search.go:83 sort.SearchInts
  Thread 3792962 at :0
  Thread 3792963 at :0
  Thread 3792994 at 0x1014830 /Users/runner/hostedtoolcache/go/1.17.13/x64/src/runtime/mbitmap.go:947 runtime.heapBitsSetType
  Thread 3793039 at 0x1093ed1 /Users/runner/hostedtoolcache/go/1.17.13/x64/src/internal/poll/fd_mutex.go:186 internal/poll.(*fdMutex).rwunlock
  Thread 3793044 at :0
  Thread 3793045 at :0
  Thread 3793046 at :0
  Thread 3793047 at :0
  Thread 3793048 at 0x105f0e8 /Users/runner/hostedtoolcache/go/1.17.13/x64/src/runtime/netpoll.go:284 internal/poll.runtime_pollReset
  Thread 3793087 at :0
  Thread 3793088 at 0x1109fed /Users/runner/hostedtoolcache/go/1.17.13/x64/src/bufio/bufio.go:105 bufio.(*Reader).fill
  Thread 3793118 at :0
  Thread 3793645 at :0
  Thread 3793646 at 0x100c86b /Users/runner/hostedtoolcache/go/1.17.13/x64/src/runtime/malloc.go:858 runtime.mallocgc
  Thread 3793647 at :0
  Thread 3793648 at 0x10644be /Users/runner/hostedtoolcache/go/1.17.13/x64/src/runtime/asm_amd64.s:772 runtime.asmcgocall
  Thread 3793649 at :0
  Thread 3793651 at :0
  Thread 3793652 at :0
  Thread 3796699 at :0
  Thread 3797876 at 0x1045f2e /Users/runner/hostedtoolcache/go/1.17.13/x64/src/runtime/select.go:310 runtime.selectgo
  Thread 3798078 at :0
  Thread 3798079 at 0x10368df /Users/runner/hostedtoolcache/go/1.17.13/x64/src/runtime/proc.go:410 runtime.acquireSudog
  Thread 3798080 at :0
  Thread 3798081 at :0
f
trying to find the right commands.
Not sure this is what needs to be done, but: 
goroutines
list all goroutines.
goroutine X
allows to switch to a goroutine.
list
shows the source it's currently executing.
bt
prints a backtrace of the current goroutine.
b
Ah nice, it seems like we're getting somewhere
Copy code
sh
(dlv) list
> sort.SearchInts() /Users/runner/hostedtoolcache/go/1.17.13/x64/src/sort/search.go:83 (PC: 0x108d200)
Warning: debugging optimized function
Command failed: open /Users/runner/hostedtoolcache/go/1.17.13/x64/src/sort/search.go: no such file or directory
f
that's probably ok.
if you go 
up
you might get the sources.
But just having the 
bt
backtrace could already help.
b
Copy code
sh
(dlv) goroutine 2636
Switched from 2636 to 2636 (thread 3792961)
(dlv) bt
 0  0x000000000108d200 in sort.SearchInts
    at /Users/runner/hostedtoolcache/go/1.17.13/x64/src/sort/search.go:83
 1  0x00000000012a6119 in github.com/toitware/toit.git/toitlsp/lsp/toit.FindLastGreaterThanIdx
    at /Users/runner/work/toit/toit/tools/toitlsp/lsp/toit/summary.go:544
 2  0x00000000012aaa0d in github.com/toitware/toit.git/toitlsp/lsp/toit/text.(*summaryReader).topLevelReferenceFromGlobalID
    at /Users/runner/work/toit/toit/tools/toitlsp/lsp/toit/text/parser.go:776
 3  0x00000000012a91b3 in github.com/toitware/toit.git/toitlsp/lsp/toit/text.(*summaryReader).readType
    at /Users/runner/work/toit/toit/tools/toitlsp/lsp/toit/text/parser.go:430
 4  0x00000000012a8b6a in github.com/toitware/toit.git/toitlsp/lsp/toit/text.(*summaryReader).readMethod
    at /Users/runner/work/toit/toit/tools/toitlsp/lsp/toit/text/parser.go:359
 5  0x00000000012a8325 in github.com/toitware/toit.git/toitlsp/lsp/toit/text.(*summaryReader).readFunctions
    at /Users/runner/work/toit/toit/tools/toitlsp/lsp/toit/text/parser.go:257
 6  0x00000000012a785b in github.com/toitware/toit.git/toitlsp/lsp/toit/text.(*summaryReader).readModule
    at /Users/runner/work/toit/toit/tools/toitlsp/lsp/toit/text/parser.go:121
 7  0x00000000012a7545 in github.com/toitware/toit.git/toitlsp/lsp/toit/text.(*summaryReader).Read
    at /Users/runner/work/toit/toit/tools/toitlsp/lsp/toit/text/parser.go:82
 8  0x00000000012a728c in github.com/toitware/toit.git/toitlsp/lsp/toit/text.ParseSummary
    at /Users/runner/work/toit/toit/tools/toitlsp/lsp/toit/text/parser.go:49
 9  0x00000000012b3ca7 in github.com/toitware/toit.git/toitlsp/lsp/compiler.(*parser).AnalyzeOutput
    at /Users/runner/work/toit/toit/tools/toitlsp/lsp/compiler/parser.go:69
10  0x00000000012ac1da in github.com/toitware/toit.git/toitlsp/lsp/compiler.(*Compiler).Analyze.func1
    at /Users/runner/work/toit/toit/tools/toitlsp/lsp/compiler/compiler.go:136
11  0x00000000012ae903 in github.com/toitware/toit.git/toitlsp/lsp/compiler.(*Compiler).run.func1
    at /Users/runner/work/toit/toit/tools/toitlsp/lsp/compiler/compiler.go:336
12  0x0000000001064661 in runtime.goexit
    at /Users/runner/hostedtoolcache/go/1.17.13/x64/src/runtime/asm_amd64.s:1581
Copy code
> sort.SearchInts() /Users/runner/hostedtoolcache/go/1.17.13/x64/src/sort/search.go:83 (PC: 0x108d200)
Warning: debugging optimized function
Frame 1: /Users/runner/work/toit/toit/tools/toitlsp/lsp/toit/summary.go:544 (PC: 12a6119)
(dlv) up
> sort.SearchInts() /Users/runner/hostedtoolcache/go/1.17.13/x64/src/sort/search.go:83 (PC: 0x108d200)
Warning: debugging optimized function
Frame 2: /Users/runner/work/toit/toit/tools/toitlsp/lsp/toit/text/parser.go:776 (PC: 12aaa0d)
(dlv) up
> sort.SearchInts() /Users/runner/hostedtoolcache/go/1.17.13/x64/src/sort/search.go:83 (PC: 0x108d200)
Warning: debugging optimized function
Frame 3: /Users/runner/work/toit/toit/tools/toitlsp/lsp/toit/text/parser.go:430 (PC: 12a91b3)
(dlv) up
> sort.SearchInts() /Users/runner/hostedtoolcache/go/1.17.13/x64/src/sort/search.go:83 (PC: 0x108d200)
Warning: debugging optimized function
Frame 4: /Users/runner/work/toit/toit/tools/toitlsp/lsp/toit/text/parser.go:359 (PC: 12a8b6a)
(dlv) up
> sort.SearchInts() /Users/runner/hostedtoolcache/go/1.17.13/x64/src/sort/search.go:83 (PC: 0x108d200)
Warning: debugging optimized function
Frame 5: /Users/runner/work/toit/toit/tools/toitlsp/lsp/toit/text/parser.go:257 (PC: 12a8325)
(dlv) up
> sort.SearchInts() /Users/runner/hostedtoolcache/go/1.17.13/x64/src/sort/search.go:83 (PC: 0x108d200)
Warning: debugging optimized function
Frame 6: /Users/runner/work/toit/toit/tools/toitlsp/lsp/toit/text/parser.go:121 (PC: 12a785b)
f
Thanks.
Now let's continue the program (
continue
) and wait a bit.
Then 
ctrl-c
to go back into delve and see if the backtrace changed.
b
Copy code
sh
received SIGINT, stopping process (will not forward signal)
Stopped at: 0x7ff80872911a
=>   1:    no source available
(dlv) bt
 0  0x00007ff80872911a in ???
    at ?:-1
 1  0x0000000001066490 in runtime.pthread_cond_wait_trampoline
    at /Users/runner/hostedtoolcache/go/1.17.13/x64/src/runtime/sys_darwin_amd64.s:535
 2  0x00000000010644ed in runtime.asmcgocall
    at /Users/runner/hostedtoolcache/go/1.17.13/x64/src/runtime/asm_amd64.s:795
 3  0x0000000000000000 in ???
    at ?:-1
 4  0x0000000001052c34 in runtime.pthread_cond_wait
    at /Users/runner/hostedtoolcache/go/1.17.13/x64/src/runtime/sys_darwin.go:444
 5  0x000000000102fdad in runtime.semasleep
    at /Users/runner/hostedtoolcache/go/1.17.13/x64/src/runtime/os_darwin.go:66
 6  0x000000000100b2e5 in runtime.notesleep
    at /Users/runner/hostedtoolcache/go/1.17.13/x64/src/runtime/lock_sema.go:182
 7  0x000000000103904a in runtime.mPark
    at /Users/runner/hostedtoolcache/go/1.17.13/x64/src/runtime/proc.go:1441
 8  0x000000000103a558 in runtime.stopm
    at /Users/runner/hostedtoolcache/go/1.17.13/x64/src/runtime/proc.go:2408
 9  0x000000000103e6d6 in runtime.exitsyscall0
    at /Users/runner/hostedtoolcache/go/1.17.13/x64/src/runtime/proc.go:4115
10  0x0000000001062543 in runtime.mcall
    at /Users/runner/hostedtoolcache/go/1.17.13/x64/src/runtime/asm_amd64.s:307
f
Looks completely different. Maybe a different goroutine?
b
It doesn't seem to have a goroutine "selected"
Copy code
sh
Sending output to pager...
(dlv) list
Stopped at: 0x7ff80872911a
=>   1:    no source available
should i completely quit out of delve and then attach again?
f
Just noticed: "goroutine 2636". That's a lot of goroutines. My biggest is "66"...
If you 
goroutines
you should see a list of all goroutines.
Maybe one jumps out as Toit related.
k
(FWIW, I think I see this too on my Mac)
f
great(?) news. At least we should be able to debug this tomorrow, if we don't see anything fishy today.
k
Yup!
b
I'm having trouble copying the whole list, but here's my full history: https://gist.github.com/bpmct/10a64bcc2df8363fa988fa85cf26f702
Ah, great! I'm also happy to give one of y'all 
tmate
/ssh access to my machine tomorrow if you need to debug further
f
If we can reproduce we should manage. But thanks.
Not making huge progress yet, but the server just seems to plow through goroutines...
I don't see anything obvious yet, so I think @kasperl and I will debug this tomorrow.
b
Sounds great. Thanks for the quick response, as always
f
And thanks for reporting and giving delve a try.
k
Maybe give Jaguar v1.9.13 a spin and see if the updated Go compiler and support packages help toit.lsp?
b
Hey - still noticing high CPU usage with 
toit.lsp
after upgrading to Jaguar v1.19.14
f
Ok. Could you enable profiling?
For that you need to change the vscode settings to start the LSP server with special instructions.
Let me find them.
If you search for the settings id 
toitLanguageServer.command
you should have an 'edit in settings.json'.
If you click on that you will be dropped into settings.json
There you have to call 
toit.lsp
with two different flags (each with a value): - 
--toitc
pointing to the toit compiler. - 
--cpuprofile
with a directory where the profiles can be stored. That directory must exist. For example, for me the following would work:
Copy code
[
      "/home/flo/.cache/jaguar/sdk/bin/toit.lsp",
      "--toitc", "/home/flo/.cache/jaguar/sdk/bin/toit.compile",
      "--cpuprofile", "/home/flo/tmp/lsp-profile"
      ]
Use 
ctrl-shift-p
followed by 
Developer: Reload Window
to apply the changes and restart the server.
Now Go is a bit annoying here, in that the profile is not regularly written. The 
.prof
file stays empty until the LSP server is shut down.
The best way to achieve this is by closing all (Toit) buffers.
(I think closing the editor doesn't work).
Once the CPU spikes again, let it maybe run a bit (to get the offending functions to the top). Then close all buffers. That should leave you with a profile file that might help us figure out what's going on. If you want you can also have a look at the profile file yourself: 
go tool pprof PATH_TO_TOIT_LSP PATH_TO_PROFILE_FILE
. (see https://go.dev/blog/pprof), but I hope that we can do that on our machines as well.
b
f
Let's see if I can get the data, or if we need a mac for that.
b
Quite a lot of files, actually. One is 35kb, then a few between 16-24kb, then many 2-3kb
f
Can you confirm that you are running v2.0.0-alpha.71?
b
Copy code
sh
➜ jag version
Version:         v1.9.14
SDK version:     v2.0.0-alpha.71
Build date:      2023-03-25T18:51:50Z
➜  toit
f
Weird... One editor should only have one toit.lsp running.
b
Ah there are quite a lot in my activity monitor
f
While I'm looking at the zip, could you have a look at the LSP output?
b
Sure thing
f
open view -> Output
In the drop-down "Toit lsp server" (or something similar).
b
f
thanks!
Ok. That's similar to what we already knew. Not clear why you would have so many lsp servers.
One other thing that could maybe help: 
toitLanguageServer.trace.server
In the settings: could you set that to 'verbose' ?
b
f
Thanks. From what I can see, this trace doesn't contain any repeated errors yet. So I assume that it wasn't yet consuming 100% CPU. Also, I think I was wrong when I said that an editor should only have one LSP. If I remember correctly, we spawn a new LSP server for each project. That is, for each file that isn't in a subdirectory of an LSP server. (I think we walk up the directory chain to find the 'package.lock' files.)
I will now go back to the traces and see if I can see something that sticks out.
b
Here's a significantly longer trace, my system has extremely high CPU load whenever the extension is installed
trace
f
you mean as soon as the extension calls 'initialize' the CPU goes up?
b
Umm, basically as soon as I open a 
.toit
file
f
ok. good to know. thanks.
b
Not necessarily at install time, I mispoke
f
If you open a fresh vscode, and open a simple 'hello.toit' does that also trigger the CPU?
b
Let's try.
Interesting!
An extremely simple toit program doesn't seem to have the same problem
f
interesting.
b
Here's the code I am running which causes high CPU. Still quite simple at this point
Copy code
toit
// Save as hello.toit

import uart
import gpio
import reader show BufferedReader
import writer show Writer
import net
import mqtt
import net.x509
import certificate_roots
import encoding.json
import gpio

import gpio
import gpio.adc show Adc


// Include a random number, as we are sharing test.mosquitto.org with other users.
CLIENT_ID ::= "tio-$(random)"
HOST      ::= "broker.mqttdashboard.com"
PORT      ::= 8000
TOPIC     ::= "tio"

main:
    print "Hello totto!"

    port := uart.Port
      --rx=gpio.Pin 1 //blue
      --tx=gpio.Pin 0 //purple 
      --baud_rate=9600

    writer := Writer port
    writer.write "Hello\n\n\n\n"

    network := net.open
    transport := mqtt.TcpTransport network --host=HOST
    client := mqtt.Client --transport=transport
    client.start --client_id=CLIENT_ID

    client.subscribe TOPIC:: | topic/string payload/ByteArray |
      writer.write payload
      writer.write "\n\n\n"

    print "Hello world?"
    button1 := gpio.Pin 4 --input 
    button1Pressed := false

// butotn1: 2
// light1: 3

// button2: 4
// light2: 5ss

    output_pin := gpio.Pin 5
     --output


    
    output_pin.set 1
    print "light 1"

    while true:
      button1.wait_for 1
      print "clicked"
      sleep --ms=100
      // writer.write "ooo button pushed\v n\n\n\n"  

      // print button1.get
      // // sleep --ms 100
      // sleep --ms=100
      // if button1.get == 1 and not button1Pressed:
      //   print "passed"
      //   button1Pressed = true
      //   // writer.write "button1 pushed\v n\n\n\n"
      //   // client.publish TOPIC:: "button1 pushed\v n\n\n\n"
f
probably one of the imports...
b
I see. Sorry for not sending all of the info from the start, I hadn't considered it was due to one of the packages
f
No worries. I'm just happy for the help 🙂
b
It seems to work just fine on my Linux machine, which perplexes me
f
Could you maybe comment them (one by one, or binary search), to see if one specifically is causing this?
b
Sure
It will be quite a slow process though since I think I need to uninstall/reinstall the extension between each check
f
I would probably reload the window after every change. (just in case the LSP server doesn't recover).
b
Yeah
f
why?
b
I haven't tried reloading the window so perhaps that would do the trick. Navigating to the simple file or closing it doesn't recover the LSP server
f
you might also be able to just 
killall toit.lsp
b
Reloading the window does the trick. Will start looking now
Ok I had to comment them all out then uncomment one-by-one but seems like uncommenting the 
mqtt
package import leads to the spikes. Seeing if any others do.
f
strange.
but interesting.
b
The others would spawn temporary 
toit.lsp
processes and then they'd disappear. When I uncommented the mqtt import, 9 long-running 
toit.lsp
processes started all with high CPU usage
Doing more digging though
f
I think there shouldn't be any temporary 
toit.lsp
processes, but maybe that's just the threading showing up.
Could ctrl-click on the mqtt import and see where it goes?
It should go into a directory inside some 
.packages
.
b
f
Exactly. So it's in the 
.packages
of your project.
Could you rename that 
.packages
(so we can investigate if it turns out to be the problem) and rerun 
jag pkg install
(so it downloads all packages again)?
b
Here is what i meant about the "temporary" processes.
screen-recording-2023-03-25-at-2-58-53-pm
f
It's unlikely, but maybe the download of the packages left the package download in a bad state. (Not sure why that would lead to 100% CPU though)
question is whether it's a temporary process, or the same one that just starts using CPU (while handling the diagnostic).
b
> It's unlikely, but maybe the download of the packages left the package download in a bad state. (Not sure why that would lead to 100% CPU though) No luck
f
Still good to know.
b
Would it be more helpful if I used 
ps
or something?
f
Since you have a very nice setup now. Could you remove all old profiles, and do another one with the mqtt?
b
I have been considering factory resetting my machine. It's possible something on my environment is just wonky
Sure
f
Also checking whether there are some messages in the output.
b
Sure thing
What I did: - Opened IDE - Uncommented line 8 (
import mqtt
) - CPU spiked (exactly like video I sent) - Waited 30 seconds or so - Uninstalled VS Code extension
f
Still trying to make sense of this. There are a lot of 
initialize
calls.
I'm guessing the LSP output window stays busy when the CPU is high? (but is otherwise only active when changes happen).
b
Yep.
f
I'm a bit confused by all the 'initialize' calls. I'm trying to create a vscode extension that adds a bit of logging.
Needed to page in a lot of old IDE stuff, so took a bit of time. So far I have only added one debugging line, but let's see if it makes a difference: https://drive.google.com/file/d/1cs4ZB_WVl-kbYAMS_hPT0hCL-ms5QzYT/view?usp=sharing
At that location is a toit-1.6.6.vsix. That should be exactly the same extension as the one that is published through the store, except for one 'print'.
It can be installed with 
code --install-extension toit-1.6.6.vsix
In the Output window of the Toit lsp server there is now one line above every 
initialize
call. For example: 
Starting Toit LSP server: workingDir=/home/flo/work/pkg-tar
. Will be interesting to see which working-directories your IDE starts the LSP for.
Will be taking a break now, but will have a look later and see if there is something interesting. It's getting late here, and I will be busy tomorrow, so maybe I will not be able to follow up before Monday, though.
b
No worries! Again this isn't blocking me at all, and I can even try resetting my machine if this isn't something y'all can reproduce
Here are the output logs
message
seems to loop with the following libraries
Copy code
sh
jaguar/sdk/lib/crypto
jaguar/sdk/lib/system/base
jaguar/sdk/lib/system
jaguar/sdk/lib/encoding
jaguar/sdk/lib/tls
message
f
Yeah. something is weird there. As long as you don't have these files open, it shouldn't open a new server.
(If I remember correctly).
Let me add a bit more debugging info.
I think we are on the right track.
From the logs it looks like every time we publish a diagnostic, the editor sends a 'textDocument/didOpen' request.
It doesn't do that in my editor.
Either the code on macos is behaving differently than the one on Linux, or you have an extension that opens files if there is a diagnostic for them.
My guess is that the mqtt package opens a library that has a cyclic import, which then leads to infinite toit lsp servers.
b
> or you have an extension that opens files if there is a diagnostic for them Wow. It seems like the CodeTogether VS Code extension is causing this
When I uninstall it, this doesn't happen
f
Good to know.
Might still be a bad idea to report diagnostics for files that aren't open. Need to check with the LSP specification authors.
b
Well thank you so much for looking into this. Such an odd bug
Bummed it had to do with my environment lol
f
Very grateful you did all the tests
Might still be a mistake on our side.
b
I'll just disable the extension for this workspace and it seems like I'm "unblocked" to develop Toit on a Mac. I don't plan on using that extension for this project
f
Very happy we seem to have found the issue.
7 Views
PreviousNext
Powered by