Create a Visual Studio Extension with minimal impact on VS startup performance
The good news: It’s very easy to create an extension in Visual Studio.
The bad news: It’s also easy to make that extension have an adverse effect on the start time of Visual Studio.
Let’s examine how we can mitigate the impact on Visual Studio performance.
Make sure your VS Installation has installed Extensibility by using the Installer tool
Something like: "C:\Program Files (x86)\Microsoft Visual Studio\Installer\vs_installer.exe"
Ensure that “Visual Studio extension development” is installed.
Then start VS,
File->New Project->Extensibility->VSIX Project
I called mine “VSIXTest”. A Getting Started page shows with instructions on how to add extensibility items to your project, like ToolWindows, Margins, etc.
I chose to add a new Custom Tool Window and called it MyToolWindow.cs
At this point, hit F5 to Start an experimental instance of VS with your code installed. Click the menu item Tools->Other Windows-> “MyToolWindow” to see your fancy toolWindow. You can move it around and dock it like any other tool window.
If you now shut down the experimental instance of VS (saving the window layout), hit F5 again, VS will restore “MyToolWindow”at startup, which means it runs your initialization code before allowing the user to interact with Visual Studio.
Now you’ll notice in solution explorer that your ToolWindow code lives in a Package that was created for you: “MyToolWindowPackage.cs”
In that file, let’s paste some logging code:
private static DateTime? _startLogging;
public static void LogMessage(string msg)
{
if (!_startLogging.HasValue)
{
_startLogging = DateTime.Now;
}
var elapsed = DateTime.Now - _startLogging.Value;
var txt = DateTime.Now.ToString("hh:mm:ss") + $" {elapsed.TotalMilliseconds,8:n1} MyExtensionLog {System.Threading.Thread.CurrentThread.ManagedThreadId,3} {msg}";
Debug.WriteLine(txt);
}
call that code from various places to get a log of events and their timing: put one in the MyToolWindowPackage.Initialize()
LogMessage(nameof(Initialize));
And in the MyToolWindow constructor:
MyToolWindowPackage.LogMessage(nameof(MyToolWindow));
When you hit F5 this time, you’ll get some simple logging in the Debug->Output Window
06:07:35 0.0 MyExtensionLog 1 Initialize
06:07:35 4.0 MyExtensionLog 1 MyToolWindow
The log shows time and elapsed time for each message. The thread shows “1” which means its running on the UI or main thread.
There’s a lot of other unrelated stuff showing in the output window, but it’s easy to filter to our output: Shift-Ctrl-F (Find In Files), search for “MyExtensionLog” change the “Look In” to “Current Window” and click “Find All”. The search results show the line number at the beginning of each line in parentheses along with the log message
Now imagine that the ToolWindow needs to do a lot of expensive initialization work: in MyToolWindow class add this method to simulate the work with a Sleep:
private void DoToolWindowInitWorkThatCanBeDeferred(int SecondsDeferredWork)
{
MyToolWindowPackage.LogMessage($"Starting {nameof(DoToolWindowInitWorkThatCanBeDeferred)} with {SecondsDeferredWork} {nameof(SecondsDeferredWork)}");
Thread.Sleep((int)TimeSpan.FromSeconds(SecondsDeferredWork).TotalMilliseconds);
MyToolWindowPackage.LogMessage($"deferred work done");
}
That hard work is just sleeping for N seconds, but it includes some logging. Call it from the MyToolWindow constructor with a 10 second parameter.
Find all "MyExtensionLog", Find Results 1, Current Document
(2):02:03:47 0.0 MyExtensionLog 1 Initialize
(3):02:03:47 3.0 MyExtensionLog 1 MyToolWindow
(4):02:03:47 5.0 MyExtensionLog 1 Starting DoToolWindowInitWorkThatCanBeDeferred with 10 SecondsDeferredWork
(16):02:03:57 10,010.6 MyExtensionLog 1 deferred work done
Now we can see the 10 second delay in the log, with all work on the main thread.
VS will now appear unresponsive and VS startup has been delayed by 10 seconds, causing unhappy users.
How do we fix that? (hint: why did we add Thread ID to the log?)
In the ToolWindow Constructor, call a method called “doInitialize” which looks like this:
async private void doInitialize()
{
var idleTask = ThreadHelper.JoinableTaskFactory.StartOnIdle(
async () =>
{
MyToolWindowPackage.LogMessage($"JTF StartOnIdle");
await Task.Run(() =>
{
MyToolWindowPackage.LogMessage($"StartOnIdle Task running");
DoToolWindowInitWorkThatCanBeDeferred(10);
});
MyToolWindowPackage.LogMessage($"End of JTF StartOnIdle");
}
);
MyToolWindowPackage.LogMessage($"End of {nameof(doInitialize)}");
}
We have an asynchronous lambda that will run some code on a background thread after VS has reached Idle (after much of startup has occurred).
(2):02:07:33 0.0 MyExtensionLog 1 Initialize
(3):02:07:33 3.0 MyExtensionLog 1 MyToolWindow
(4):02:07:33 6.0 MyExtensionLog 1 End of doInitialize
(14):02:07:34 1,642.0 MyExtensionLog 1 JTF StartOnIdle
(15):02:07:34 1,646.1 MyExtensionLog 21 StartOnIdle Task running
(16):02:07:34 1,683.1 MyExtensionLog 21 Starting DoToolWindowInitWorkThatCanBeDeferred with 10 SecondsDeferredWork
(64):02:07:44 11,726.9 MyExtensionLog 21 deferred work done
(65):02:07:44 11,727.9 MyExtensionLog 1 End of JTF StartOnIdle
Voila! VS reaches idle in 1.6 seconds and is responsive before the deferred “work” is done (and the deferred work finishes after the user can do other tasks with Visual Studio.
What if every extension waited until idle? It’s not hard to extend this using ContinueWith tasks to run something N seconds after idle. Note how it can run code on the main thread too.
async private void doInitialize()
{
var idleTask = ThreadHelper.JoinableTaskFactory.StartOnIdle(
async () =>
{
MyToolWindowPackage.LogMessage($"JTF StartOnIdle");
await Task.Run(() =>
{
MyToolWindowPackage.LogMessage($"StartOnIdle Task running");
DoToolWindowInitWorkThatCanBeDeferred(10);
});
MyToolWindowPackage.LogMessage($"End of JTF StartOnIdle");
}
);
MyToolWindowPackage.LogMessage($"Adding ContinueWith");
await idleTask.Task.ContinueWith((priorTask) =>
{
MyToolWindowPackage.LogMessage($"ContinueWith");
Thread.Sleep(TimeSpan.FromSeconds(15)); // sleep 15 seconds after idle on bgd thread
},
TaskContinuationOptions.OnlyOnRanToCompletion //run continued task only if prior task completed successfully
).ContinueWith(async (priorTask) =>
{
MyToolWindowPackage.LogMessage($"2nd ContinueWith: 15 seconds after VS idle after start");
// note that the user could have closed VS by this time.
DoToolWindowInitWorkThatCanBeDeferred(30);
await ThreadHelper.JoinableTaskFactory.SwitchToMainThreadAsync();
// if we're on the main thread, break up the task to run and Yield often
//await Task.Yield();
MyToolWindowPackage.LogMessage($"2nd ContinueWith: now running on main thread");
},
TaskContinuationOptions.OnlyOnRanToCompletion //run continued task only if prior task completed successfully
);
MyToolWindowPackage.LogMessage($"End of {nameof(doInitialize)}");
}
(2):02:14:04 0.0 MyExtensionLog 1 Initialize
(3):02:14:04 3.0 MyExtensionLog 1 MyToolWindow
(4):02:14:04 7.0 MyExtensionLog 1 Adding ContinueWith
(14):02:14:05 1,606.1 MyExtensionLog 1 JTF StartOnIdle
(15):02:14:05 1,632.1 MyExtensionLog 23 StartOnIdle Task running
(16):02:14:05 1,634.1 MyExtensionLog 23 Starting DoToolWindowInitWorkThatCanBeDeferred with 10 SecondsDeferredWork
(64):02:14:15 11,662.3 MyExtensionLog 23 deferred work done
(65):02:14:15 11,663.3 MyExtensionLog 1 End of JTF StartOnIdle
(66):02:14:15 11,664.3 MyExtensionLog 23 ContinueWith
(67):02:14:30 26,668.5 MyExtensionLog 8 2nd ContinueWith: 15 seconds after VS idle after start
(68):02:14:30 26,669.4 MyExtensionLog 8 Starting DoToolWindowInitWorkThatCanBeDeferred with 30 SecondsDeferredWork
(69):02:15:00 56,671.9 MyExtensionLog 8 deferred work done
(70):02:15:00 56,673.9 MyExtensionLog 1 2nd ContinueWith: now running on main thread
(71):02:15:00 56,674.9 MyExtensionLog 1 End of doInitialize
It’s not difficult to schedule work after VS starts, and that the work can be on a background thread or the main thread. To make users happy, minimize the work on the main thread so the UI is more responsive.
Note that there are many options to determine if Tasks should run or Continue, and that authors should understand that Tasks might not complete successfully and can be cancelled.
Also, if you have a task that runs on the main thread for > 200 msecs, and you delay it til after Idle, then the user could be typing into the editor or moving the mouse and experiencing slow or blocking performance. You can break the work into smaller pieces and Yield after each.
Note an equivalent alternative to wait for Idle using VsTaskLibraryHelper:
await VsTaskLibraryHelper.CreateAndStartTask(
VsTaskLibraryHelper.ServiceInstance,
VsTaskRunContext.UIThreadIdlePriority,
() =>
{
// this code is run after Idle
MyToolWindowPackage.LogMessage($"IdleTask Fired");
}
);
Also note that you can change your Package to derive from the AsyncPackage class for further improvements
See also:
/en-us/visualstudio/extensibility/how-to-diagnose-extension-performance
https://github.com/Microsoft/vs-threading/blob/master/doc/cookbook_vs.md