Why are server requests sent delayed?

[squidfunk]

I'm developing a VS Code extension and the experience so far has been tremendous!

I want my language server to be as fast as possible, which already works well for the textDocument/didChange and textDocument/publishDiagnostics notification roundtrip. However, VS Code seems to wait for 300ms (?) after the document change notification until it asks the language server for other providers, like for example textDocument/documentSymbol and textDocument/documentColor.

Trace captured with ngrep when run via TCP transport

T 2021/10/19 16:17:06.122088 127.0.0.1:8460 -> 127.0.0.1:53585 [AP] #105
  Content-Length: 278....                                                                                                                                                                 
##
T 2021/10/19 16:17:06.122415 127.0.0.1:8460 -> 127.0.0.1:53585 [AP] #107
  {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///Users/squidfunk/Desktop/css-test/small.css","version":143},"contentChanges":[{"range":{"star
  t":{"line":10,"character":36},"end":{"line":10,"character":36}},"rangeLength":0,"text":"0"}]}}                                                                                          
##
T 2021/10/19 16:17:06.125139 127.0.0.1:53585 -> 127.0.0.1:8460 [AP] #109
  Content-Length: 147....                                                                                                                                                                 
##
T 2021/10/19 16:17:06.125215 127.0.0.1:53585 -> 127.0.0.1:8460 [AP] #111
  {"jsonrpc":"2.0","method":"textDocument/publishDiagnostics","params":{"uri":"file:///Users/squidfunk/Desktop/css-test/small.css","diagnostics":[]}}                                     
##
T 2021/10/19 16:17:06.461254 127.0.0.1:8460 -> 127.0.0.1:53585 [AP] #113
  Content-Length: 151....                                                                                                                                                                 
##
T 2021/10/19 16:17:06.461386 127.0.0.1:8460 -> 127.0.0.1:53585 [AP] #115
  {"jsonrpc":"2.0","id":18,"method":"textDocument/documentSymbol","params":{"textDocument":{"uri":"file:///Users/squidfunk/Desktop/css-test/small.css"}}}                                 
##
T 2021/10/19 16:17:06.462931 127.0.0.1:53585 -> 127.0.0.1:8460 [AP] #117
  Content-Length: 1888....                                                                                                                                                                
##
T 2021/10/19 16:17:06.462988 127.0.0.1:53585 -> 127.0.0.1:8460 [AP] #119
  {"jsonrpc":"2.0","id":18,"result":[{"kind":5,"name":"div","range":{"start":{"line":0,"character":0},"end":{"line":5,"character":1}},"selectionRange":{"start":{"line":0,"character":0},"
  end":{"line":0,"character":4}},"children":[{"kind":13,"name":"--foo","range":{"start":{"line":3,"character":2},"end":{"line":3,"character":12}},"selectionRange":{"start":{"line":3,"cha
  racter":2},"end":{"line":3,"character":12}}}]},{"kind":11,"name":"@media screen and (min-width: 320px)","range":{"start":{"line":7,"character":0},"end":{"line":24,"character":1}},"sele
  ctionRange":{"start":{"line":7,"character":6},"end":{"line":7,"character":37}},"children":[{"kind":5,"name":"div","range":{"start":{"line":8,"character":2},"end":{"line":12,"character"
  :3}},"selectionRange":{"start":{"line":8,"character":2},"end":{"line":8,"character":6}},"children":[]},{"kind":11,"name":"@media screen","range":{"start":{"line":14,"character":2},"end
  ":{"line":21,"character":3}},"selectionRange":{"start":{"line":14,"character":8},"end":{"line":14,"character":16}},"children":[{"kind":11,"name":"@media print","range":{"start":{"line"
  :15,"character":4},"end":{"line":20,"character":5}},"selectionRange":{"start":{"line":15,"character":10},"end":{"line":15,"character":17}},"children":[{"kind":5,"name":".bar","range":{
  "start":{"line":16,"character":6},"end":{"line":16,"character":13}},"selectionRange":{"start":{"line":16,"character":6},"end":{"line":16,"character":11}},"children":[]},{"kind":11,"nam
  e":"@supports (display: grid)","range":{"start":{"line":17,"character":6},"end":{"line":19,"character":7}},"selectionRange":{"start":{"line":17,"character":15},"end":{"line":17,"charac
  ter":32}},"children":[]}]}]},{"kind":5,"name":".foo","range":{"start":{"line":23,"character":2},"end":{"line":23,"character":9}},"selectionRange":{"start":{"line":23,"character":2},"en
  d":{"line":23,"character":7}},"children":[]}]}]}                                                                                                                                        
##
T 2021/10/19 16:17:07.111888 127.0.0.1:8460 -> 127.0.0.1:53585 [AP] #121
  Content-Length: 150....                                                                                                                                                                 
##
T 2021/10/19 16:17:07.112014 127.0.0.1:8460 -> 127.0.0.1:53585 [AP] #123
  {"jsonrpc":"2.0","id":19,"method":"textDocument/documentColor","params":{"textDocument":{"uri":"file:///Users/squidfunk/Desktop/css-test/small.css"}}}                                  
##
T 2021/10/19 16:17:07.112828 127.0.0.1:53585 -> 127.0.0.1:8460 [AP] #125
  Content-Length: 167....                                                                                                                                                                 
##
T 2021/10/19 16:17:07.112914 127.0.0.1:53585 -> 127.0.0.1:8460 [AP] #127
  {"jsonrpc":"2.0","id":19,"result":[{"color":{"red":255,"green":0,"blue":100,"alpha":1},"range":{"start":{"line":10,"character":22},"end":{"line":10,"character":38}}}]}            

As can be seen from the trace, my language server responds within the order of milliseconds:

textDocument/didChange
  T 2021/10/19 16:17:06.122088 – Content length
  T 2021/10/19 16:17:06.122415 – Content

textDocument/publishDiagnostics
  T 2021/10/19 16:17:06.125139 – Content length
  T 2021/10/19 16:17:06.125215 – Content

However, VS Code will wait for more than 300ms before invoking the other providers, which becomes very noticable:

textDocument/documentSymbol
  T 2021/10/19 16:17:06.461254 – Content length
  T 2021/10/19 16:17:06.461386 – Content
  Response
    T 2021/10/19 16:17:06.462931 – Content length
    T 2021/10/19 16:17:06.462988 – Content

textDocument/documentColor
  T 2021/10/19 16:17:07.111888 – Content length
  T 2021/10/19 16:17:07.112014 – Content
  Response
    T 2021/10/19 16:17:07.112828 – Content length
    T 2021/10/19 16:17:07.112914 – Content

My question is why does VS Code wait for so long? Can this interval be reduced via a language client, language server option, or setting? I would really like to mitigate this behavior because this delay renders the otherwise instantaneous experience rather slugish.

[rcjsuen]

My question is why does VS Code wait for so long?

@squidfunk Can you reproduce this slowness using a pure VS Code extension?

[squidfunk]

I dug into the code base of VS Code and think I've found traces of the issue, e.g. in outlineModel.ts:

new LanguageFeatureRequestDelays(DocumentSymbolProviderRegistry, 350);

A search for this class yields:
https://github.com/microsoft/vscode/search?q=LanguageFeatureRequestDelays

[squidfunk]

@rcjsuen sorry, saw your comment too late. Yes, the issue reproduces consistently with the simplest extension, which just answers the textDocument/documentSymbol request. It's always 350ms or more, which I think is related to the LanguageFeatureRequestDelays I just posted. I also tested a clean VS Code installation without any other third-party extensions with the same result.

[rcjsuen]

Yes, the issue reproduces consistently with the simplest extension, which just answers the textDocument/documentSymbol request. It's always 350ms or more, which I think is related to the LanguageFeatureRequestDelays I just posted. I also tested a clean VS Code installation without any other third-party extensions with the same result.

@squidfunk Looks like the delay is for debounce purposes? Perhaps they do not want an extension to cause the UI to redraw too much?

If you can reproduce it with a vanilla Visual Studio Code extension without any language servers then you may want to open an issue in the microsoft/vscode repository instead.

[squidfunk]

Yes, I agree, after isolating the issue, it's better suited to be reported on the Visual Studio Code repository.

If it's for debounce purposes, I don't understand why textDocument/documentSymbol is denounced, whereas textDocument/documentHover and others are not, as both need a language model.