What happens between Application.Run and Form.Load?

Question

I have a WinForms application written in VB.NET for Framework 4.5. I noticed that the startup time of the application is unusually long (other applications I have written that are doing even more work on startup start nearly instantly, this application needs >5 seconds) The startup time does not change after multiple starts, so I guess it is not a case of uncached CLR code during the first start of the application.

I did some testing by writing down times during startup:

Module modMain
    Public MyLog As System.Text.StringBuilder

    <STAThread>
    Public Sub Main()
        MyLog = New System.Text.StringBuilder

        Application.EnableVisualStyles()
        Application.SetCompatibleTextRenderingDefault(False)
        MyLog.AppendLine("Before run: " & Date.Now.ToString & "," & Date.Now.Millisecond.ToString)
        Application.Run(frmMain)
    End Sub
End Module

Sub Main() is the applications entry point. It runs frmMain, and there the first real thing I have control over is Sub InitializeComponent(), generated by the designer:

<System.Diagnostics.DebuggerStepThrough()> _
Private Sub InitializeComponent()
    MyLog.AppendLine("Init Start: " & Date.Now.ToString & "," & Date.Now.Millisecond.ToString)
    'All the control initializations
    MyLog.AppendLine("Init End: " & Date.Now.ToString & "," & Date.Now.Millisecond.ToString)
End Sub

And finally I arrive at the Form.Load event

Private Sub frmMain_Load(sender As Object, e As EventArgs) Handles MyBase.Load
    MyLog.AppendLine("Form_Load Start: " & Date.Now.ToString & "," & Date.Now.Millisecond.ToString)
    '...
    MyLog.AppendLine("Form_Load End: " & Date.Now.ToString & "," & Date.Now.Millisecond.ToString)
End Sub

Now, the output of MyLog is as follows:

Before run: 15.12.2014 19:56:47,579
Init Start: 15.12.2014 19:56:51,451
Init End: 15.12.2014 19:56:51,521
Form_Load Start: 15.12.2014 19:56:51,544
Form_Load End: 15.12.2014 19:56:51,547

You can see, that the main pause occurs between Application.Run() and Sub InitializeComponent(). I know from other questions, that there a message loop is started for the GUI thread, but I don't know why it should be so much slower for this application than for other applications.

So my question is: What exactly happens between Application.Run and the point I regain control over my code, and can I do something to speed it up? Is the work done there in any way related to the components on the form?

I already tried using frmMain.ShowDialog() instead of Application.Run(frmMain), but this led to the same results. I am using Visual Studio Express, so unfortunately I can't use a more in depth performance profiler.

Tagging this as both C# and VB.NET, because answers in both languages are very welcome.

EDIT
I have done some more tests, including the proposed solution in SLaks answer. Using NGEN to precompile the assembly did not seem to have any noticable effect. So I guess it is not the JIT compilation of the InitializeComponent code.

I however noticed, that on other systems the program started practically instantaneously (>10 times faster), even if the computer in question was slower in all respects. The difference between the computers was the operating system:

Windows 7: Slow start
Windows 8.1: Fast start
Windows Server 2008: Fast start

These are just more clues, I don't really know if it is helpful for an answer.

EDIT 2
Looking at ProcMon during startup I find that the execution hangs at the following lines:

"15:56:29.3547260","Electrochemical Calculator.exe","5972","CreateFile","C:\Users\Jens\Desktop\Electrochemical Calculator Barebone\Electrochemical Calculator\bin\Release\de\Electrochemical Calculator.resources.dll","PATH NOT FOUND","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a"
"15:56:29.3548019","Electrochemical Calculator.exe","5972","CreateFile","C:\Users\Jens\Desktop\Electrochemical Calculator Barebone\Electrochemical Calculator\bin\Release\de\Electrochemical Calculator.resources\Electrochemical Calculator.resources.dll","PATH NOT FOUND","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a"
"15:56:29.3548612","Electrochemical Calculator.exe","5972","CreateFile","C:\Users\Jens\Desktop\Electrochemical Calculator Barebone\Electrochemical Calculator\bin\Release\de\Electrochemical Calculator.resources.exe","PATH NOT FOUND","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a"
"15:56:29.3549519","Electrochemical Calculator.exe","5972","CreateFile","C:\Users\Jens\Desktop\Electrochemical Calculator Barebone\Electrochemical Calculator\bin\Release\de\Electrochemical Calculator.resources\Electrochemical Calculator.resources.exe","PATH NOT FOUND","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a"
"15:56:32.8796760","Electrochemical Calculator.exe","5972","CreateFile","C:\Windows\Fonts\StaticCache.dat","SUCCESS","Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: n/a, ShareMode: Read, Delete, AllocationSize: n/a, OpenResult: Opened"
"15:56:32.8797088","Electrochemical Calculator.exe","5972","QueryStandardInformationFile","C:\Windows\Fonts\StaticCache.dat","SUCCESS","AllocationSize: 9,633,792, EndOfFile: 9,633,792, NumberOfLinks: 1, DeletePending: False, Directory: False"
"15:56:32.8797218","Electrochemical Calculator.exe","5972","ReadFile","C:\Windows\Fonts\StaticCache.dat","SUCCESS","Offset: 0, Length: 60, Priority: Normal"
"15:56:32.8797429","Electrochemical Calculator.exe","5972","CreateFileMapping","C:\Windows\Fonts\StaticCache.dat","FILE LOCKED WITH ONLY READERS","SyncType: SyncTypeCreateSection, PageProtection: "

