.NET (Core and Framework)

15-Sep-06 5:34

Hi I wrote some winforms app which seems to work but has very ugly problem - it needs near 30 seconds to start.
Application starts in 3 steps -
- splash window is initialized and shown
- main app window is initialized and shown
- splash is hidden.

There is no any data connection touch or any other similar operation at the start.
Measured times to start the app are:
1. splash is shown in 6 ( WTF | :WTF:

) seconds at first and is reduced to 4 seconds in next run
2. Main app window needs about 16 seconds to show.

I am mostly shocked by time to show the splash which is just plain, frameless window with some bitmap loaded from resources.

I have tried different tricks with the assemblies - signed them, added to the GAC and even precompiled, but it doesn't change situation in any significant way.

Time has been measured on my development machine which is Ahlon 2.2 GHz with 1.5BG of RAM so I don't think it is the hardware/os/environment problem.

Could anybody tell me what's wrong?
Any ideas are welcome - I'm getting mad on this Smile | :)

Thanx
H.

Jakob Farian Krarup17-Sep-06 19:16

17-Sep-06 19:16

Hi H

Do you compile the application in Release mode?
This can change the startup time dramatically.

If you are already in release mode, then try inserting a few Trace lines here and there and add a System.Diagnostics.TextWriterTraceListener to your application, to find out where all those CPU cycles are going.

TextWriterTraceListener myTextListener = new TextWriterTraceListener(@"C:\debug.txt");
Trace.Listeners.Add(myTextListener);
 
// Write output to the file.
Trace.Write("BEFORE doing something - the time is: " + DateTime.Now);
...
Trace.Write("AFTER doing something - the time is: " + DateTime.Now);

Kind regards - Jakob

Kind regards - Jakob Cool | :cool:

*********************************************
Three kinds of people in the world:
- Those who can count..
- Those who can't!

10 kinds of people in the world:
- Those who understand binary
- Those who don't

..Hubert..18-Sep-06 1:27

18-Sep-06 1:27

Hi Jacob
I have tried 3 time measuring methods - user measured time, console output and JetBrains dotTrace.
dotTrace is most detailed, but it has huge influence on measured time.
Your method is probably best since, it has permanent storage of results - thank you for the idea Smile | :)

I have included it in my project and measured times are very similar to those posted before. But I have found something pretty interesting.
There is SplashForm creation in the Program.cs. The SplashForm is derived from NiceDialog class (which is some pre-customized form). Here is part of the log file created with Trace listeners:

2006-09-18 11:44:49; Start of creating splash form
2006-09-18 11:44:52; NiceDialog InitializeComponent start
2006-09-18 11:44:52; NiceDialog InitializeComponent end
2006-09-18 11:44:53; SplashForm InitializeComponent start
2006-09-18 11:44:53; SplashForm InitializeComponent ends

Following code is executed here:
Program.cs

Trace.WriteLine(string.Format("{0}; Start of creating splash form", DateTime.Now));<br />
             SplashForm splash = new SplashForm();<br />
            splash.Show();<br />

NiceDialog.cs

<br />
        public NiceDialogForm()<br />
        {<br />
            Log("NiceDialog InitializeComponent start");<br />
            InitializeComponent();<br />
            Log("NiceDialog InitializeComponent end"); <br />
        }<br />
        protected static void Log(string message)<br />
        {<br />
            Trace.WriteLine(string.Format("{0}; {1}",DateTime.Now, message));<br />
        }<br />

SplashForm.cs

<br />
        public SplashForm()<br />
        {<br />
            Log("SplashForm InitializeComponent start");<br />
            InitializeComponent();<br />
            Log("SplashForm InitializeComponent ends");<br />
            this.lblVersion.Text = "version: "+Application.ProductVersion;<br />
        }<br />

Well - it is strange to me. SplashForm constructor is called but its first method is called 3 seconds later. And it's not the time to load next library - they are all declared in main exe file.
There is picture box with some resource based bitmap on the NiceDialog form. I have heard that resources may make program execution slower, so I decided to reset pictureBox Image propery - so it doesn't show anything right now. Here is part of log file with this operations:

2006-09-18 12:25:45; Start of creating splash form
2006-09-18 12:25:45; NiceDialog InitializeComponent start
2006-09-18 12:25:49; NiceDialog InitializeComponent end
2006-09-18 12:25:49; SplashForm InitializeComponent start
2006-09-18 12:25:49; SplashForm InitializeComponent ends

As you can see, NiceDialog execution time become normal, but NiceDialog InitializeComponent gone much higher (4 seconds!!!)- I have no idea why.

Best regards
Hubert

Jakob Farian Krarup18-Sep-06 2:02

18-Sep-06 2:02

Hi Hubert

Could you dump the contents of InitializeComponent from NiceDialog here - so we could have a look.
We should be able to find the problem Wink | ;-)

Kind regards - Jakob Cool | :cool:

..Hubert..18-Sep-06 4:48

18-Sep-06 4:48

Hi Jakob
Here is the code of NiceDialog InitializeComponent:

