.Net Runtime error and intermittent performance issues

[WylieE]

We have been experiencing intermittent system slowdowns for some time now. For a long time, we thought they were related to AC maintenance as we would regularly find maintenance related errors in the AC error log that coincided with the performance lags. Essentially, the site will come to a standstill for 2 - 3 minues.

Since we've upgraded to 7.0.3, we no longer see the AC errors but still have the slowdowns. After digging through our web server event logs, I've found a .net error that coincides with those slowdowns. Something seems to be causing the app pool to reset according to the MSFT docs.

Errors:
EventType clr20r3, P1 w3wp.exe, P2 6.0.3790.3959, P3 45d6968e, P4 commercebuilder, P5 7.3.12065.0, P6 4a1eea76, P7 178e, P8 0, P9 exception, P10 NIL.

Faulting application w3wp.exe, version 6.0.3790.3959, stamp 45d6968e, faulting module kernel32.dll, version 5.2.3790.4480, stamp 49c51f0a, debug? 0, fault address 0x0000bef7.

A process serving application pool 'warmothable' suffered a fatal communication error with the World Wide Web Publishing Service. The process id was '1772'. The data field contains the error number.


I've found reference to this under old AC 5.5 threads and this MSFT page:
http://support.microsoft.com/kb/911816

The first error seems to be referencing commercebuilder. The MSFT page only offers instructions on how to get more error data.

Has anyone else encountered these errors on a recent AC install? If so, were you able to resolve the problems and how?

[afm]

It looks like there is an unhandled exception in your application. The exception might be thrown by AbleCommerce or any customization you might have made. The default behavior when an unhandled exception is thrown is to exit the application. Since IIS is setup to automatically start the application when a request comes in, the application is automatically restarted and what you see is an intermittent slow down.

The event log does not provide enough detail to know what the unhandled exception is. It might be logged in the AbleCommerce logs. If not, the folks at AC might have a way to enable logging of exceptions which would help.

[WylieE]

Unfortunately, the AC logs don't have a lot of information. I can only find one instance where maintenance was recorded as running in the app.log that matched up to time where we had server issues. I'm inclined to say it may not be an AC maintenance issue.

If AC has an option to turn on a greater level of logging, I would be interested. We've added some additional error code and have begun capturing thousands (that is correct) of invalid viewstate errors. The interesting thing is they are all referencing the same URL and most have the same User Id.

Error:

System.Web.HttpException: The state information is invalid for this page and might be corrupted. ---> System.Web.UI.ViewStateException: Invalid viewstate.
Client IP: 64.41.140.102
Port: 47931
User-Agent: Mozilla/5.0 (compatible; MSIE 7.0; MSIE 6.0; ScanAlert; +http://www.scanalert.com/bot.jsp) Firefox/2.0.0.3
ViewState: uYkJI6gwLU3HJnSXwiMXukzwbkhANSF2Z2cb89Shrr/"Xx<XaXaXXaXaX>xX/SGXSImB5rWlBGFlrAmjd6KH2nno8gxzm/ATD36dko73l7UqN4REAtzi+6HxiUqFKbusoZ7qnsapOaIY3s4IUdXO2Ub0sxrIlwoRC9NfLKTWQ8yZ8e0aQCTS4S6i1eCV0AZma11oQx6+2pueOiAZ9pv2rchQsvVHDmiBnTXCY8qMWtiFbN73LUeTcPIucj9cNpLn6yLNb7LJ6V0NwVu6R+FaB40SfnnrS8fsSqoTAOG0GnAf0zHzmayRYAzvMozCO+g7IVbuTCH8e9kDGGk6kfOmIvTS+FMpupaZ6h/WBvChIgxjYYyYgJuq6uNsXQjSxQSHurJH7RmrKmAdoFMoQuaAGN6W7OIwpM+UZnzCxp87I9Wfcdx48AP66FxLkI7nz1cuNNXdC6gwFcBAMoloDTRyV3L+TKUu3Bt6cwz1feanC/ZIAhYVAHhqLl2eXDhibNDCYD85keArUM3+biN5pF62co1xFwTMrDVDamvgoI9vQBUVTXbywmFKJhRW66Yfm7zXEQ2GdMTBHFtxhkXW/ZEuBioBXQCTC0bk0yQXVX4Qm+taVTCcROB8tCVeFHhSNBYMjMDL2029bCQYkDc+5Vb9lkxlQK/wczWwnXov/2qItiONzsxcIt/fepKPr6f/d8IBwBrrxwv6Mp6FM8Ws9TOse12PMJBL5mto41C3XfrKRvgUZJd+xf3MZHB4omob3h0NBz3+2osA7xlQVyacWYa4TA9MYmQb/3UwTqdghYH78nHlKdzpx+6U4mmk5AnkiUPp2ePfr4KrpRows... ---> System.FormatException: Invalid character in a Base-64 string.
at System.Convert.FromBase64String(String s)
at System.Web.UI.ObjectStateFormatter.Deserialize(String inputString)
at System.Web.UI.ObjectStateFormatter.System.Web.UI.IStateFormatter.Deserialize(String serializedState)
at System.Web.UI.Util.DeserializeWithAssert(IStateFormatter formatter, String serializedState)
at System.Web.UI.HiddenFieldPageStatePersister.Load()
--- End of inner exception stack trace ---
--- End of inner exception stack trace ---
at System.Web.UI.ViewStateException.ThrowError(Exception inner, String persistedState, String errorPageMessage, Boolean macValidationError)
at System.Web.UI.ViewStateException.ThrowViewStateError(Exception inner, String persistedState)
at System.Web.UI.HiddenFieldPageStatePersister.Load()
at System.Web.UI.Page.LoadPageStateFromPersistenceMedium()
at System.Web.UI.Page.LoadAllState()
at System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)
at System.Web.UI.Page.ProcessRequest(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)
at System.Web.UI.Page.ProcessRequest()
at System.Web.UI.Page.ProcessRequestWithNoAssert(HttpContext context)
at System.Web.UI.Page.ProcessRequest(HttpContext context)
at ASP.categorygrid4_aspx.ProcessRequest(HttpContext context)
at System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)

