Processing a large compile_commands.json takes too long

akbyrd commented 2 weeks ago

Environment

OS and Version: Win10 22H2 19045
VS Code Version: 1.94
C/C++ Extension Version: 1.21.6
If using SSH remote, specify OS of remote machine: N/A

Bug Summary and Steps to Reproduce

Bug Summary: The extension gets stuck initializing Intellisense more or less permanently when loading a compilation database with a large number of file entries. The extension is unusable while this occurs. It's a single threaded process that appears to process every file in the compilation database before enabling any LSP features for currently opened files.

Steps to reproduce:

Clone UnrealEngine (use a shallow clone to make it faster) a. Sorry, I know this is a pain for a repro. There's a small, self-contained partial repro I can't share publicly if there's a private channel available.
Open the folder with vscode
Run GenerateProjectFiles.bat -VSCode
Close and re-open vscode (still as a folder, you don't need to use the workspace)
Open a file (e.g. AssertionMacroTests.cpp)
Notice Intellisense is initializing
Wait a while
Notice Intellisense is still initializing
Attempt to "go to definition" on a #include statement
Notice no code navigation or code completion operations work

Expected behavior:

Intellisense and LSP operations for the currently active file are prioritized above all other files.
Beginning normal LSP operations is not blocked on doing any operation on every single file in the directory.

When not using compile commands the tag parser fallback behaves correctly. It will immediately parse the current open file. Similarly, clangd handles the current file before doing background indexing.

It's also possible to observe the bad behavior with just the .vscode directory and not the entire engine. When the actual code files are missing the C/C++ Configuration Warnings output will be spammed with errors like this:

[10/9/2024, 9:37:04 AM] Unable to locate forced include: D:\UnrealEngine\Engine\Intermediate\Build\Win64\x64\UnrealEditorGPF\Development\UnrealEd\SharedPCH.UnrealEd.Cpp20.h

While this is occurring, Intellisense is in the "initializing" state indicating that it is processing every single file in the database before the init completes and LSP operations in the current file begin to function.

Configuration and Logs

{
    "configurations": [
        {
            "name": "Win32",
            "compilerPath": "C:\\Program Files\\Microsoft Visual Studio\\2022\\Professional\\VC\\Tools\\MSVC\\14.38.33130\\bin\\Hostx64\\x64\\cl.exe",
            "cStandard": "c17",
            "cppStandard": "c++20",
            "intelliSenseMode": "msvc-x64",
            "compileCommands": "D:\\UnrealEngine\\.vscode\\compileCommands_Default.json"
        }
    ],
    "version": 4
}

I don't think I can get C/C++: Log Diagnostics. The command doesn't do anything. Looks like it's an LSP request? And since the LSP is essentially stalled it's not returning a response.

loggingLevel: Debug
LSP: (received) cpptools/initialize (id: 1)
LSP: (invoked) cpptools/initialize (id: 1)
cpptools version (TypeScript): 1.21.6
cpptools version (native): 1.21.6.0
Autocomplete is enabled.
Error squiggles are enabled.
Hover is enabled.
IntelliSense Engine = default.
LSP: Sending response (id: 1)
LSP: (received) cpptools/queryCompilerDefaults (id: 2)
LSP: (invoked) cpptools/queryCompilerDefaults (id: 2)
LSP: Sending response (id: 2)
LSP: (received) cpptools/didChangeCppProperties (id: 3)
LSP: (invoked) cpptools/didChangeCppProperties (id: 3)
LSP: (received) cpptools/didChangeSettings
LSP: (received) cpptools/didChangeSettings
LSP: (received) cpptools/didChangeSettings
LSP: (received - deferred) textDocument/didOpen: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp
LSP: Message ignored due to no registered handler: $/setTrace
LSP: (received - deferred) cpptools/didChangeVisibleTextEditors
LSP: (received - deferred) cpptools/didChangeVisibleTextEditors
LSP: (received - deferred) cpptools/didChangeVisibleTextEditors
LSP: (received - deferred) cpptools/getCodeActions: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 4)
LSP: (received - deferred) cpptools/getCodeActions: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 5)
LSP: (received - deferred) cpptools/getFoldingRanges: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 6)
LSP: (received) cpptools/didChangeSettings
LSP: (received - deferred) cpptools/getCodeActions: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 7)
LSP: (received - deferred) cpptools/getCodeActions: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 8)
LSP: $/cancelRequest (cpptools/getCodeActions, id: 4)
LSP: $/cancelRequest (cpptools/getCodeActions, id: 5)
LSP: $/cancelRequest (cpptools/getFoldingRanges, id: 6)
LSP: $/cancelRequest (cpptools/getCodeActions, id: 7)
LSP: (received - deferred) cpptools/getDocumentSymbols: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 9)
Code browsing service initialized
Attempting to get defaults from C++ compiler in "compilerPath" property: 'C:\Program Files\Microsoft Visual Studio\2022\Professional\VC\Tools\MSVC\14.38.33130\bin\Hostx64\x64\cl.exe'
Attempting to get defaults from C compiler in "compilerPath" property: 'C:\Program Files\Microsoft Visual Studio\2022\Professional\VC\Tools\MSVC\14.38.33130\bin\Hostx64\x64\cl.exe'

