application_start firing unexpectedly asp.net

Question

I am looking at an asp.net application that makes calls to a database within the application start inside global.asax. These calls takes around 3 seconds (depends on SQL cache plan) to run. I have noticed that the application runs slowly when I first redeploy. I put this down to the calls to the database whilst the application started. However after a few minutes the application again takes time to load.

To find out what was going, I have written to a log file (see below). From this file you can see that application start fires multipe times when multiple requests hits the application for the first time. It then appears that the application_start is fired in a random fashion (anything from 2-10 mins).

From my understanding of how application_starts works it should only get triggered when the applicaton FIRST starts, however it appears to be fired from multiple clients randomly! According to MSDN "The Application_Start event is fired the first time when an application starts."

Can anyone help me work out what is going on? I am using IIS6 and .net 2.0. Is it an application pool setting I am missing.

Many thanks Rippo

[12/02/2009 16:16:58] 91.84.25.241 - Application started, Sub MyRules started
[12/02/2009 16:17:06] 65.55.51.34 - Application started, Sub MyRules started
[12/02/2009 16:17:07] 91.84.25.241 - Application started, Sub MyRules completed
[12/02/2009 16:17:10] 65.55.51.34 - Application started, Sub MyRules completed
[12/02/2009 16:17:26] 212.115.51.229 - Application started, Sub MyRules started
[12/02/2009 16:17:30] 212.115.51.229 - Application started, Sub MyRules completed
[12/02/2009 16:17:30] 212.115.51.229 - Application started, Sub MyRules started
[12/02/2009 16:17:33] 212.115.51.229 - Application started, Sub MyRules completed
[12/02/2009 16:17:33] 212.115.51.229 - Application started, Sub MyRules started
[12/02/2009 16:17:36] 212.115.51.229 - Application started, Sub MyRules completed
[12/02/2009 16:17:36] 212.115.51.229 - Application started, Sub MyRules started
[12/02/2009 16:17:39] 212.115.51.229 - Application started, Sub MyRules completed
[12/02/2009 16:17:42] 212.115.51.229 - Application started, Sub MyRules started
[12/02/2009 16:17:48] 212.115.51.229 - Application started, Sub MyRules completed
[12/02/2009 16:17:48] 212.115.51.229 - Application started, Sub MyRules started
[12/02/2009 16:17:52] 212.115.51.229 - Application started, Sub MyRules completed
[12/02/2009 16:17:52] 212.115.51.229 - Application started, Sub MyRules started
[12/02/2009 16:17:54] 212.115.51.229 - Application started, Sub MyRules completed
[12/02/2009 16:18:27] 91.84.25.241 - Application started, Sub MyRules started
[12/02/2009 16:18:31] 91.84.25.241 - Application started, Sub MyRules completed
[12/02/2009 16:18:31] 212.115.51.229 - Application started, Sub MyRules started
[12/02/2009 16:18:33] 212.115.51.229 - Application started, Sub MyRules completed
[12/02/2009 16:29:26] 167.230.38.115 - Application started, Sub MyRules started
[12/02/2009 16:29:28] 167.230.38.115 - Application started, Sub MyRules completed
[12/02/2009 16:29:34] 82.110.42.84 - Application started, Sub MyRules started
[12/02/2009 16:29:37] 82.110.42.84 - Application started, Sub MyRules completed
[12/02/2009 16:29:38] 82.110.42.84 - Application started, Sub MyRules started
[12/02/2009 16:29:41] 82.110.42.84 - Application started, Sub MyRules completed
[12/02/2009 16:32:53] 99.142.1.97 - Application started, Sub MyRules started
[12/02/2009 16:32:57] 99.142.1.97 - Application started, Sub MyRules completed
[12/02/2009 16:32:57] 99.142.1.97 - Application started, Sub MyRules started
[12/02/2009 16:33:01] 99.142.1.97 - Application started, Sub MyRules completed
[12/02/2009 16:33:01] 99.142.1.97 - Application started, Sub MyRules started
[12/02/2009 16:33:06] 99.142.1.97 - Application started, Sub MyRules completed
[12/02/2009 16:33:06] 99.142.1.97 - Application started, Sub MyRules started
[12/02/2009 16:33:10] 99.142.1.97 - Application started, Sub MyRules completed
[12/02/2009 16:33:11] 99.142.1.97 - Application started, Sub MyRules started
[12/02/2009 16:33:16] 99.142.1.97 - Application started, Sub MyRules completed
[12/02/2009 16:36:15] 65.55.51.34 - Application started, Sub MyRules started
[12/02/2009 16:36:17] 65.55.51.34 - Application started, Sub MyRules completed
[12/02/2009 16:41:37] 119.123.226.156 - Application started, Sub MyRules started
[12/02/2009 16:41:37] 62.49.121.122 - Application started, Sub MyRules started
[12/02/2009 16:41:40] 62.49.121.122 - Application started, Sub MyRules completed
[12/02/2009 16:41:40] 119.123.226.156 - Application started, Sub MyRules completed
[12/02/2009 16:41:41] 62.49.121.122 - Application started, Sub MyRules started
[12/02/2009 16:41:44] 62.49.121.122 - Application started, Sub MyRules completed
[12/02/2009 16:45:17] 84.70.249.242 - Application started, Sub MyRules started
[12/02/2009 16:45:19] 84.70.249.242 - Application started, Sub MyRules completed
[12/02/2009 16:47:03] 80.41.121.68 - Application started, Sub MyRules started
[12/02/2009 16:47:05] 80.41.121.68 - Application started, Sub MyRules completed
[12/02/2009 16:47:29] 81.179.26.249 - Application started, Sub MyRules started
[12/02/2009 16:47:31] 81.179.26.249 - Application started, Sub MyRules completed
[12/02/2009 16:47:59] 81.136.179.170 - Application started, Sub MyRules started
[12/02/2009 16:47:59] 81.136.179.170 - Application started, Sub MyRules started
[12/02/2009 16:48:02] 81.136.179.170 - Application started, Sub MyRules completed
[12/02/2009 16:48:02] 81.136.179.170 - Application started, Sub MyRules started
[12/02/2009 16:48:02] 81.136.179.170 - Application started, Sub MyRules completed
[12/02/2009 16:48:02] 81.136.179.170 - Application started, Sub MyRules started
[12/02/2009 16:48:04] 81.136.179.170 - Application started, Sub MyRules completed
[12/02/2009 16:48:04] 81.136.179.170 - Application started, Sub MyRules completed
[12/02/2009 16:52:35] 69.34.161.80 - Application started, Sub MyRules started
[12/02/2009 16:52:35] 69.34.161.80 - Application started, Sub MyRules started
[12/02/2009 16:52:35] 69.34.161.80 - Application started, Sub MyRules started
[12/02/2009 16:52:38] 69.34.161.80 - Application started, Sub MyRules completed
[12/02/2009 16:52:38] 69.34.161.80 - Application started, Sub MyRules started
[12/02/2009 16:52:39] 69.34.161.80 - Application started, Sub MyRules completed
[12/02/2009 16:52:39] 69.34.161.80 - Application started, Sub MyRules completed
[12/02/2009 16:52:40] 69.34.161.80 - Application started, Sub MyRules completed

Answer 1

Check in what cases an App restarts. Recently we were writing some log entries to bin folder and exactly the same thing was happening and we didn't understand the reason. Then finally realized that making any modifications to bin folder was causing the app restart.

Answer 2

Check the event log, something is causing the app pool to recycle.

Answer 3

I had a problem with the Application_Start getting called multiple times, and it turns out it was because I had multiple instances set up. Stupid mistake, but I wanted to note it.

Answer 4

I don't know why, but I saw the same thing in my logs. Is it possibly because it takes too long and you have multiple requests coming in at the same time? Anyway, just to be safe, I'm adding this code:

public class MvcApplication : HttpApplication
{
    private static volatile bool hasRegisteredBgTasks = false;
    private static object registeredBgTasksLock = new object();

    protected void Application_Start()
    {
        lock (registeredBgTasksLock)
        {
            if (hasRegisteredBgTasks)
            {
                return;
            }
            // Actual start up code.
            hasRegisteredBgTasks = true;
        }
    }

    // Other Application methods...
}