LSP file watch events with many paths spends too much time/memory in MatchesFileName

[lukpsaxo]

I had a @types/lodash package installed that caused errors, then switched branch to one with a previous version and did yarn install.

at 07:08:21 the yarn command had finished and the editor showed errors (e.g. was still using the old version of node_modules)

I started raising this bug and seemingly without interaction at 07:11:01 the errors disappeared (the extension noticed that node_modules had been updated and used the latest version)

I've seen this behaviour when switching branches and running yarn before so I think it should be easily reproducible. In the past I just restarted the extension whenever running yarn install.

I am using the classic mode of yarn where files are copied into node_modules - no linking.

The logs looked like this:

Info 142  [07:08:21.025] createGlobMapper took 80.1279ms to create 11 globs for 153405 failed lookups
Info 143  [07:08:21.025] createGlobMapper took 0s to create 6 globs for 349 failed lookups
Info 144  [07:08:21.025] Finishing updateGraph: Project: c:/Projects/x/y/src/frontend/tsconfig.json version: 5 in 1.3436852s
Info 145  [07:11:01.206] Starting updateGraph: Project: c:/Projects/x/y/src/frontend/tsconfig.json
Info 146  [07:11:01.206] Program 6 used 3 checker(s)
Info 147  [07:11:01.206] Starting updateGraph: Project: c:/Projects/x/y/src/toolkit/tsconfig.json
Info 148  [07:11:01.206] Program 6 used 2 checker(s)
Info 149  [07:11:01.206] Starting updateGraph: Project: c:/Projects/x/y/src/ui/tsconfig.json
Info 150  [07:11:01.206] Program 4 used 2 checker(s)
Info 151  [07:11:01.334] 

[jakebailey]

It'd be interesting if you could look at the raw LSP logs (the other output window) and see when the watch events came in.

All the new server does is ask VS Code to watch the files, so we'd need to know where the delay is.

[lukpsaxo]

I re-did the test. Again it eventually gets the right types after 3 minutes.

The LSP server sends a notification whilst yarn is installing - so you see one notification and then a 2nd with the rest of the files.

[Trace - 10:38:40 AM] Sending notification 'workspace/didChangeWatchedFiles'.
Params: {
    "changes": [
        {
            "uri": "file:///c%3A/Projects/x/y/node_modules/react-stately/node_modules/%40internationalized/date/dist/BuddhistCalendar.main.js",
            "type": 3
        },
        {
            "uri": "file:///c%3A/Projects/x/y/node_modules/react-stately/node_modules/%40internationalized/date/dist/BuddhistCalendar.main.js",
            "type": 3
        }
    ]
}


[Trace - 10:38:40 AM] Received request 'workspace/diagnostic/refresh - (ts133)'.
[Trace - 10:38:40 AM] Sending response 'workspace/diagnostic/refresh - (ts133)'. Processing request took 0ms
No result returned.


[Trace - 10:38:40 AM] Sending request 'textDocument/diagnostic - (11067)'.
Params: {
    "textDocument": {
        "uri": "file:///c%3A/Projects/x/y/src/frontend/components/file.ts"
    }
}


[Trace - 10:38:40 AM] Received response 'textDocument/diagnostic - (11067)' in 1ms.
Result: {
    "kind": "full",
    "items": []
}


