Avoid the blocking wait operation in RestoreOperationLogger #1588

sharwell · 2017-07-28T20:47:32Z

The approach used here is the more important of a two-part true solution. The natural solution would be using ILogger.LogAsync instead of the various synchronous calls currently in place. However, I realized that while such a solution would address the thread pool starvation problems, it still leaves NuGet susceptible to not making progress whenever the UI thread is blocked. The change here instead decouples the UI thread logging operations from the ongoing background work, but takes care to ensure that when the messages finally do appear, they appear in the same order they otherwise would have.

Messages are queued in order of calls made to log methods
For each logged message, a UI thread operation is started which will print one UI thread message

Since the code makes no effort to ensure that the operations started by 2 actually execute in the same order as the messages in 1, all information necessary for printing the message on the UI thread must be held in the queue.

Fixes NuGet/Home#5663

⚠️ I have not yet run tests. I'm waiting to see the results of the CI build for this.

⚠️ Do not rebase or squash this pull request on merge.

Fixes NuGet/Home#5663

dnfclas · 2017-07-28T20:47:36Z

@sharwell,
Thanks for having already signed the Contribution License Agreement. Your agreement was validated by .NET Foundation. We will now review your pull request.
Thanks,
.NET Foundation Pull Request Bot

sharwell · 2017-07-28T21:00:42Z

💭 The CI infrastructure seems to be down, as it hasn't picked up this PR for 15 minutes now.

nkolev92 · 2017-07-29T01:37:49Z

@sharwell
Unfortunately our CI will only run branches from the NuGet.Client repo.
It does not have the capability to run tests from forks yet.
I will kick them off manually.

Update:
Kicked it off...main build link https://devdiv.visualstudio.com/DevDiv/NuGet/_build/index?buildId=893145

sharwell · 2017-07-29T17:14:13Z

Unfortunately our CI will only run branches from the NuGet.Client repo.

This explains why I had 149 random branches to delete when I forked the repository. 😄

emgarten · 2017-07-30T21:32:32Z

Thanks for the PR @sharwell!

I made an attempt at avoiding blocking the UI using a pumping logger on another thread and a blocking collection to hold message, similar to the other option you mention in the issue. This change looks much simpler which I like.

Concerns

Is it guaranteed that after getting a message from the queue that it will be logged before another thread enters and dequeues the next message along with logging it?
Does this need throttling? Potentially a lot of strings could flood in before they can be written out. Filtering before hand helps, but if the logger were set to diag it could really add up.
It looks like restore could end before all logging is complete, I think the tasks need to be awaited on to avoid this. Otherwise when another restore starts the output may be cleared, and then messages from an old restore could show up along with messages from the current restore.

Last time this was investigated perf was improved by using different APIs for logging to VS, and by filtering out the messages earlier on log level. From your stats it looks like this change is needed to avoid blocking.

davidfowl · 2017-07-30T23:03:13Z

src/NuGet.Clients/NuGet.SolutionRestoreManager/RestoreOperationLogger.cs

 // Run on the UI thread
