Format on save takes way too long with cmake extension enabled.

[christianbrugger]

Brief Issue Summary

When using format on save "editor.formatOnSave": true with CMake Tools extension enabled the save often takes 10 seconds or even longer. For the formatting itself I am using clang-format-17.

Slow.-.CMake.Extension.Enabled.webm

Running clang-format-17 itself takes 20ms on this file when launched from the terminal.

$ time clang-format-17 -i src/component/simulation/history_calculation.h

real	0m0.023s
user	0m0.007s
sys	0m0.015s

[gcampbell-msft]

@christianbrugger Thanks for posting this issue. I believe this is actually a bug on the cpptools extension, which is a dependency of ours (see #6809). @sean-mcmanus @bobbrow @Colengms Could you transfer this to the cpptools extension?

[sean-mcmanus]

@christianbrugger What is your "editor.formatOnSaveMode"?

[christianbrugger]

@sean-mcmanus "editor.formatOnSaveMode" is set to "file"

[sean-mcmanus]

@christianbrugger What version of the C/C++ extension are you using? Also, with "C_Cpp.loggingLevel": "Debug" set, what is the last "LSP (invoked)" line that in the C/C++ logging pane when it's stuck formatting? It should be LSP: (invoked) cpptools/formatDocument unless it's stuck on a different operation.

[sean-mcmanus]

@christianbrugger My guess is you're hitting a combination of #6156 and #12169 . You'd see logging like

Intellisense update pending for: 
LSP: (invoked) textDocument/didChange: 
LSP: (invoked) textDocument/completion (or some other IntelliSense operation): 
Populating file name cache...
...
Done populating filename cache. Elapsed time: 
sending compilation args for
...
LSP: (invoked) cpptools/formatDocument

[christianbrugger]

@sean-mcmanus I am using C/C++ version 1.20.1 (pre-release).

When enabling "C_Cpp.loggingLevel": "Debug" it hangs at actually at several points:

LSP: (received) cpptools/didChangeTextEditorSelection
LSP: (received) textDocument/didChange: file:history_calculation.h
LSP: (received) cpptools/didChangeTextEditorSelection
//                                                      <============== hangs here 1.5 seconds
LSP: (received) textDocument/willSaveWaitUntil: file:history_calculation.h (id: 366)
LSP: (invoked) textDocument/willSaveWaitUntil: file:history_calculation.h (id: 366)
LSP: Sending response (id: 366)
willSaveWaitUntil: 0ms
LSP: (received) cpptools/getCodeActions: file:history_calculation.h (id: 367)
LSP: (received) cpptools/formatDocument: file:history_calculation.h (id: 368)
LSP: (received) cpptools/getDocumentSymbols: file:history_calculation.h (id: 369)
LSP: (invoked) cpptools/getDocumentSymbols: file:history_calculation.h (id: 369)
LSP: (received) cpptools/getDocumentSymbols: file:history_calculation.h (id: 370)
LSP: $/cancelRequest (cpptools/getDocumentSymbols, id: 365)
LSP: (invoked) cpptools/getDocumentSymbols: file:history_calculation.h (id: 370)
sending 2 changes to server
//                                                      <============== hangs here 6 seconds
Database safe to open.
LSP: Sending response (id: 369)
LSP: Sending response (id: 370)
//                                                      <============== hangs here 8 seconds
Update IntelliSense time (sec): 22.524
LSP: (invoked) cpptools/fileChanged: file:history_calculation.h
LSP: (invoked) cpptools/getCodeActions: file:history_calculation.h (id: 363)
LSP: (invoked) textDocument/didChange: file:history_calculation.h
LSP: (invoked) textDocument/didChange: file:history_calculation.h
LSP: (invoked) cpptools/didChangeTextEditorSelection
LSP: (invoked) cpptools/getCodeActions: file:history_calculation.h (id: 367)
//                                                      <============== hangs here 1 seconds
LSP: Sending response (id: 367)
LSP: (invoked) cpptools/formatDocument: file:history_calculation.h (id: 368)
Formatting document: file:history_calculation.h
Formatting Engine: clangFormat
/usr/bin/clang-format-17 -style=file -fallback-style=LLVM --Wno-error=unknown -assume-filename=history_calculation.h
LSP: Sending response (id: 368)

formatting-file-log.webm

To me it looks like formatting is sometimes blocked until IntelliSense is done, leading to large delays. Formatting does not depend on IntelliSense so this could be resolved by better scheduling of those tasks.

Issue #6156 speaks about the same problem in a the context of on-type formatting, where similar delays are reported. In that way it is similar. One suggested fix was to make on-type formatting not depend on file formatting and use a simpler, e.g. Python based, method. Such a fix would not help here.

Issue #12169 is about the time of IntelliSense being too large in general, not using multiple threads and lacking caching. I think it is only remotely related. While a speedup would make the lags less, the issue here seems to be related to both formatting and IntelliSense competing sometimes, not the time of IntelliSense itself.

[sean-mcmanus]

This is a duplicate of #6156 -- I've updated the title to not mention "on type" formatting, since the root issue occurs for all formatting.

The formatting is stuck behind a 22 second IntelliSense update: Update IntelliSense time (sec): 22.524. The other logging is from getDocumentSymbol which is already in a separate thread. This could also be fixed by moving formatting into a separate thread from the main one that also handles potentially slow IntelliSense operations. The "getCodeAction" is also potentially an IntelliSense invoking message.