Other Extensions

I've repro'd on Insiders with no other extensions.

Additional context

No response

sean-mcmanus commented 2 weeks ago

@akbyrd Did you repro this with 1.22.8 too? That has some potential fixes.

It appears to be stuck from (invoked) cpptools/didChangeCppProperties

akbyrd commented 2 weeks ago

Yea, looks like the insiders version I have is 1.22.8 and I was able to repro there. The logging is a little different though. I see a continuous stream of

Attempting to get defaults from C++ compiler in "compilerPath" property: 'C:\Program Files\Microsoft Visual Studio\2022\Professional\VC\Tools\MSVC\14.38.33130\bin\Hostx64\x64\cl.exe'

It doesn't seem stalled, it just seems like it's doing a boatload of work before enabling LSP operations.

loggingLevel: Debug
LSP: (received) cpptools/initialize (id: 1)
LSP: (invoked) cpptools/initialize (id: 1)
cpptools version (TypeScript): 1.22.8
cpptools version (native): 1.22.8.0
Autocomplete is enabled.
Error squiggles are enabled if all header dependencies are resolved.
Hover is enabled.
IntelliSense Engine = default.
LSP: Sending response (id: 1)
LSP: (received) cpptools/queryCompilerDefaults (id: 2)
LSP: (invoked) cpptools/queryCompilerDefaults (id: 2)
Compiler info database not connected - skipping load.
Compiler info database not connected - skipping load.
LSP: Sending response (id: 2)
LSP: (received) cpptools/didChangeCppProperties (id: 3)
LSP: (invoked) cpptools/didChangeCppProperties (id: 3)
LSP: (received) cpptools/didChangeSettings
LSP: (received) cpptools/didChangeSettings
LSP: (received) cpptools/didChangeSettings
LSP: (received) cpptools/didChangeSettings
LSP: (received) cpptools/didChangeSettings
LSP: (received - deferred) textDocument/didOpen: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp
LSP: (received - deferred) cpptools/didChangeVisibleTextEditors
LSP: (received - deferred) cpptools/didChangeVisibleTextEditors
LSP: (received - deferred) cpptools/didChangeVisibleTextEditors
LSP: (received - deferred) cpptools/getCodeActions: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 4)
LSP: (received - deferred) cpptools/getCodeActions: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 5)
LSP: (received - deferred) cpptools/getFoldingRanges: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 6)
LSP: (received - deferred) cpptools/getCodeActions: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 7)
LSP: $/cancelRequest (cpptools/getCodeActions, id: 4)
LSP: $/cancelRequest (cpptools/getCodeActions, id: 5)
LSP: $/cancelRequest (cpptools/getFoldingRanges, id: 6)
LSP: Message ignored due to no registered handler: $/setTrace
LSP: (received) cpptools/didChangeSettings
LSP: (received - deferred) cpptools/getDocumentSymbols: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 8)
LSP: $/cancelRequest (cpptools/getCodeActions, id: 7)
LSP: (received - deferred) cpptools/getCodeActions: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 9)
LSP: (received - deferred) cpptools/getDocumentSymbols: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 10)
Code browsing service initialized
Populating file name cache...
Done populating filename cache. Elapsed time: 0 ms
Attempting to get defaults from C compiler in "compilerPath" property: 'C:\Program Files\Microsoft Visual Studio\2022\Professional\VC\Tools\MSVC\14.38.33130\bin\Hostx64\x64\cl.exe'
Attempting to get defaults from C++ compiler in "compilerPath" property: 'C:\Program Files\Microsoft Visual Studio\2022\Professional\VC\Tools\MSVC\14.38.33130\bin\Hostx64\x64\cl.exe'
Attempting to get defaults from C++ compiler in "compilerPath" property: 'C:\Program Files\Microsoft Visual Studio\2022\Professional\VC\Tools\MSVC\14.38.33130\bin\Hostx64\x64\cl.exe'
Attempting to get defaults from C++ compiler in "compilerPath" property: 'C:\Program Files\Microsoft Visual Studio\2022\Professional\VC\Tools\MSVC\14.38.33130\bin\Hostx64\x64\cl.exe'
...