URL: /CategoryGrid4.aspx?CategoryId=41

User Id: 1419054

Microsoft has a technote regarding this error: http://support.microsoft.com/kb/555353. The most likely culprits being app pool recycling and server clusters. We already have the machine key set so we can synch from dev to live servers. That brings us back to the app pool resetting, but we don't know if the errors are simply a result of the app pool resetting or if something else if causing the app pool to reset.

[afm]

The sample you quoted looks like it is coming from your McAffee scan service. They are probably trying to
intentionlly send bad requests to see if they can force a behavior. If you can confirm that with them, then
you can safely filter those out of your logs.

I suspect bad requests are handled (i.e. not an unhandled exception). So even if you can't filter them out
of your logs, you can ignore them for this exercise.

What you are looking for are unhandled exceptions. Things that the AC logger records and then rethrows
because AC does not know what to with them.

You (or someone at the server) may have to attach a debugger to the site to catch one.

[AbleMods]

http://www.scanalert.com/bot.jsp

[WylieE]

http://www.scanalert.com/bot.jsp

Yep. Caught that after posting. Trying to figure out how to filter the data.

We've confirmed our machine key settings with our co-locating company so that rules out part of the MSFT tech note options.

UPDATE: Just found an old thread regarding this issue. No resolution though. It looks like there may have been an open case at some point. viewtopic.php?f=42&t=8717&view=previous

[afm]

UPDATE: Just found an old thread regarding this issue. No resolution though.

Eric,

I'm pretty sure you have 2 separate issues:

1. Intermittent performance issues caused by intermittent site restarts.
2. Lots of invalid ViewState exceptions in the log.

The 2nd is almost certainly the same as in the other thread. The next step for you (and the other thread) is for someone to contact the scanalert people to confirm that they are causing the ViewState exceptions on purpose (I suspect it is a side effect of some tests they perform).

The 1st is almost certainly unrelated to the Viewstate exceptions. Caught exceptions like invalid viewstate will not cause the site to restart. As far as I know, only uncaught exception can make a site restart.

Actually, that's not true. Many things can cause a site restart. One of them is uncaught exceptions. Your first post seems to point to an uncaught exception causing your site to restart.

The next step for #1 is to find the uncaught exception.

[WylieE]

UPDATE: Just found an old thread regarding this issue. No resolution though.

Eric,

I'm pretty sure you have 2 separate issues:

1. Intermittent performance issues caused by intermittent site restarts.
2. Lots of invalid ViewState exceptions in the log.

The 2nd is almost certainly the same as in the other thread. The next step for you (and the other thread) is for someone to contact the scanalert people to confirm that they are causing the ViewState exceptions on purpose (I suspect it is a side effect of some tests they perform).

