|
|
Rank: Umbracoholic
Joined: 9/8/2006
Posts: 1,432
Location: KY, USA
|
I've tried everything I can think of... I need some help resolving the huge number of "application started" entries in my umbraco log. I don't know why they show up, and so many of them so often. I've got a series of websites that are all quite similar to one another. Each running in its own app-pool, each umbraco installation running one site. None of the sites get very many hits per day (well under 100 visitors/day). One of the sites has a few "application started" log entries per day, and another has thousands! I can't figure out what is triggering the entries, and especially so many of them. Interestingly, there are almost no "application shutted down" entries, and IIS/perf mon don't report application restarts (except when I touch the web.config or put a new dll in the /bin folder). And the overall performance of the site is very good. When the application really does restart (touch web.config, for instance), it takes about 6sec for the site to respond again. But the site's maximum response time (according to some external monitoring tools I use to watch for performance problems) show less than 2sec maximum and well under a second average response time (except for the few times I deliberately restarted the site and can account for the longer times). Here is a snippet of the System log as shown using the LogViewer package so you can see what I mean. This represents all the entries for one hour's uptime... Code:
System Administrator 2/11/2008 8:00:03 AM Application started at 2/11/2008 8:00:03 AM
System Administrator 2/11/2008 7:56:09 AM Application started at 2/11/2008 7:56:09 AM
System Administrator 2/11/2008 7:56:09 AM Application started at 2/11/2008 7:56:09 AM
System Administrator 2/11/2008 7:56:09 AM Application started at 2/11/2008 7:56:09 AM
System Administrator 2/11/2008 7:56:09 AM Application started at 2/11/2008 7:56:09 AM
System Administrator 2/11/2008 7:56:09 AM Application started at 2/11/2008 7:56:09 AM
System Administrator 2/11/2008 7:51:10 AM Application started at 2/11/2008 7:51:10 AM
System Administrator 2/11/2008 7:51:10 AM Application started at 2/11/2008 7:51:10 AM
System Administrator 2/11/2008 7:51:10 AM Application started at 2/11/2008 7:51:10 AM
System Administrator 2/11/2008 7:51:10 AM Application started at 2/11/2008 7:51:10 AM
System Administrator 2/11/2008 7:47:17 AM Application started at 2/11/2008 7:47:17 AM
System Administrator 2/11/2008 7:47:17 AM Application started at 2/11/2008 7:47:17 AM
System Administrator 2/11/2008 7:47:17 AM Application started at 2/11/2008 7:47:17 AM
System Administrator 2/11/2008 7:46:10 AM Application started at 2/11/2008 7:46:10 AM
System Administrator 2/11/2008 7:46:10 AM Application started at 2/11/2008 7:46:10 AM
System Administrator 2/11/2008 7:46:10 AM Application started at 2/11/2008 7:46:10 AM
System Administrator 2/11/2008 7:46:10 AM Application started at 2/11/2008 7:46:10 AM
System Administrator 2/11/2008 7:46:10 AM Application started at 2/11/2008 7:46:10 AM
System Administrator 2/11/2008 7:42:14 AM Application started at 2/11/2008 7:42:14 AM
System Administrator 2/11/2008 7:42:14 AM Application started at 2/11/2008 7:42:14 AM
System Administrator 2/11/2008 7:41:10 AM Application started at 2/11/2008 7:41:10 AM
System Administrator 2/11/2008 7:41:10 AM Application started at 2/11/2008 7:41:10 AM
System Administrator 2/11/2008 7:41:10 AM Application started at 2/11/2008 7:41:10 AM
System Administrator 2/11/2008 7:41:10 AM Application started at 2/11/2008 7:41:10 AM
System Administrator 2/11/2008 7:37:15 AM Application started at 2/11/2008 7:37:15 AM
System Administrator 2/11/2008 7:37:15 AM Application started at 2/11/2008 7:37:15 AM
System Administrator 2/11/2008 7:36:10 AM Application started at 2/11/2008 7:36:10 AM
System Administrator 2/11/2008 7:36:10 AM Application started at 2/11/2008 7:36:10 AM
System Administrator 2/11/2008 7:36:10 AM Application started at 2/11/2008 7:36:10 AM
System Administrator 2/11/2008 7:36:10 AM Application started at 2/11/2008 7:36:10 AM
System Administrator 2/11/2008 7:31:10 AM Application started at 2/11/2008 7:31:10 AM
System Administrator 2/11/2008 7:31:10 AM Application started at 2/11/2008 7:31:10 AM
System Administrator 2/11/2008 7:31:10 AM Application started at 2/11/2008 7:31:10 AM
System Administrator 2/11/2008 7:31:10 AM Application started at 2/11/2008 7:31:10 AM
System Administrator 2/11/2008 7:26:10 AM Application started at 2/11/2008 7:26:10 AM
System Administrator 2/11/2008 7:26:10 AM Application started at 2/11/2008 7:26:10 AM
System Administrator 2/11/2008 7:26:10 AM Application started at 2/11/2008 7:26:10 AM
System Administrator 2/11/2008 7:26:10 AM Application started at 2/11/2008 7:26:10 AM
System Administrator 2/11/2008 7:26:10 AM Application started at 2/11/2008 7:26:10 AM
System Administrator 2/11/2008 7:26:10 AM Application started at 2/11/2008 7:26:10 AM
System Administrator 2/11/2008 7:21:10 AM Application started at 2/11/2008 7:21:10 AM
System Administrator 2/11/2008 7:21:10 AM Application started at 2/11/2008 7:21:10 AM
System Administrator 2/11/2008 7:21:10 AM Application started at 2/11/2008 7:21:10 AM
System Administrator 2/11/2008 7:21:10 AM Application started at 2/11/2008 7:21:10 AM
System Administrator 2/11/2008 7:21:10 AM Application started at 2/11/2008 7:21:10 AM
System Administrator 2/11/2008 7:20:03 AM Application started at 2/11/2008 7:20:03 AM
System Administrator 2/11/2008 7:16:10 AM Application started at 2/11/2008 7:16:10 AM
System Administrator 2/11/2008 7:16:10 AM Application started at 2/11/2008 7:16:10 AM
System Administrator 2/11/2008 7:16:10 AM Application started at 2/11/2008 7:16:10 AM
System Administrator 2/11/2008 7:16:10 AM Application started at 2/11/2008 7:16:10 AM
System Administrator 2/11/2008 7:11:10 AM Application started at 2/11/2008 7:11:10 AM
System Administrator 2/11/2008 7:11:10 AM Application started at 2/11/2008 7:11:10 AM
System Administrator 2/11/2008 7:11:10 AM Application started at 2/11/2008 7:11:10 AM
System Administrator 2/11/2008 7:11:10 AM Application started at 2/11/2008 7:11:10 AM
System Administrator 2/11/2008 7:11:10 AM Application started at 2/11/2008 7:11:10 AM
System Administrator 2/11/2008 7:10:03 AM Application started at 2/11/2008 7:10:03 AM
System Administrator 2/11/2008 7:06:10 AM Application started at 2/11/2008 7:06:10 AM
System Administrator 2/11/2008 7:06:10 AM Application started at 2/11/2008 7:06:10 AM
System Administrator 2/11/2008 7:06:10 AM Application started at 2/11/2008 7:06:10 AM
System Administrator 2/11/2008 7:06:10 AM Application started at 2/11/2008 7:06:10 AM
System Administrator 2/11/2008 7:06:10 AM Application started at 2/11/2008 7:06:10 AM
System Administrator 2/11/2008 7:06:10 AM Application started at 2/11/2008 7:06:10 AM
System Administrator 2/11/2008 7:01:10 AM Application started at 2/11/2008 7:01:10 AM
System Administrator 2/11/2008 7:01:10 AM Application started at 2/11/2008 7:01:10 AM
System Administrator 2/11/2008 7:01:10 AM Application started at 2/11/2008 7:01:10 AM
System Administrator 2/11/2008 7:01:10 AM Application started at 2/11/2008 7:01:10 AM
System Administrator 2/11/2008 7:00:03 AM Application started at 2/11/2008 7:00:03 AM
Any ideas why so many "application started" messages? Why so many entries at the same time, or why it happens about every 5 minutes? I'm totally stumped. cheers, doug.
MVP 2007-2009 - Official Umbraco Trainer for North America - Percipient Studios
|
|
Rank: Aficionado
Joined: 10/30/2007
Posts: 191
Location: Bellingham
|
Doug - I'm not sure on this one, may need to wait for Niels since this wrapped in the Umbraco core, but I see where this is firing from: umbraco.presentation.ApplicationStartAnd I'm supposing that this is due to the KeepAlive feature of Umbraco which is set to Ping the HttpApp.Context every 300000 milliseconds (which just happens to be 5 minutes). In theory this could be changed in order to generate fewer log entries, but I believe this would result in a performance penalty. Perhaps a better way to address the large number of log entries (which appears to be a common topic in the forums) is to create a log entry sink that would intercept the log entries and only log those with a certain "status" - such as errors or as set in a configuration value. -Paul
motusconnect.com :: level-2 certified :: MVP 2008/2009 See you at Codegarden08 US in Chicago!
|
|
Rank: Umbracoholic
Joined: 9/8/2006
Posts: 1,432
Location: KY, USA
|
I thought about that, so I logged in to one of the sites that isn't getting many log entries, and let it just site there for an hour. Nothing. No log entries. Now, I'm not a pro C# guy so I'd appreciate any input from someone who want to poke around in the source... now, let's say the umbraco.presentation.ApplicationStart is the cause of the issue... when does that get called? It does NOT seem to be related to the actual restarting of the app pool. In fact, when I do restart the app pool manually, I see an "application shutted down" message, followed by "application starting" followed by "loading content from disk cache...". But as you can see from my log snippet, this sequence is very rare. So again, I wonder, what on earth is calling ApplicationStart? Thanks in advance for any insight on this one! cheers, doug.
MVP 2007-2009 - Official Umbraco Trainer for North America - Percipient Studios
|
|
Rank: Fanatic
Joined: 7/20/2006
Posts: 453
Location: NL
|
Doug,
could you check the web.config files of a few and see if there is any difference in the key: key="umbracoDebugMode"
To be honest, from the top of my head, I've seen this on one of my own sites also I think.
Not sure why it does that either though but no matter what the key mentioned above is set to, it should not happen I think. I see some entries on a website that has about 400 visitors a day but only every now and then (debugMode is set to true).
Can it be some different setting in your application-pool?
Cant be of more help than this.....
PeterD
Working on an events-calendar with recursion. Post requests on my blog!
|
|
Rank: Aficionado
Joined: 10/30/2007
Posts: 191
Location: Bellingham
|
Doug - Sorry, I should've explained a bit more. umbraco.presentation.ApplicationStart is called only when the App actually starts as defined by IIS - as an AppPool restart or IISRESET, etc.... Within this ApplicationStart the PingTimer is created and fires off a call to the Ping.aspx page (in .../umbraco/ping.aspx) every 5 minutes which calls the KeepAliveService. This simply loads a page to keep things going and creates the log entry you're seeing. When I comment out the call to the KeepAliveService the log entries: Application started at <Date + Time>Are not created. I hope this helps, -Paul
motusconnect.com :: level-2 certified :: MVP 2008/2009 See you at Codegarden08 US in Chicago!
|
|
Rank: Umbracoholic
Joined: 9/8/2006
Posts: 1,432
Location: KY, USA
|
Thanks for looking into this for me, Paul! Interesting. Let me be sure I'm following 100%... The keepalive ping records itself as "application started"? That sounds like a bug to me, it should say "keeping site alive" or something like that? Or have I still misunderstood the situation? cheers, doug.
MVP 2007-2009 - Official Umbraco Trainer for North America - Percipient Studios
|
|
Rank: Aficionado
Joined: 10/30/2007
Posts: 191
Location: Bellingham
|
Doug - Exactly right. I agree that the "Application Started at ..." is rather misleading and, assuming I've correctly identified the intention of this functionality, it would be more accurate to log "Application keep alive fired at ...". In case there are any takers on verifying this here is the relevant location: Code:umbraco.presentation
{
public class requestModule : IHttpModule
{
protected Timer publishingTimer;
protected Timer pingTimer;
private HttpApplication mApp;
private IContainer components = null;
protected void ApplicationStart(HttpApplication HttpApp)
{
try
{
Log.Add(LogTypes.System, User.GetUser(0), -1, "Application started at " + DateTime.Now);
...
// Start ping / keepalive timer
pingTimer = new Timer(new TimerCallback(keepAliveService.PingUmbraco), HttpApp.Context, 60000, 300000);
... -Paul
motusconnect.com :: level-2 certified :: MVP 2008/2009 See you at Codegarden08 US in Chicago!
|
|
Rank: Addict
Joined: 3/17/2008
Posts: 831
Location: Nyborg, Denmark
|
It's a major bug, where the application start event - incorrectly - was moved from global.asax to the httpmodule of umbraco, causing the application start event to fire on each init of the httpmodule.
I'll look into this along with the other bugs (like load balancing and maybe the performance hiccup issue) that will be fixed for 3.0.5 coming ASAP.
Thanks!
/n
Jeeeez, did I really start this :-)
|
|
Rank: Fanatic
Joined: 7/25/2006
Posts: 396
Location: Silkeborg, Denmark
|
My logs are getting slammed by the "Application Started" entries too. Let me know if you need help testing anything, or you can even get full access + remote desktop to my dedicated server. /SoerenS
Brug for råd til hvordan du driver en god webshop? / Need advice on how to run an effective webshop?
|
|
Rank: Addict
Joined: 3/17/2008
Posts: 831
Location: Nyborg, Denmark
|
The application started bug has been found and solved, so now it's "just" the other performance tweeks that we're trying to close.
Also, we got a hang memory dump yesterday that we're trying to analyze. I'll keep you updated.
/n
Jeeeez, did I really start this :-)
|
|
Rank: Addict
Joined: 7/19/2006
Posts: 599
Location: Preston, UK
|
Guys, I get a similar issue in the error log. Any action i do in the editor i get error although the action works some sample errors that keep occuring in my site are: Any ideas anyone?
Level 2 certified. If it aint broke dont fix.
|
|
Rank: Fanatic
Joined: 7/20/2006
Posts: 407
Location: Amsterdam
|
Maybe create a trigger on the LOG table to ignore those entries? Just a temp solution offcourse.....
|
|
Rank: Addict
Joined: 7/19/2006
Posts: 599
Location: Preston, UK
|
Sjors,
I have a scheduled job via the umbraco tasks scheduler that clears the error log every 24 hours so that my log table does not get to big. Ideally would like to get to the bottom of it.
Regards
Ismail
Level 2 certified. If it aint broke dont fix.
|
|
Rank: Fanatic
Joined: 3/15/2007
Posts: 366
Location: Cary, NC USA
|
Ismail - did you ever find a fix for this...? I'm apparently seeing similiar errors logged... using umbraco 3.05 here... anyone else? thx! imayat12 wrote:Guys, I get a similar issue in the error log. Any action i do in the editor i get error although the action works some sample errors that keep occuring in my site are: Any ideas anyone?
|
|
|
Guest |