sean-mcmanus commented 2 weeks ago

@akbyrd Yeah, I think it's processing the compile_commands command. This was improved with https://github.com/microsoft/vscode-cpptools/issues/10029. How many compile commands entries are there? How long are you seeing it take to finish processing that?

akbyrd commented 2 weeks ago

77,727 in one workspace with just the engine 108,140 in another with the projects I need to work in

Big numbers, and I'll be the first to complain about it, but it is what it is. I can't really pare it down since I'm poking at foundational bits that everything uses.

I think the important requirement here is that Intellisense and LSP operations for the current file can't depend on work being performed in all files, only its actual dependencies. That might still be a large number of files, and that's ok, as long as it's not artificially gated by everything.

I don't think this was always an issue. I've been working in this codebase for a few years and I think the extension would fallback to the tag parser if Intellisense was still trying to catch up. I vaguely recall that I'd have basic operations that weren't entirely accurate for a while in a new workspace, then it would catch up after a while. Currently I get no operations at all, everything stalls with a loading bar until the init phase is complete.

How long are you seeing it take to finish processing that?

I haven't seen it finish yet. I'll let it go overnight tonight to see if it completes. How can I see the progress? Is there a log file with progress and timestamps so I can estimate the completion time if it doesn't finish?

akbyrd commented 2 weeks ago

After letting it sit for a while it did get past initializing. Without timestamps I can't say how long it took, but more than 1 hour and less than 2.75 hours.

I set the logging to "7" instead of "Debug" which I saw you mention elsewhere. I see about 100,000

LSP: Sending server -> client notification: cpptools/updateTrustedCompilersList

then a few

Folder: D:\BLAH\ will be indexed

then all the pending LSP operations finally begin to process