The 1st is almost certainly unrelated to the Viewstate exceptions. Caught exceptions like invalid viewstate will not cause the site to restart. As far as I know, only uncaught exception can make a site restart.

Actually, that's not true. Many things can cause a site restart. One of them is uncaught exceptions. Your first post seems to point to an uncaught exception causing your site to restart.

The next step for #1 is to find the uncaught exception.

We've been banging away on this for almost a week now and have made little headway.

We've confirmed from McAffee the viewstates are coming from them and are intentional. Otherwise, we've made no progress in finding out what (or why) the app pool is restarting. It is happening at seemingly random times throughout the day.

Does anyone have any suggestions on further troubleshooting?

[ZLA]

Actually, that's not true. Many things can cause a site restart.

You're not deleting sub-directories are you? I know that will cause the app to restart: http://blogs.msdn.com/toddca/archive/20 ... 99144.aspx.

[WylieE]

Actually, that's not true. Many things can cause a site restart.

You're not deleting sub-directories are you? I know that will cause the app to restart: http://blogs.msdn.com/toddca/archive/20 ... 99144.aspx.

Nope. Not deleting sub-directories. The error message implies something is going on with commercebuilder. (P4 commercebuilder, P5 7.3.12065.0 being the assembly & version raising the exception.)

This is becoming quite the challenge.

[afm]

Tess Ferrandez talks a lot about debugging ASP.NET apps. Some of her posts are over my head, but you can probably find some useful information,

http://blogs.msdn.com/tess/

[jmestep]

Andy, thanks for posting that. We have trouble debugging sites not on our servers and I was just looking for something last night.

[WylieE]

Tess Ferrandez talks a lot about debugging ASP.NET apps. Some of her posts are over my head, but you can probably find some useful information,

http://blogs.msdn.com/tess/

Yes, I found her site a few days ago. Here's one blog post that I've been digging through quite a bit:
http://blogs.msdn.com/tess/archive/2006 ... ycles.aspx

I've also set up perfmon to track resource usage in case we have a leak:
http://dotnetdebug.net/2005/06/30/perfm ... ging-buddy

This is a common article that discusses problem solving:
http://blogs.msdn.com/david.wang/archiv ... Crash.aspx

And other articles I've read to learn more about what could be going on:
http://dimensionsusers.com/forum/viewto ... f=29&t=148

[Logan Rhodehamel]

UPDATE: Just found an old thread regarding this issue. No resolution though. It looks like there may have been an open case at some point. viewtopic.php?f=42&t=8717&view=previous

Our resolution was to stop logging the errors in AbleCommerce - they are benign and there's nothing we can do to stop them. http://bugs.ablecommerce.com/show_bug.cgi?id=7403

[Logan Rhodehamel]

We have been experiencing intermittent system slowdowns for some time now. For a long time, we thought they were related to AC maintenance as we would regularly find maintenance related errors in the AC error log that coincided with the performance lags. Essentially, the site will come to a standstill for 2 - 3 minues.

I don't like to jump to conclusions, but I still suspect maintenance. Here is another post that I think will be helpful.

http://www.eggheadcafe.com/articles/20060305.asp

So let's talk about how to get this HTTP module implemented on your site. Does the site run under a partial trust (e.g. Medium) scenario? The code as written writes to the windows event log which is a protected function. That is why they discuss putting it into the GAC. Since the error is intermittent, a suitable alternative might be to write out to a file.

EDIT: I should say, I suspect maintenance because the error is not otherwise trapped by the application. No entry in the app.log I assume. That seems to fit the scenario discussed in the article. Maintenance is launched on a separate worker thread.

[WylieE]

I don't like to jump to conclusions, but I still suspect maintenance. Here is another post that I think will be helpful.

http://www.eggheadcafe.com/articles/20060305.asp

So let's talk about how to get this HTTP module implemented on your site. Does the site run under a partial trust (e.g. Medium) scenario? The code as written writes to the windows event log which is a protected function. That is why they discuss putting it into the GAC. Since the error is intermittent, a suitable alternative might be to write out to a file.

EDIT: I should say, I suspect maintenance because the error is not otherwise trapped by the application. No entry in the app.log I assume. That seems to fit the scenario discussed in the article. Maintenance is launched on a separate worker thread.

We've put similar code in place to capture more error information. Nothing conclusive yet. BTW, you are correct. We are seeing nothing in the app log.