<code>
        private void InitializeComponent()
        {
            System.ComponentModel.ComponentResourceManager resources = new System.ComponentModel.ComponentResourceManager(typeof(NiceDialogForm));
            this.pictureBox1 = new System.Windows.Forms.PictureBox();
            this.panel1 = new System.Windows.Forms.Panel();
            this.panel2 = new System.Windows.Forms.Panel();
            ((System.ComponentModel.ISupportInitialize)(this.pictureBox1)).BeginInit();
            this.SuspendLayout();
            // 
            // pictureBox1
            // 
            this.pictureBox1.Dock = System.Windows.Forms.DockStyle.Left;
            this.pictureBox1.Location = new System.Drawing.Point(12, 12);
            this.pictureBox1.Name = "pictureBox1";
            this.pictureBox1.Size = new System.Drawing.Size(131, 264);
            this.pictureBox1.SizeMode = System.Windows.Forms.PictureBoxSizeMode.StretchImage;
            this.pictureBox1.TabIndex = 0;
            this.pictureBox1.TabStop = false;
            // 
            // panel1
            // 
            this.panel1.Dock = System.Windows.Forms.DockStyle.Fill;
            this.panel1.Location = new System.Drawing.Point(155, 12);
            this.panel1.Name = "panel1";
            this.panel1.Size = new System.Drawing.Size(228, 264);
            this.panel1.TabIndex = 2;
            // 
            // panel2
            // 
            this.panel2.Dock = System.Windows.Forms.DockStyle.Left;
            this.panel2.Location = new System.Drawing.Point(143, 12);
            this.panel2.Name = "panel2";
            this.panel2.Size = new System.Drawing.Size(12, 264);
            this.panel2.TabIndex = 3;
            // 
            // NiceDialogForm
            // 
            this.AutoScaleDimensions = new System.Drawing.SizeF(6F, 13F);
            this.AutoScaleMode = System.Windows.Forms.AutoScaleMode.Font;
            this.BackColor = System.Drawing.Color.Gainsboro;
            this.ClientSize = new System.Drawing.Size(395, 288);
            this.ControlBox = false;
            this.Controls.Add(this.panel1);
            this.Controls.Add(this.panel2);
            this.Controls.Add(this.pictureBox1);
            this.DoubleBuffered = true;
            this.FormBorderStyle = System.Windows.Forms.FormBorderStyle.None;
            this.Icon = ((System.Drawing.Icon)(resources.GetObject("$this.Icon")));
            this.MaximizeBox = false;
            this.MinimizeBox = false;
            this.Name = "NiceDialogForm";
            this.Padding = new System.Windows.Forms.Padding(12);
            this.ShowIcon = false;
            this.ShowInTaskbar = false;
            this.SizeGripStyle = System.Windows.Forms.SizeGripStyle.Hide;
            this.StartPosition = System.Windows.Forms.FormStartPosition.CenterScreen;
            this.Text = "SplashForm";
            ((System.ComponentModel.ISupportInitialize)(this.pictureBox1)).EndInit();
            this.ResumeLayout(false);

        }

</code>

There is nothing unusual for me - it's just what VS2k5 has made.
I still think about this release/debug issue - you have mentioned it in the first post. I haven't seen such a big difference, so maybe this is my problem? How can I check if the final assembly is optimized or not? The project seems to be ok - "Optimize code" flag is set.

Best regards
Hubert

Jakob Farian Krarup18-Sep-06 5:18

18-Sep-06 5:18

Hi Hubert

If I were you, I'd set the Trace.WriteLine statements at the beginning and end inside the InitializeComponent method.
Then move the Trace.WriteLine "end" halfway up, then halfway again, etc. until you find THE line that takes all the time.
I'm pretty sure there is one or two single lines taking up all the time.

Let me know when you're closer to the problem.

Kind regards - Jakob Cool | :cool:

..Hubert..18-Sep-06 6:09

18-Sep-06 6:09

Jakob Lund Krarup wrote:
there is one or two single lines taking up all the time.

Yes! I have probably found it. I decided to comment following line from the InitializeComponent method:

this.Icon = ((System.Drawing.Icon)(resources.GetObject("$this.Icon")));

Application needs just 1 second to show SplashForm now, so it is 4 times better than in the early begining of the optimalization. Smile | :)

But I don't have idea how to set icon and image in the picturebox faster than loading from resources. I don't want to have them in separate files in the app directory - I think it is not profesional.

Best regards
Hubert

Jakob Farian Krarup18-Sep-06 7:19

18-Sep-06 7:19

Hm.... weird!

Is it a homemade icon..? There may be some bug in the icon file.
Try setting the icon to the standard icon and check again for speed comparison.

Kind regards - Jakob Cool | :cool:

Phil Wilson18-Sep-06 13:20

Phil Wilson

18-Sep-06 13:20

I've noticed that getting data from a resource can be expensive. IIRC it tries to locate explicit resources for the current language (such as en-us)in a subfolder and takes a file not found exception if it's missing, and then goes on to do a lot of other stuff too. If you run a profiler on the code you'd see some of this going on by looking at the objects that get created behind your back.

Phil Wilson

..Hubert..11-Oct-06 0:39