[Trace - 10:38:40 AM] Sending notification 'workspace/didChangeWatchedFiles'.
Params: {
    "changes": [
        {
            "uri": "file:///c%3A/Projects/x/y/node_modules/%40types/lodash/at.d.ts",
            "type": 3
        },
        {
            "uri": "file:///c%3A/Projects/x/y/node_modules/%40types/lodash/eq.d.ts",

Then thousands of node_modules files that change. Then

[Trace - 10:38:48 AM] Sending request 'textDocument/diagnostic - (11068)'.
Params: {
    "textDocument": {
        "uri": "file:///c%3A/Projects/x/y/src/frontend/components/file.ts"
    }
}


[Trace - 10:39:07 AM] Received request 'workspace/diagnostic/refresh - (ts134)'.
[Trace - 10:39:07 AM] Sending notification '$/cancelRequest'.
Params: {
    "id": 11068
}


[Trace - 10:39:07 AM] Sending response 'workspace/diagnostic/refresh - (ts134)'. Processing request took 1ms
No result returned.


[Trace - 10:39:48 AM] Received request 'workspace/diagnostic/refresh - (ts135)'.
[Trace - 10:39:48 AM] Sending response 'workspace/diagnostic/refresh - (ts135)'. Processing request took 1ms
No result returned.


[Trace - 10:40:08 AM] Received request 'workspace/diagnostic/refresh - (ts136)'.
[Trace - 10:40:09 AM] Sending response 'workspace/diagnostic/refresh - (ts136)'. Processing request took 1ms
No result returned.


[Trace - 10:40:34 AM] Sending notification 'textDocument/didClose'.
Params: {
    "textDocument": {
        "uri": "file:///c%3A/Projects/x/y/src/frontend/components/different-file.ts"
    }
}


[Trace - 10:41:00 AM] Received request 'workspace/diagnostic/refresh - (ts137)'.
[Trace - 10:41:00 AM] Sending response 'workspace/diagnostic/refresh - (ts137)'. Processing request took 0ms
No result returned.


[Trace - 10:41:34 AM] Received request 'workspace/diagnostic/refresh - (ts138)'.
[Trace - 10:41:34 AM] Sending response 'workspace/diagnostic/refresh - (ts138)'. Processing request took 0ms
No result returned.


[Trace - 10:41:37 AM] Received response 'textDocument/diagnostic - (11068)' in 169121ms.
Result: {
    "kind": "full",
    "items": [

and at 10:41:37 everything is ok again.

So I guess the extension is taking a very long time after receiving notifications about alot of files in node_modules changing.

[lukpsaxo]

For reference, if I restart vscode, it takes around 10 seconds for the typescript errors to come in, which is about right considering tsgo native check takes 12 seconds.

[jakebailey]

Then thousands of node_modules files that change. Then

To be clear, you're saying that you omitted an event with thousands of files, and then it takes a while for the server to send its next message?

[lukeapage]

Sorry for being unclear. I pasted the full logs except that the event before where it’s cut off with 2 files was actually thousands of files.. too long to paste into a comment.

[lukeapage]

Eg the changes array was thousands of files.

[jakebailey]

Gotcha, thanks. That sounds like an issue we've observed internally, where all of the time is actually just spent doing pattern matches when processing all of the incoming events.

[jakebailey]

What would also be helpful is if you set typescript.native-preview.pprofDir to a fresh directory, reload your editor, make the problem happen again, then run the "restart language server command" to ask the process to exit and write the profile.

The profile doesn't contain anything private, just paths from our codebase, so would be safe to upload.

Just remember to remove the setting since leaving it on will constantly profile the code. (We should make a better flow for that...)

[lukpsaxo]

ok, here you go:

21764-cpuprofile.pb.gz
21764-memprofile.pb.gz

It seemed faster this time (less files open or maybe less files changed in node_modules?) but still slower than it should be. it should be in the later half of the profile.

[jakebailey]

Hm, this doesn't show exactly what I expect. Most of the time is just reading files, which makes it sound like Defender is getting in the way, but then the profile length seems to be a half hour, which is too long to really see what's happening. Was this from a 30 minute session or is the profile miscounting the time?

[lukeapage]

it wasn't 30 minutes for sure. I will retry and take a look myself at the visualization.

[lukeapage]

Its similiar. I am guessing its showing cpu time so with my many cores, it shows the file loading as taking the majority of the time, but wall clock time it is the first 15 seconds. Then there is 47 seconds in matches file name which you thought might be the problem and maybe thats on one core?

[jakebailey]

Yeah, that's what I was thinking. Thanks. Do you have that second profile too?

[lukeapage]

10208-memprofile.pb.gz
10208-cpuprofile.pb.gz

[lukpsaxo]

I've reproduced the 3-4 minute delay by switching from a older branch, so I will send that one shortly, it should show something more pronounced.