It is my understanding that maintenance runs on a regular schedule of every 5 hours by default. We're not seeing the crashes on a regular schedule. That had led me to discount the maintenance schedule being the culprit.

Here are the times of the last five crashes:
9/1/09 5:09AM
8/31/09 11:40AM
8/31/09 9:46AM
<no errors over the weekend, very odd>
8/28/09 1:46PM
8/28/09 10:14AM

No crashes today since 5AM. I have had perfmon running all day and am seeing #bytes in all heaps slowly and consistently climbing. (.Net CLR Memory). I'll let you know if w3wp crashes and the heap size drops.

Thanks Logan.

[WylieE]

No crashes today since 5AM. I have had perfmon running all day and am seeing #bytes in all heaps slowly and consistently climbing. (.Net CLR Memory). I'll let you know if w3wp crashes and the heap size drops.

We had a couple w3wp crashes yesterday. I compare the times with maintenance times in the app.log and there were no matches. I did see #bytes in all heaps consistently climb and then drop significantly after each pool reset.

This is very odd in that it seems to go in spurts. No errors for a day or so and then multiple in a short period of time.

[WylieE]

I don't like to jump to conclusions, but I still suspect maintenance. Here is another post that I think will be helpful.

http://www.eggheadcafe.com/articles/20060305.asp

So let's talk about how to get this HTTP module implemented on your site. Does the site run under a partial trust (e.g. Medium) scenario? The code as written writes to the windows event log which is a protected function. That is why they discuss putting it into the GAC. Since the error is intermittent, a suitable alternative might be to write out to a file.

EDIT: I should say, I suspect maintenance because the error is not otherwise trapped by the application. No entry in the app.log I assume. That seems to fit the scenario discussed in the article. Maintenance is launched on a separate worker thread.

Logan,

We have code like this in placed and are receiving regular emails. We're not getting anything relevant around the times of a w3wp reset.

We continue to average one or two pool resets a day and have been experiencing this for a long time. We need to get this resolved before we head in to the holiday season.

This has exceeded our skillset. Any recommendations for hardcore webserver/AC/SQL experts? Feel free to email me direct at eric@warmoth.com.

Thanks.

[jmestep]

This may or may not help. I've been reading thru a MS article on scaling .net applications for good performance and there might be some help in it. I remember very little of what I've read in it, but it has given me a good idea of where I might be able to find info. I tried to upload it here, but it is too large. It is MS Improving .NET Application Performance and Scalability -- Patterns & Practices.

[Logan Rhodehamel]

We have code like this in placed and are receiving regular emails. We're not getting anything relevant around the times of a w3wp reset.

Can you expand on this? The code I referenced shows how to set up a special HTTP Module that will intercept unhandled exceptions and send you a stack trace. When you say you have code like this in place, can you PM me what you have so I can determine what other options there might be?

[WylieE]

We have code like this in placed and are receiving regular emails. We're not getting anything relevant around the times of a w3wp reset.

Can you expand on this? The code I referenced shows how to set up a special HTTP Module that will intercept unhandled exceptions and send you a stack trace. When you say you have code like this in place, can you PM me what you have so I can determine what other options there might be?

Logan, you should have a PM from our programmer, Bryan.

[WylieE]

We are in the process of replacing our web server and our hosting company noticed the errors. They took a look and sent us some stack trace information. It doesn't make sense to me, but it might benefit someone else.

[afm]

Eric,

Without the request information (URL, method, etc) it is hard to even guess what these stack traces mean. But here's my guess:

There is a request for some page that uses the Category4 template. The template uses at least one scriplet (i.e. content) that has a part (usercontrol) that is expecting a querystring parameter (i.e. id) that is missing.

For example, perhaps you manually added a link to one of your categories on your home page, but you made a typo and spelled "id" as "jd". Then this is how the error might appear.

However, I sincerely doubt this error would cause your site to restart.

[triplw]

I have just started experiencing similar problems on my 7.0.3 site. I am getting runtime errors where I have to restart the application pool almost daily. Did anyone ever resolve this or have any additional info?

Thanks

[Logan Rhodehamel]

I have just started experiencing similar problems on my 7.0.3 site. I am getting runtime errors where I have to restart the application pool almost daily. Did anyone ever resolve this or have any additional info?

I may. I am in fact working on a problem with similar symptoms right now - this time a cause was identified and a solution is being tested.