- Do((_, progress) =>
+ var ignored = DoAsync((_, progress) =>


nit: _ = instead ignored

➡️ This is a candidate feature for a future version of C# (dotnet/csharplang#111), but currently isn't available.

It is for the return value.

There is already a parameter named _ on the same line 😉

davidfowl · 2017-07-30T23:04:16Z

src/NuGet.Clients/NuGet.SolutionRestoreManager/RestoreOperationLogger.cs

@@ -145,10 +149,20 @@ public override void Log(ILogMessage logMessage)
 // Avoid moving to the UI thread unless there is work to do
 if (reportProgress || showAsOutputMessage)
 {
+ // Make sure the message is queued in order of calls to LogAsync, but don't wait for the UI thread
+ // to actually show it.
+ _loggedMessages.Enqueue(Tuple.Create(reportProgress, showAsOutputMessage, logMessage));


Why not use the tuple syntax?

The tuple syntax would be very much preferable, but I wasn't sure if this project was using it yet.

➡️ Currently System.ValueTuple is not available for use in this project.

Create a private struct with the two fields?

@benaadams I predict that in the near future someone will finally add System.ValueTuple to this project and go through the code searching for Tuple.Create. The currently implementation works well with such a transition. It's also part of the reason why I created the field's comment in the form I did.

davidfowl · 2017-07-30T23:04:39Z

src/NuGet.Clients/NuGet.SolutionRestoreManager/RestoreOperationLogger.cs

- }
- }
-
+ Log(logMessage);
 return Task.FromResult(0);


Avoid allocating the task every time by returning a cached one.

This is an extremely common pattern in the current code base

It didn't show up as a dominant contributor in recent profiling

➡️ Based on this, I decided to treat this as a code cleanup issue which can wait for a future commit dedicated to this effort.

sharwell · 2017-07-31T11:41:44Z

Is it guaranteed that after getting a message from the queue that it will be logged before another thread enters and dequeues the next message along with logging it?

The dequeue occurs on the UI thread, so printing is guaranteed to occur in the same order as the messages end up in the queue.

Does this need throttling? Potentially a lot of strings could flood in before they can be written out. Filtering before hand helps, but if the logger were set to diag it could really add up.

It is unlikely this needs throttling.

At the default severity there are "not that many" strings
As long as the UI thread is responsive, for all practical purposes it has no trouble keeping up
The code already employs filtering prior to the queue to reduce the load required on the UI thread

It looks like restore could end before all logging is complete, I think the tasks need to be awaited on to avoid this. Otherwise when another restore starts the output may be cleared, and then messages from an old restore could show up along with messages from the current restore.

In my original work on this issue, I investigated transitioning to await so the same underlying display behavior occurs while unblocking the threads in the thread pool. However, I realized that even though this fixed the thread pool, the restore operation time itself would not benefit at all.

We're gaining a very real benefit by ensuring the progress of the background operation is not dependent on the responsiveness of the UI thread. As mentioned above, it's unlikely this will be a problem (the user can only observe the case if the UI responds, and the delay is only pronounced if the UI does not respond). If we do encounter cases that meet the described clearing scenario (for me the window is never automatically cleared), we can simply move the clear command into the queue to ensure it executes at an appropriate time.

alpaix · 2017-08-01T01:34:35Z

I don't understand why queue is needed if every call creates "abandoned" task. Alternatively the same effect would be achieved by simply replacing Do by DoAsync. Am I missing something?

alpaix

Blocking for now to clarify the design.

sharwell · 2017-08-01T04:19:58Z

I don't understand why queue is needed if every call creates "abandoned" task.

I wasn't sure that we could depend on this line getting executed prior to DoAsync returning (when the result is not awaited). In other words, we can only count on the execution queue of the UI thread for maintaining the order if we are sure that the call gets placed in that queue prior to Log returning. The queue in this pull request provides a guarantee regarding the order that doesn't depend on the implementation details of JoinableTaskFactory. I would not be opposed to changing it (and just allowing the UI dispatcher to queue things) under either of the following conditions:

JoinableTaskFactory and DoAsync provide sufficient guarantee that the operation will either the UI thread queue before the async method yields.
The possibilities of out-of-order execution in the absence of guarantees from the former are not considered problematic.

alpaix · 2017-08-01T16:35:03Z

@AArnott Is there a better way to facilitate JoinableTaskCollection to efficiently demux log writes on UI thread without blocking background tasks?

alpaix · 2017-08-07T16:22:01Z

@sharwell My biggest concern here is scheduling abundance of ignored tasks as it may potentially cause reliability issues. For instance, consider a scenario when a user wants to shut the VS instance down while it's still printing hundreds of messages. I suggest keeping all of these tasks in a JoinableTaskCollection and joining them all before printing summary message at the end.

AArnott · 2017-08-07T20:04:11Z

@alpaix Yes, it's certainly possible to do this without blocking any thread. Except in the shutdown case, where the whole point is to be able to block the UI thread until the async work has been completed (or canceled) so that you don't tear down the AppDomain while code is still running in it.

AArnott · 2017-08-07T20:07:18Z

@sharwell The JoinableTaskFactory provides no ordering guarantees, in general. If multiple folks want the UI thread, any number of factors can influence which one gets it first. If you're already on the UI thread and you ask for it via SwitchToMainThreadAsync(), it's a no-op and you just keep it.

There are things you can do to set priority for your UI thread request, based on VS-proprietary priority levels or Dispatcher priorities.

emgarten · 2017-08-30T22:43:26Z

Closing, this was merged with #1638

Avoid the blocking wait operation in RestoreOperationLogger

3bdb761

Fixes NuGet/Home#5663

dnfclas added the cla-already-signed label Jul 28, 2017

davidfowl reviewed Jul 30, 2017

View reviewed changes

alpaix suggested changes Aug 1, 2017

View reviewed changes

alpaix mentioned this pull request Aug 11, 2017

Avoid the blocking wait operation in RestoreOperationLogger - 2 #1638

Merged

emgarten closed this Aug 30, 2017

sharwell deleted the no-blocking-wait branch August 31, 2017 13:34

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Avoid the blocking wait operation in RestoreOperationLogger #1588

Avoid the blocking wait operation in RestoreOperationLogger #1588

sharwell commented Jul 28, 2017 •

edited

Loading

dnfclas commented Jul 28, 2017

sharwell commented Jul 28, 2017

nkolev92 commented Jul 29, 2017 •

edited

Loading

sharwell commented Jul 29, 2017

emgarten commented Jul 30, 2017

davidfowl Jul 30, 2017

sharwell Jul 31, 2017

davidfowl Jul 31, 2017

sharwell Jul 31, 2017

davidfowl Jul 30, 2017

sharwell Jul 31, 2017

sharwell Jul 31, 2017

benaadams Jul 31, 2017

sharwell Aug 1, 2017 •

edited

Loading

davidfowl Jul 30, 2017

sharwell Jul 31, 2017 •

edited

Loading

sharwell commented Jul 31, 2017

alpaix commented Aug 1, 2017

alpaix left a comment

sharwell commented Aug 1, 2017

alpaix commented Aug 1, 2017

alpaix commented Aug 7, 2017

AArnott commented Aug 7, 2017

AArnott commented Aug 7, 2017 •

edited

Loading

emgarten commented Aug 30, 2017

Avoid the blocking wait operation in RestoreOperationLogger #1588

Avoid the blocking wait operation in RestoreOperationLogger #1588

Conversation

sharwell commented Jul 28, 2017 • edited Loading

dnfclas commented Jul 28, 2017

sharwell commented Jul 28, 2017

nkolev92 commented Jul 29, 2017 • edited Loading

sharwell commented Jul 29, 2017

emgarten commented Jul 30, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

sharwell Aug 1, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

sharwell Jul 31, 2017 • edited Loading

Choose a reason for hiding this comment

sharwell commented Jul 31, 2017

alpaix commented Aug 1, 2017

alpaix left a comment

Choose a reason for hiding this comment

sharwell commented Aug 1, 2017

alpaix commented Aug 1, 2017

alpaix commented Aug 7, 2017

AArnott commented Aug 7, 2017

AArnott commented Aug 7, 2017 • edited Loading

emgarten commented Aug 30, 2017

sharwell commented Jul 28, 2017 •

edited

Loading

nkolev92 commented Jul 29, 2017 •

edited

Loading

sharwell Aug 1, 2017 •

edited

Loading

sharwell Jul 31, 2017 •

edited

Loading

AArnott commented Aug 7, 2017 •

edited

Loading