LSP: (queued) textDocument/didOpen: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp
LSP: (queued) cpptools/didChangeVisibleTextEditors
LSP: (queued) cpptools/didChangeVisibleTextEditors
LSP: (queued) cpptools/didChangeVisibleTextEditors
LSP: (queued) cpptools/getCodeActions: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 4)
LSP: (queued) cpptools/getCodeActions: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 5)
LSP: (queued) cpptools/getCodeActions: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 6)
LSP: (queued) cpptools/getDocumentSymbols: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 7)
LSP: (queued) cpptools/getCodeActions: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 8)
LSP: (queued) cpptools/getFoldingRanges: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 9)
LSP: (queued) cpptools/getDocumentSymbols: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 10)
LSP: (invoked) cpptools/getDocumentSymbols: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 7)
LSP: Sending response (id: 3)
LSP: (invoked) cpptools/getDocumentSymbols: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 10)
LSP: Sending server -> client notification: cpptools/reportStatus
LSP: Sending server -> client notification: cpptools/reportTagParseStatus
LSP: Sending server -> client notification: cpptools/reportStatus
Discovering files...
LSP: (invoked) cpptools/didChangeSettings
LSP: Sending server -> client notification: cpptools/reportStatus
Autocomplete is enabled.
Error squiggles are enabled.
Hover is enabled.
IntelliSense Engine = default.
Enhanced Colorization is enabled.
LSP: Sending server -> client notification: cpptools/reportStatus
LSP: (invoked) cpptools/didChangeSettings
Autocomplete is enabled.
Error squiggles are enabled.
Hover is enabled.
IntelliSense Engine = default.
Enhanced Colorization is enabled.
LSP: Sending server -> client notification: cpptools/reportStatus
LSP: (invoked) cpptools/didChangeSettings
Autocomplete is enabled.
Error squiggles are enabled.
Hover is enabled.
IntelliSense Engine = default.
tag parsing file: D:\UnrealEngine\Engine\Source\Runtime\Core\Tests\Misc\AssertionMacrosTest.cpp
Enhanced Colorization is enabled.
LSP: Sending server -> client notification: cpptools/reportStatus
LSP: (invoked) cpptools/didChangeSettings
Autocomplete is enabled.
Error squiggles are enabled.
Hover is enabled.
IntelliSense Engine = default.
Enhanced Colorization is enabled.
LSP: Sending server -> client notification: cpptools/reportStatus
LSP: (invoked) cpptools/queryCompilerDefaults (id: 11)
LSP: Sending response (id: 11)
LSP: (invoked) textDocument/didOpen: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp
  Processing folder (non-recursive): C:\PROGRAM FILES (X86)\MICROSOFT VISUAL STUDIO\2019\PROFESSIONAL\VC\TOOLS\MSVC\14.29.30133\INCLUDE
process_path: C:\PROGRAM FILES (X86)\MICROSOFT VISUAL STUDIO\2019\PROFESSIONAL\VC\TOOLS\MSVC\14.29.30133\INCLUDE
LSP: (invoked) cpptools/didChangeVisibleTextEditors
LSP: Sending server -> client notification: cpptools/IntelliSenseSetup
CodeSearch (prefix phase): Time(2ms) ResultsCount(6) Indexed(t) Fuzzy(f) SingleFile (t) Scoped(f) ExcludedImplicit(f)
CodeSearch: TotalResultsCount(6) TotalTime(2ms)
  Processing folder (recursive): C:\PROGRAM FILES (X86)\WINDOWS KITS\10\INCLUDE\10.0.26100.0\CPPWINRT\
process_path: C:\PROGRAM FILES (X86)\WINDOWS KITS\10\INCLUDE\10.0.26100.0\CPPWINRT\
CodeSearch: LoadResultsTime(14ms)
CodeSearch: QuerySymbolsTotalTime(17ms)
LSP: Sending response (id: 7)
CodeSearch (prefix phase): Time(1ms) ResultsCount(6) Indexed(t) Fuzzy(f) SingleFile (t) Scoped(f) ExcludedImplicit(f)
CodeSearch: TotalResultsCount(6) TotalTime(1ms)
CodeSearch: LoadResultsTime(7ms)
CodeSearch: QuerySymbolsTotalTime(9ms)
LSP: Sending response (id: 10)
tag parsing file: D:\UnrealEngine\Engine\Source\Runtime\Core\Tests\Misc\AssertionMacrosTest.cpp
Intellisense update pending for: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp
LSP: Sending server -> client notification: cpptools/reportStatus
LSP: (invoked) cpptools/getCodeActions: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 4)
LSP: (invoked) cpptools/getCodeActions: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 5)
LSP: (invoked) cpptools/getCodeActions: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (id: 6)

