Toit VS Code extension high CPU usage (MacOS)

Toit

#Toit VS Code extension high CPU usage (MacOS)

Thread channel in help

bpmct 03/19/2023 07:53 PM

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

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

High CPU usage on MacOS · Issue #212 · toitware/ide-tools

I'm seeing extremely high CPU usage on my MacOS (amd64) machine. On Linux, the extension works fine. Here are the logs from the output panel: 2023-03-19T14:50:17.591-0500 ERROR Compiler.com...

floitsch 03/19/2023 07:54 PM

floitsch 03/19/2023 07:56 PM

Do you know if the error message is related?

floitsch 03/19/2023 07:56 PM

Is the CPU spiking after such a message?

floitsch 03/19/2023 07:56 PM

Is the error message showing up continuously?

bpmct 03/19/2023 07:56 PM

Yeah the error is showing up continuously

bpmct 03/19/2023 07:57 PM

CPU spikes almost immediately after I open a toit file and the error appears

bpmct 03/19/2023 07:58 PM

Ah there is a bit more at the top! Sorry

bpmct 03/19/2023 07:59 PM

https://gist.github.com/bpmct/ba17b88a5c43e9d6c35b48082ae7829b

gist:ba17b88a5c43e9d6c35b48082ae7829b

GitHub Gist: instantly share code, notes, and snippets.

floitsch 03/19/2023 08:00 PM

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).

bpmct 03/19/2023 08:02 PM

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

bpmct 03/19/2023 08:02 PM

No worries. I have a Linux machine so I'm happy to use that

floitsch 03/19/2023 08:02 PM

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).

floitsch 03/19/2023 08:04 PM

