What happens between Application.Run and Form.Load?

Asked 15/12, 2014 at 19:2 Answered 19/12, 2014 at 8:41

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.

Thump answered 15/12, 2014 at 19:2 Comment(7)

Add a log call in Sub New and see where it falls. – Refresh 15/12, 2014 at 19:10

msdn.microsoft.com/en-us/magazine/cc163655.aspx – Tokyo 15/12, 2014 at 19:26

You might try running Process Monitor to see what's going on at the lower level during those five seconds. – Jablonski 18/12, 2014 at 8:13

There happens a lot. When you really want to know what's going on take a look at this book "Windows internals" amazon.com/Windows-Internals-Edition-Developer-Reference/dp/… – Vanguard 18/12, 2014 at 8:52

Looking at your Edit 2, it's obvious that there are some problems while accessing resources (either because they are not on the correct path, or because the user is denied access to them), this might be causing exceptions (which are probably trapped) which usually cause such delays. Check that all the files are good and the user running them has permissions on the folder where you are running them – Fishgig 18/12, 2014 at 15:49

What bitness are you compiling for? And, do you see a difference if you 'run as administrator' the release build from Explorer? – Civism 18/12, 2014 at 20:19

I use AnyCPU and running as administrator does not make a difference. – Thump 18/12, 2014 at 20:28

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.

Tokyo answered 18/12, 2014 at 11:24 Comment(4)

Thank you for your nice answer. I first noticed now that the problem only occurs in "Release" Build mode and only when started from the explorer (from VS it's fast as well). It seems to hang at one specific line, related to creation of some resource file, when I look at ProcMon (I'll add the lines to my question). – Thump 18/12, 2014 at 15:3

Oh, but it has something to do with the complexity of the form in any case. When I delete controls, it speeds up. So the Designer in some way might be the culprit. I can't however make out a significant difference in the generated code (looking at ILSpy) between the two versions. However the Optimization step definitely causes the difference (I turned it off in the Release build and it's fast again). – Thump 18/12, 2014 at 15:13

Strong hint of anti-malware being involved. – Tokyo 18/12, 2014 at 15:49

Since the bounty is running out I will award this answer since it provides the most detailed look. I could not yet trace the issue to its source, but I will keep on testing. Anti-Malware can still be the culprit, even though I tried to avoid it, but I can test this further. Thank you again for your contribution! – Thump 24/12, 2014 at 16:23

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

Refresh answered 15/12, 2014 at 19:9 Comment(3)

I see, this makes sense since I have quite a lot of controls in the form, placed in various TableLayoutPanels, so the code for InitializeComponent is rather long. On the other hand I only reference 7 .NET assemblies, and nothing more, so I guess the JIT compilation is the culprit. Is there any way to speed it up, or do I just have to add a splash screen and live with it? – Thump 15/12, 2014 at 20:5

You could ngen the assemblies. – Refresh 15/12, 2014 at 20:6

I now have tried this, but it did not have a noticable effect. Please seee the edited question, if you like. – Thump 18/12, 2014 at 7:47

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.

Riches answered 19/12, 2014 at 8:41 Comment(0)

Recommended topics

Hot tags