then some more processing

Populating file name cache...
  Processing folder (recursive): C:\PROGRAM FILES (X86)\WINDOWS KITS\10\INCLUDE\10.0.26100.0\UCRT\

Done populating filename cache. Elapsed time: 812 ms
    Memory usage delta: 142 MB
    Number of files: 6589
    Number of parent/child relationships: 5854
sending compilation args for D:\UnrealEngine\Engine\Source\Runtime\Core\Tests\Misc\AssertionMacrosTest.cpp
  include: D:\UNREALENGINE\ENGINE\SOURCE
...
  system include: C:\PROGRAM FILES\MICROSOFT VISUAL STUDIO\2022\PROFESSIONAL\VC\TOOLS\MSVC\14.38.33130\INCLUDE
...
  preinclude: D:\UNREALENGINE\ENGINE\INTERMEDIATE\BUILD\WIN64\X64\ACEXEPARSERGPF\DEVELOPMENT\CORE\DEFINITIONS.H
  stdver: ms_c++20
  intelliSenseMode: windows-msvc-x64
IntelliSense TU acquired for: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp
Starting IntelliSense update for: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp (needs_reparse==true)
Processing partial IntelliSense update for: file:///d%3A/UnrealEngine/Engine/Source/Runtime/Core/Tests/Misc/AssertionMacrosTest.cpp [0-850]
LSP: Sending server -> client notification: cpptools/reportTagParseStatus

  Discovering files: 313511 file(s) processed
  0 file(s) removed from database
LSP: Sending server -> client notification: cpptools/logTelemetry
Done discovering files.
LSP: Sending server -> client notification: cpptools/reportStatus
Parsing open files...
LSP: Sending server -> client notification: cpptools/reportStatus
Populating include completion cache.
Parsing remaining files...
tag parsing file: D:\UnrealEngine\Engine\Source\Runtime\Core\Public\Misc\AssertionMacros.h
...

sean-mcmanus commented 2 weeks ago

@akbyrd Was the 100k updateTrustedCompilersList with 1.22.8? That was supposed to be fixed by https://github.com/microsoft/vscode-cpptools/issues/12078 .

I think we only tested performance for a 10k compile_commands and 70-110k might require additional optimization or algorithm changes.

akbyrd commented 2 weeks ago

No, it was my retail install that I let run (1.21.6). Is there any other helpful data I can gather?

sean-mcmanus commented 2 weeks ago

@akbyrd If you can try with 1.22.8 (which we're planning to release soon as 1.22.9 non-pre-release) and let us know if (how much) it is faster that would help. But otherwise, I think we have enough info.

akbyrd commented 2 weeks ago

I let 1.22.8 grind away on the 108k workspace and it took around 2.75 hours (+/- 30 minutes). AMD EPYC 7R32 with 32 threads and 128 GB of memory available.

sean-mcmanus commented 2 weeks ago

@akbyrd Okay, sounds like "no improvement".

sean-mcmanus commented 2 weeks ago

@akbyrd Also, FYI, the Visual Studio 2022 product has specific optimizations and functionality for Unreal Engine that don't exist in VS Code, so you may want to consider that instead.

akbyrd commented 2 weeks ago

Thanks for the tip. I'm using that as a fallback for the moment. But the goal is to stick when vscode as vs is much too slow for daily use.

I noticed it does some initial parsing for headers for the first minute or so and then Intellisense operations work so it doesn't seem to get blocked up on the initial. But the build tool for Unreal produces some sort of Intellisense data in advance, but I haven't looked into exactly what that data is yet. So it might be pre-populating some of the data that vscode has to figure out for itself.

microsoft / vscode-cpptools