The problem further occurs only in a Release build, and only when I start the program directly from the Windows Explorer. A debug build launches instantly (0.3 seconds, compared to 5-10 seconds), as does a Release build when started from Visual Studio.

Answer 1

This time is spent loading every assembly used by your form's controls, and JITting the InitializeComponent method.

Answer 2

Well, you eliminated all the normal sources of startup delays. It most definitely doesn't have anything to do with Application.Run(), that doesn't start until after the form's InitializeComponent() method finishes running. And you eliminated jitting overhead by using Ngen.exe. Be sure to distinguish between cold and warm start delays, if it is only slow the first time you start the program then it is a hardware problem, you need a faster disk. The fact that it is only slow on some machines strongly points to an environmental problem.

Triggered by the code that runs in InitializeComponent(). In other words, all the constructors and property setters of the controls on your form. That normally takes very little time, but there are certainly trouble-makers around. You need to look for a non-trivial control, particularly the kind that uses COM (aka ActiveX) under the hood. Like WebBrowser. There are many more possibilities, anything whose class name starts with "Ax". Such controls can load a lot of other DLLs and are apt to be interesting to security software.

Some debugging tips:

• Ensure you have a good backup and start deleting controls from the form, starting with the non-trivial ones.
• A 5 second delay is long enough to notice while single-stepping through the InitializeComponent() method. Instantly tells you which particular control and statement causes the delay.
• Switching the debugger to unmanaged mode tells you a lot more about what other DLLs get loaded into your program. Project + Properties, Debug tab, tick the "Enable native code debugging" option. Keep an eye on the Output window while you debug, you'll see load notifications for any unmanaged DLL getting loaded. That can pin-point the particular DLL that causes the delay.
• When possible, disable anti-malware so you can eliminate delays due to inappropriate DLL scans.
• The SysInternals' TcpView utility is a excellent to detect networking delays. Be wary when you see your program contacting a CRL server, Certificate Revocation List queries can be slow.
• The SysInternals' Process Monitor utility is excellent to see delays due to most anything else. The trace can be very large, save it and post it on a file sharing site if you need another set of eyes on it.

Answer 3

Like Hans said, you have already eliminated obvious, and to me, the issue seems to be environmental... so how do you troubleshoot in this given the extreme conditions...

Since the process consistently takes 5 or more seconds (when launched from explorer), here's are some of the approaches I would think of taking in this situation -

Note - Since there is a potential for timing issue, you may have to repeat the experiment a few number of times to get decent results. It is obviously, still hard for me to guarantee the results... If I was personally doing it, I would hope to improvise if these high level ideas don't work 100%.. But I would most certainly give them a shot.

• Use Procdump to launch the process, and take n full dumps after Elapsed Time performance counter for the processes reaches some value (like 2, or 3 or 4). Then you can open these dumps in windbg (most information, difficult to use), or VS.Net (easier to use, but may or may not show what you want to find, even if it is there - Do use mixed mode debugging when opening the dump).

• On similar lines, but less powerful, more tricky to get right.. Configure ProcessExplorer to show native stack traces when you look at the process properties... As soon as you start the process, switch to ProcessExplorer, and look at the stack traces for various threads in the process.. This is trickier, because depending on how many threads are there, manually going through their stack traces may not work at well at all.. Might be worth a shot or two, in case it does make the problem obvious with least effort.

In either case, be sure to have your symbols configured to Microsoft's public symbol servers.. So that you get most information from the native stack traces.

To summarize, the idea is.. in this case, some high level function should have high probability of showing in stack trace, if things below it were taking several seconds to complete.

Note - Once you know the high level function, it may be the end of the story, or it may still be necessary to co-relate it with other system level processes.. (again anti-virus being typical example).. But you could certainly expect to have more clues to help backup any such hypothesis.