WIP: Experimental message queue

[rkeithhill]

This is still very experimental but the idea is that we spin two threads instead of one for the ProtocolEndpoint. The current impl uses one to read a JSON RPC message, process it and then read the next message. The consequence of this sequential approach is that by the time we process a $/cancelRequest we've already processed the target message.

This PR adds changes the original thread to just listen and queue JSON RPC messages to an AsyncQueue (I think @daviwil created this type). Cancel message are currently added to a pending cancel requests ConcurrentDictionary.

Another thread is created to service the Aysnc message queue. Actually, I'm experiementing with two AsyncQueue's one for "low priority" messages like codeLens, codeAction and documentSymbol. Not sure if we really need this - was trying to make sure that textDocument/completion requests got serviced more quickly. Not entirely sure I've achieved that just yet. So the dequeue/dispatch thread dequeues a message and first checks to see if there is a pending cancellation request. If there is, we send the appropriate error response for that message indicating it was cancelled. If the message does not have a cancel request pending, then we process the message normally.

Here are some things we might want to change. If the AsyncQueue had a method to remove a message (anywhere in the queue), we could process the $/cancelRequest when it's received (rather than pending it and processing when the target message is dequeued). Seems like this would be friendlier to the LSP client. Actually, we probably want to use the single dequeue/dispatch thread to write all messages to the channel. We still might want to drop the low priority queue - to simplify the implemenation and preserve message order.

Also, do we have messages we process on a bg thread? Seems like the code analysis support may happen in the background. If so, we probably want to send the "error - request cancelled" response when message processing completes and is about to send its response, in the scenario where a cancel request comes in after the message is dispatched but before it has returned a response.

[rkeithhill]

Here is some sample log output:

JsonRpcQueue.txt
JsonRpcCancelling.txt

Oh yeah, the PsesLogAnalyzer changes weren't supposed to be part of this commit. I'll continue to work on the module support for analyzing the queue.

[rkeithhill]

Hmm, need to think about this one a bit:

public async Task WriteMessage(Message messageToWrite) {
    ...
            // Make sure only one call is writing at a time.  You might be thinking
            // "Why not use a normal lock?"  We use an AsyncLock here so that the
            // message loop doesn't get blocked while waiting for I/O to complete.
            using (await this.writeLock.LockAsync())

[TylerLeonhardt]

I haven't read through the PR at all but I wanted to drop this as a data point as to another reason for this PR being critical!

For the codelens request for references we look at the file system. If we could use a Globber like Glob.cs that does lazy evaluation and cancelation... We can use a cancelationtoken when receiving a cancelRequest or another codelens request.

[rkeithhill]

Full disclosure here … this still needs work. I'm on the edge (actually over a little) WRT my async/threading chops. I'm using this AsyncQueue but it might not be the best data structure. Also, I'm seeing large delays (6-8 seconds) sometimes with textDocument/completion that I can't explain yet - still investigating.

Seems like something is blocking:

2018-12-16 19:14:16.299 [VERBOSE] tid:23 in 'WriteMessage' C:\Users\Keith\GitHub\rkeithhill\PowerShellEditorServices\src\PowerShellEditorServices.Protocol\MessageProtocol\MessageWriter.cs: line 90
    Writing Response 'textDocument/signatureHelp' with id 146
    
    {
      "jsonrpc": "2.0",
      "id": "146",
      "result": {
        "signatures": [],
        "activeSignature": 0,
        "activeParameter": null
      }
    }

… There is no activity on the dequeue/dispatch thread for 13.2 seconds

2018-12-16 19:14:29.526 [VERBOSE] tid:23 in 'WriteMessage' C:\Users\Keith\GitHub\rkeithhill\PowerShellEditorServices\src\PowerShellEditorServices.Protocol\MessageProtocol\MessageWriter.cs: line 56
    WriteMessage [13226ms]

One source of extra time is that event messages written from PSES to the client, get posted to the dequeue/dispatch thread to be written to the channel. The intent is that only thread writes to the channel which makes sense.

[rkeithhill]

Here's another message that takes a long time to dispatch/process (which has to be done before we dequeue/dispatch the next message):

2018-12-18 19:22:11.503 [VERBOSE] tid:23 in 'DequeueAndDispatchMessages' C:\Users\Keith\GitHub\rkeithhill\PowerShellEditorServices\src\PowerShellEditorServices.Protocol\MessageProtocol\ProtocolEndpoint.cs: line 560
    [JsonRpcQueue] Time to dispatch textDocument/documentSymbol id:376 seq:655 [13624ms]

Yikes, why so long to get all the document symbols?

[TylerLeonhardt]

@rkeithhill I take it that delay happens in the extension today for some folks - not introduced by your change.

[rkeithhill]

I'm pretty sure that is the case. This is the time span between writing the log message inidicating we've pulled the JSON RPC request off the queue and have dispatched it and writing the log message indicating we have written the response for that JSON RPC request.

[rkeithhill]

Rebased from the new master - that was a bit ugly but got through it.

[rkeithhill]

Rebased from master.

[TylerLeonhardt]

Sorry @rkeithhill, would you like us to take a look at this?

[rkeithhill]

Yes but not so much from a "is this ready to check in" perspective. I'm looking more for a "is this a sane approach" kind of feedback. I have a couple of concerns. One is about using the AsyncQueue that David created quite a while back. I think it is the right approach but not 100%. I'm more comfortable using async/await in GUI's - less so in servers. I also don't like that I'm currently waiting until dispatch of a queued $/cancelRequest message to actually cancel the requested message (ie never dispatch it). It is better than our current approach but I'd prefer to remove the corresponding message to be cancelled from the msg queue at the time we receive the $/cancelRequest message. I "think" that would make us a bit better of a LSP server. Finally, I'm not sure about having a "low-priority" queue. I'm not sure what the consequences are of processing LSP client messages out-of-order.

FWIW I don't think this will represent a major leap in perf. We're still processing client messages sequentially but it should reduce the message processing load some by eliminating cancelled messages before we ever start processing them. Cancelling messages currently being processed is a whole other can worms I'm not trying to tackle here. :-)

I also need to add some functionality to my PsesLogAnalyzer module to provide a suite of message queue analysis commands. That should help us visualize how the message queue is performing - queue wait times, depth, etc.

[TylerLeonhardt]

Ok so here are my thoughts:

1. Throw out AsyncQueue for the .NET ConcurrentQueue class...

2. I like the idea of having 2 queues... but I'm afraid of race conditions. Maybe we should go iterative and just do 1 queue first and go from there. @daxian-dbw @rjmholt and I have been discussing how we could separate getting completions from the main runspace (see: "it's a hard problem to solve")... if we get to that point, then having 2 queues makes me feel a bit better in terms of thread safety.

3. I don't really see a problem with processing whether something is cancelled or not til it gets popped from the queue... if we switch to ConcurrentQueue we wouldn't be able to do what you're suggesting sadly because it doesn't have a RemoveAt or something like that. I feel safer processing the items in FIFO from .NET's own implementation of a concurrent queue.

[TylerLeonhardt]

I don't think we need this anymore because of Omnisharp! :D

[rkeithhill]

Agreed.