[Do not merge] Added tracing for application startup

[tomasherceg]

I have added a simple mechanism to trace startup events and send them along with request performance traces.

I thought that the slow startup of DotVVM apps in Azure is caused by InvokeAllStaticConstructors that loads all assemblies, but it looks that the slow-down is earlier than this and that it happens in DotvvmStartup.Configure.

This PR doesn't solve the issues, it just gathers timings from the startup code in order to provide a foundation for further analysis.

The results are from Dotvvm.Samples.BasicSamples.Owin and Dotvvm.Samples.BasicSamples.AspNetCore.

• Total means the number of milliseconds since the app startup (to be precise, from the very first entry into DotVVM code).
• Duration represents the number of milliseconds since the previous event.

Local - OWIN

Event Name                                                              Duration [ms]     Total [ms]
----------------------------------------------------------------------------------------------------
AddDotvvmStarted                                                                 0 ms           0 ms
DotvvmConfigurationUserServicesRegistrationStarted                              12 ms          12 ms
DotvvmConfigurationUserServicesRegistrationFinished                              5 ms          17 ms
DotvvmConfigurationUserConfigureStarted                                         58 ms          75 ms
DotvvmConfigurationUserConfigureFinished                                       617 ms         692 ms
UseDotvvmStarted                                                                 7 ms         699 ms
UseDotvvmFinished                                                                6 ms         705 ms
InvokeAllStaticConstructorsStarted                                             325 ms        1030 ms
InvokeAllStaticConstructorsFinished                                            142 ms        1172 ms

Local - ASP.NET Core

Event Name                                                              Duration [ms]     Total [ms]
----------------------------------------------------------------------------------------------------
AddDotvvmStarted                                                                 0 ms           0 ms
DotvvmConfigurationUserServicesRegistrationStarted                              23 ms          23 ms
DotvvmConfigurationUserServicesRegistrationFinished                              3 ms          26 ms
DotvvmConfigurationUserConfigureStarted                                        202 ms         228 ms
DotvvmConfigurationUserConfigureFinished                                       431 ms         659 ms
UseDotvvmStarted                                                                 4 ms         663 ms
UseDotvvmFinished                                                               10 ms         673 ms
InvokeAllStaticConstructorsStarted                                             724 ms        1397 ms
InvokeAllStaticConstructorsFinished                                             89 ms        1486 ms

Azure App Service - OWIN

Event Name                                                              Duration [ms]     Total [ms]
----------------------------------------------------------------------------------------------------
AddDotvvmStarted                                                                 0 ms           1 ms
DotvvmConfigurationUserServicesRegistrationStarted                              48 ms          48 ms
DotvvmConfigurationUserServicesRegistrationFinished                             13 ms          61 ms
DotvvmConfigurationUserConfigureStarted                                        154 ms         215 ms
DotvvmConfigurationUserConfigureFinished                                      2830 ms        3045 ms
UseDotvvmStarted                                                                19 ms        3064 ms
UseDotvvmFinished                                                               20 ms        3084 ms
InvokeAllStaticConstructorsStarted                                            1457 ms        4541 ms
InvokeAllStaticConstructorsFinished                                           1155 ms        5696 ms

Azure App Service - ASP.NET Core

Event Name                                                              Duration [ms]     Total [ms]
----------------------------------------------------------------------------------------------------
AddDotvvmStarted                                                                 0 ms           6 ms
DotvvmConfigurationUserServicesRegistrationStarted                              46 ms          46 ms
DotvvmConfigurationUserServicesRegistrationFinished                             18 ms          64 ms
DotvvmConfigurationUserConfigureStarted                                        922 ms         986 ms
DotvvmConfigurationUserConfigureFinished                                      2067 ms        3053 ms
UseDotvvmStarted                                                                13 ms        3066 ms
UseDotvvmFinished                                                               47 ms        3113 ms
InvokeAllStaticConstructorsStarted                                            2603 ms        5716 ms
InvokeAllStaticConstructorsFinished                                            378 ms        6094 ms

[tomasherceg]

I've added a startup perf sample app that can repeatedly run iisexpress/dotnet and measures the time to first HTTP response.

On my machine, I've observed these average start times on the basic samples app:

OWIN (with DisableMarkupAssemblyDiscovery=true): 4496ms
OWIN (with DisableMarkupAssemblyDiscovery=false): 4556ms
ASP.NET Core (with DisableMarkupAssemblyDiscovery=true): 3085ms
ASP.NET Core (with DisableMarkupAssemblyDiscovery=false): 3374ms

I'll do further testing on real-world apps.

[tomasherceg]

I've updated the startup perf test console app to be a universal .NET tool for measuring startup performance of DotVVM apps.
The tool can run it multiple times and measure time to first HTTP response on a specified URL.

I've tried the performance improvements on two real-world apps (one OWIN, one ASP.NET Core). Both apps are using Entity Framework, AutoMapper, and a complex configuration of IoC/DI which add to the startup time. Still, the improvement is quite visible here.

OWIN app (EF 6.3 with complex model, AutoMapper, Castle Windsor):

with DisableMarkupAssemblyDiscovery=true:  10223ms
with DisableMarkupAssemblyDiscovery=false: 10600ms

ASP.NET Core app (EF Core with complex model, AutoMapper, Scrutor + Microsoft.Extensions.DependencyInjection): 

with DisableMarkupAssemblyDiscovery=true:  3460ms
with DisableMarkupAssemblyDiscovery=false: 3959ms

Also, the assembly handling can have impact on view compilation times - there will be fewer assemblies that would be referenced in the Roslyn compilation when assembly discovery is disabled - right now, all assemblies are in the compiled assembly cache and thus they are referenced in the view compilation.

When this is merged in master and combined with #841, we'll see whether the view compilation got faster thanks to the lower number of assemblies DotVVM is dealing with.

[tomasherceg]

There is still one issue that needs to be addressed - if the user forgets to register an assembly with controls manually, there is no error message, and the application breaks on some places - some DotVVM properties will not get registered and DotVVM will try to treat them as "virtual" properties. This is quite unfortunate and I am not sure where exactly to place the check whether the assembly is registered or not.

Also, we need to add the following registrations to our commercial packages:

Bootstrap for DotVVM (both versions)

config.Markup.AddAssembly("DotVVM.Framework.Controls.Bootstrap");

DotVVM Business Pack

config.Markup.AddAssembly("DotVVM.Utils.HtmlElements");
config.Markup.AddAssembly("DotVVM.BusinessPack.Core");
config.Markup.AddAssembly("DotVVM.BusinessPack");

DotVVM Dynamic Data

config.Markup.Assemblies.Add("DotVVM.Framework.Controls.DynamicData");
config.Markup.Assemblies.Add("DotVVM.Framework.Controls.DynamicData.Annotations");

There are also other packages which may need this: Contrib, MiniProfiler, AppInsights, Status Page...