Do you, by chance, have delve installed (Go's debugger).

bpmct 03/19/2023 08:04 PM

No, but I'l happy to install it.\

floitsch 03/19/2023 08:04 PM

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.

floitsch 03/19/2023 08:04 PM

I'm not sure if it works without the sources, but this is how we found the issue last time.

bpmct 03/19/2023 08:05 PM

To the pid for toit.lsp?

floitsch 03/19/2023 08:05 PM

yes.

bpmct 03/19/2023 08:05 PM

Sure. Giving this a shot now

bpmct 03/19/2023 08:10 PM

I'm afraid I don't know where to go from here:

➜  bin dlv attach 61015
Type 'help' for list of commands.
(dlv)

floitsch 03/19/2023 08:11 PM

not too familiar with Golang/delve either, but let me look it up.

floitsch 03/19/2023 08:11 PM

can you start by threads ?

bpmct 03/19/2023 08:12 PM

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

(edited)

floitsch 03/19/2023 08:13 PM

trying to find the right commands.

floitsch 03/19/2023 08:15 PM

Not sure this is what needs to be done, but:

goroutines

list all goroutines.

floitsch 03/19/2023 08:15 PM

goroutine X

allows to switch to a goroutine.

floitsch 03/19/2023 08:15 PM

list

shows the source it's currently executing.

floitsch 03/19/2023 08:16 PM

bt

prints a backtrace of the current goroutine.

bpmct 03/19/2023 08:18 PM

Ah nice, it seems like we're getting somewhere

(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

floitsch 03/19/2023 08:19 PM

that's probably ok.

floitsch 03/19/2023 08:19 PM

if you go up

floitsch 03/19/2023 08:19 PM

you might get the sources.

floitsch 03/19/2023 08:19 PM

But just having the bt backtrace could already help.(edited)

bpmct 03/19/2023 08:19 PM

(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

bpmct 03/19/2023 08:20 PM

> 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)

floitsch 03/19/2023 08:20 PM

Thanks.

floitsch 03/19/2023 08:21 PM

Now let's continue the program (continue) and wait a bit.

floitsch 03/19/2023 08:21 PM

Then ctrl-c to go back into delve and see if the backtrace changed.

bpmct 03/19/2023 08:23 PM

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

floitsch 03/19/2023 08:23 PM

Looks completely different. Maybe a different goroutine?

bpmct 03/19/2023 08:25 PM

It doesn't seem to have a goroutine "selected"

Sending output to pager...
(dlv) list
Stopped at: 0x7ff80872911a
=>   1:    no source available

bpmct 03/19/2023 08:25 PM

should i completely quit out of delve and then attach again?

floitsch 03/19/2023 08:25 PM

Just noticed: "goroutine 2636". That's a lot of goroutines.
My biggest is "66"...

floitsch 03/19/2023 08:25 PM

If you goroutines you should see a list of all goroutines.

floitsch 03/19/2023 08:26 PM

Maybe one jumps out as Toit related.

bitphlipphar 03/19/2023 08:26 PM

(FWIW, I think I see this too on my Mac)

bitphlipphar

(FWIW, I think I see this too on my Mac)

floitsch 03/19/2023 08:26 PM

great(?) news. At least we should be able to debug this tomorrow, if we don't see anything fishy today.

floitsch

great(?) news. At least we should be able to debug this tomorrow, if we don't see anything fishy today.

bitphlipphar 03/19/2023 08:27 PM

Yup!

bpmct 03/19/2023 08:28 PM

I'm having trouble copying the whole list, but here's my full history: https://gist.github.com/bpmct/10a64bcc2df8363fa988fa85cf26f702

goroutines

GitHub Gist: instantly share code, notes, and snippets.

bpmct 03/19/2023 08:29 PM

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

floitsch 03/19/2023 08:29 PM

If we can reproduce we should manage. But thanks.

floitsch 03/19/2023 08:31 PM

Not making huge progress yet, but the server just seems to plow through goroutines...

floitsch 03/19/2023 08:35 PM

I don't see anything obvious yet, so I think @bitphlipphar and I will debug this tomorrow.

bpmct 03/19/2023 08:35 PM

Sounds great. Thanks for the quick response, as always

floitsch 03/19/2023 08:36 PM

And thanks for reporting and giving delve a try.

bitphlipphar 03/24/2023 01:32 PM

Maybe give Jaguar v1.9.13 a spin and see if the updated Go compiler and support packages help toit.lsp?

bpmct 03/25/2023 06:54 PM

Hey - still noticing high CPU usage with toit.lsp after upgrading to Jaguar v1.19.14

floitsch 03/25/2023 06:55 PM

Ok. Could you enable profiling?

floitsch 03/25/2023 06:55 PM

For that you need to change the vscode settings to start the LSP server with special instructions.

floitsch 03/25/2023 06:55 PM

Let me find them.

floitsch 03/25/2023 06:56 PM

If you search for the settings id toitLanguageServer.command you should have an 'edit in settings.json'.(edited)

floitsch 03/25/2023 06:56 PM

If you click on that you will be dropped into settings.json

floitsch 03/25/2023 07:00 PM

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:

[
      "/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.(edited)

floitsch 03/25/2023 07:02 PM

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.

floitsch 03/25/2023 07:02 PM

The best way to achieve this is by closing all (Toit) buffers.

floitsch 03/25/2023 07:02 PM

(I think closing the editor doesn't work).

floitsch 03/25/2023 07:07 PM

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.

bpmct 03/25/2023 07:07 PM

floitsch 03/25/2023 07:08 PM

Let's see if I can get the data, or if we need a mac for that.

bpmct 03/25/2023 07:08 PM

Quite a lot of files, actually. One is 35kb, then a few between 16-24kb, then many 2-3kb

floitsch 03/25/2023 07:08 PM

Can you confirm that you are running v2.0.0-alpha.71?

bpmct 03/25/2023 07:09 PM

➜ jag version
Version:         v1.9.14
SDK version:     v2.0.0-alpha.71
Build date:      2023-03-25T18:51:50Z
➜  toit

(edited)

OPbpmct

Quite a lot of files, actually. One is 35kb, then a few between 16-24kb, then many 2-3kb

floitsch 03/25/2023 07:09 PM

Weird... One editor should only have one toit.lsp running.

bpmct 03/25/2023 07:09 PM

Ah there are quite a lot in my activity monitor

floitsch 03/25/2023 07:09 PM

While I'm looking at the zip, could you have a look at the LSP output?

bpmct 03/25/2023 07:09 PM

Sure thing

floitsch 03/25/2023 07:09 PM

open view -> Output

floitsch 03/25/2023 07:10 PM

In the drop-down "Toit lsp server" (or something similar).

bpmct 03/25/2023 07:11 PM

https://gist.github.com/bpmct/262efe8f8a205071e70c9ae642231ea7

extension-output.sh

GitHub Gist: instantly share code, notes, and snippets.

floitsch 03/25/2023 07:11 PM

thanks!

floitsch 03/25/2023 07:12 PM

Ok. That's similar to what we already knew. Not clear why you would have so many lsp servers.

floitsch 03/25/2023 07:13 PM

One other thing that could maybe help: toitLanguageServer.trace.server

floitsch 03/25/2023 07:13 PM

In the settings: could you set that to 'verbose' ?

floitsch

Let's see if I can get the data, or if we need a mac for that.

bpmct 03/25/2023 07:15 PM

https://gist.github.com/bpmct/0ca974fbfd1c3ecee1a77707bdf1ef07

toit-trace.sh

GitHub Gist: instantly share code, notes, and snippets.

floitsch 03/25/2023 07:23 PM

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.)

floitsch 03/25/2023 07:23 PM

I will now go back to the traces and see if I can see something that sticks out.

bpmct 03/25/2023 07:28 PM

Here's a significantly longer trace, my system has extremely high CPU load whenever the extension is installed(edited)

floitsch 03/25/2023 07:29 PM

you mean as soon as the extension calls 'initialize' the CPU goes up?

bpmct 03/25/2023 07:30 PM

Umm, basically as soon as I open a .toit file

floitsch 03/25/2023 07:30 PM

ok. good to know. thanks.

bpmct 03/25/2023 07:30 PM

Not necessarily at install time, I mispoke

floitsch 03/25/2023 07:30 PM

If you open a fresh vscode, and open a simple 'hello.toit' does that also trigger the CPU?

bpmct 03/25/2023 07:31 PM

Let's try.

bpmct 03/25/2023 07:36 PM

Interesting!

bpmct 03/25/2023 07:36 PM

An extremely simple toit program doesn't seem to have the same problem

bpmct 03/25/2023 07:36 PM

floitsch 03/25/2023 07:36 PM

interesting.

bpmct 03/25/2023 07:37 PM

Here's the code I am running which causes high CPU. Still quite simple at this point

// 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"

(edited)

floitsch 03/25/2023 07:37 PM

probably one of the imports...

bpmct 03/25/2023 07:37 PM

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

floitsch 03/25/2023 07:38 PM

No worries. I'm just happy for the help

bpmct 03/25/2023 07:38 PM

It seems to work just fine on my Linux machine, which perplexes me

floitsch 03/25/2023 07:38 PM

Could you maybe comment them (one by one, or binary search), to see if one specifically is causing this?

bpmct 03/25/2023 07:38 PM

Sure

bpmct 03/25/2023 07:39 PM

It will be quite a slow process though since I think I need to uninstall/reinstall the extension between each check

floitsch 03/25/2023 07:39 PM

I would probably reload the window after every change. (just in case the LSP server doesn't recover).

bpmct 03/25/2023 07:39 PM

Yeah

floitsch 03/25/2023 07:39 PM

why?

bpmct 03/25/2023 07:39 PM

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(edited)

floitsch 03/25/2023 07:40 PM

you might also be able to just killall toit.lsp

bpmct 03/25/2023 07:42 PM

Reloading the window does the trick. Will start looking now

bpmct 03/25/2023 07:54 PM

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.

floitsch 03/25/2023 07:55 PM

strange.

floitsch 03/25/2023 07:55 PM

but interesting.

bpmct 03/25/2023 07:56 PM

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

bpmct 03/25/2023 07:57 PM

Doing more digging though

floitsch 03/25/2023 07:57 PM

I think there shouldn't be any temporary toit.lsp processes, but maybe that's just the threading showing up.

floitsch 03/25/2023 07:57 PM

Could ctrl-click on the mqtt import and see where it goes?

floitsch 03/25/2023 07:57 PM

It should go into a directory inside some .packages.

bpmct 03/25/2023 07:58 PM

floitsch 03/25/2023 07:58 PM

Exactly. So it's in the .packages of your project.

floitsch 03/25/2023 07:59 PM

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)?

bpmct 03/25/2023 07:59 PM

Here is what i meant about the "temporary" processes.

floitsch 03/25/2023 07:59 PM

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)

OPbpmct

Here is what i meant about the "temporary" processes.

floitsch 03/25/2023 08:00 PM

question is whether it's a temporary process, or the same one that just starts using CPU (while handling the diagnostic).

bpmct 03/25/2023 08:01 PM

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(edited)

bpmct 03/25/2023 08:01 PM

floitsch 03/25/2023 08:02 PM

Still good to know.

bpmct 03/25/2023 08:02 PM

Would it be more helpful if I used ps or something?

floitsch 03/25/2023 08:02 PM

Since you have a very nice setup now. Could you remove all old profiles, and do another one with the mqtt?

bpmct 03/25/2023 08:02 PM

I have been considering factory resetting my machine. It's possible something on my environment is just wonky

bpmct 03/25/2023 08:02 PM

Sure

floitsch 03/25/2023 08:02 PM

Also checking whether there are some messages in the output.

bpmct 03/25/2023 08:03 PM

Sure thing

bpmct 03/25/2023 08:05 PM

and the lsp output: https://gist.github.com/bpmct/abfc2e600574584866164d76ac5413e7

lsp-output.txt

GitHub Gist: instantly share code, notes, and snippets.

bpmct 03/25/2023 08:07 PM

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

floitsch 03/25/2023 08:07 PM

Still trying to make sense of this.
There are a lot of initialize calls.

floitsch 03/25/2023 08:13 PM

I'm guessing the LSP output window stays busy when the CPU is high?
(but is otherwise only active when changes happen).

bpmct 03/25/2023 08:15 PM

Yep.

floitsch 03/25/2023 08:15 PM

I'm a bit confused by all the 'initialize' calls.
I'm trying to create a vscode extension that adds a bit of logging.

floitsch 03/25/2023 08:42 PM

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

floitsch 03/25/2023 08:43 PM

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'.

floitsch 03/25/2023 08:43 PM

It can be installed with code --install-extension toit-1.6.6.vsix

floitsch 03/25/2023 08:45 PM

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.

floitsch 03/25/2023 08:47 PM

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.

bpmct 03/25/2023 09:21 PM

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

bpmct 03/25/2023 09:22 PM

Here are the output logs

bpmct 03/25/2023 09:27 PM

seems to loop with the following libraries

jaguar/sdk/lib/crypto
jaguar/sdk/lib/system/base
jaguar/sdk/lib/system
jaguar/sdk/lib/encoding
jaguar/sdk/lib/tls

floitsch 03/25/2023 09:29 PM

Yeah. something is weird there.
As long as you don't have these files open, it shouldn't open a new server.

floitsch 03/25/2023 09:29 PM

(If I remember correctly).

floitsch 03/25/2023 09:30 PM

Let me add a bit more debugging info.

floitsch 03/25/2023 09:36 PM

I think we are on the right track.

floitsch 03/25/2023 09:37 PM

From the logs it looks like every time we publish a diagnostic, the editor sends a 'textDocument/didOpen' request.

floitsch 03/25/2023 09:37 PM

It doesn't do that in my editor.

floitsch 03/25/2023 09:37 PM

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.

floitsch 03/25/2023 09:38 PM

My guess is that the mqtt package opens a library that has a cyclic import, which then leads to infinite toit lsp servers.

bpmct 03/25/2023 10:40 PM

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

bpmct 03/25/2023 10:41 PM

When I uninstall it, this doesn't happen

floitsch 03/25/2023 10:41 PM

Good to know.

floitsch 03/25/2023 10:41 PM

Might still be a bad idea to report diagnostics for files that aren't open. Need to check with the LSP specification authors.(edited)

bpmct 03/25/2023 10:42 PM

Well thank you so much for looking into this. Such an odd bug

bpmct 03/25/2023 10:42 PM

Bummed it had to do with my environment lol

floitsch 03/25/2023 10:42 PM

Very grateful you did all the tests

OPbpmct

Bummed it had to do with my environment lol

floitsch 03/25/2023 10:43 PM

Might still be a mistake on our side.

bpmct 03/25/2023 10:43 PM

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

floitsch 03/25/2023 10:44 PM

Very happy we seem to have found the issue.

167 messages in total