Read a great blog entry by Scott Hanselman recently talking about the parallel dilemma that I’m sure we’ll see folks face in the future with the (old/new) Parallel classes.  I wanted to add a few things to this discussion as he focused on the mechanics of the parallel requests but maybe not the potential effects it could have on the macro view of your application.  This was originally written as an e-mail I sent to my team but thought others might find it interesting.

There will be an inclination by people to use the new Parallel functionality in .NET 4.0 to easily spawn operations onto numerous background threads.  That will generally be okay for console/winform/wpf apps – but could also be potentially bad for ASP.NET apps as the spawned threads could take away from the processing power and threads available to process new webpage requests.  I’ll explain more on that later. 

For example, by default, when you do something like Parallel.ForEach(…) or some such, the parallel library starts firing Tasks to the thread pool so that it can best utilize the processing power available on your machine (oversimplification but you get the idea).  The downside is that the thread pool contains a finite number of worker threads threads available to a process.  Granted, you have about 100 threads per logical processor in .NET 4 – but it’s worth noting.

While Scott’s entry talks about the new way to implement the Async pattern, I’ve already seen a bunch of folks use the “Parallel” class because it abstracts away some of the plumbing of the Async operations and that ease of use could become problematic. 

For example, consider this code:

string[] myStrings = { "hello", "world", "you", "crazy", "pfes", "out", "there" };


Parallel.ForEach(myStrings, myString =>

{


System.Console.WriteLine(DateTime.Now + ":" + myString + 


" - From Thread #" + 


Thread.CurrentThread.ManagedThreadId);

Thread.Sleep(new Random().Next(1000, 5000));


});

This is a very simple implementation of Parallel’izing a foreach that just writes some string output with an artificial delay.  Output would be something like:

11/16/2010 2:40:05 AM:hello - From Thread #10
11/16/2010 2:40:05 AM:crazy - From Thread #11
11/16/2010 2:40:05 AM:there - From Thread #12
11/16/2010 2:40:06 AM:world - From Thread #13
11/16/2010 2:40:06 AM:pfes - From Thread #14
11/16/2010 2:40:06 AM:you - From Thread #12
11/16/2010 2:40:07 AM:out - From Thread #11 

Note the multiple thread ids and extrapolate that out to a server that has more than just my paltry 2 CPUs.  This can be potentially problematic for ASP.NET applications as you have a finite number of worker threads available in your worker process and they must be shared across not just one user but hundreds (or even thousands).  So, we might see that spawning an operation across tons of threads can potentially reduce the scalability of your site.

Fortunately, there is a ParallelOptions class where you can set the degree of parallel’ism.  Updated code as follows:

string[] myStrings = { "hello", "world", "you", "crazy", "pfes", "out", "there" };


ParallelOptions options = new ParallelOptions();

options.MaxDegreeOfParallelism = 1;


Parallel.ForEach(myStrings,options, myString =>

{


// Nothing changes here

...


});

This would then output something like:

11/16/2010 2:40:11 AM:hello - From Thread #10
11/16/2010 2:40:12 AM:world - From Thread #10
11/16/2010 2:40:16 AM:you - From Thread #10
11/16/2010 2:40:20 AM:crazy - From Thread #10
11/16/2010 2:40:23 AM:pfes - From Thread #10
11/16/2010 2:40:26 AM:out - From Thread #10
11/16/2010 2:40:29 AM:there - From Thread #10

Since I set the MaxDegreeOfParallelism to “1”, we see that it just uses the same thread over and over.  Within reason, that setting *should* correspond to the number of threads it will use to handle the request. 

Applying to a website

So, let’s apply the code from the above to a simple website and compare the difference between the full parallel implementation and the non-parallel implementation.  The test I used ran for 10 minutes with a consistent load of 20 users on a dual-core machine running IIS 7.

In all of the images below, the blue line (or baseline) represents the single-threaded implementation and the purple line (or compared) represents the parallel implementation . 

We’ll start with the request execution time.  As we’d expect, the time to complete the request decreases significantly with the parallel implementation.

But what is the cost from a thread perspective?  For that, we’ll look at the number of physical threads:

As we’d also expect, there is a significant increase in the number of threads used in the process.  We go from ~20 threads in the process to a peak of almost 200 threads throughout the test.  Seeing as this was run on a dual-core machine, we’ll have a maximum of 200 worker threads available in the thread pool.  After those threads become depleted, you often see requests start getting queued, waiting for a thread to become available.  So, what happened in our simple test?  We’re look at the requests queued value for that:

We did, in-fact, start to see a small number of requests become queued throughout our test.  This indicates that some requests started to pile up waiting for an available thread to become available. 

Please note that I’m NOT saying that you should not use Parallel operations in your website.  You saw in the first image that the actual request execution time decreased significantly from the non-parallel implementation to the parallel implementation. But it’s important to note that nothing is free and while parallelizing your work can and will improve the performance of a single request, it should also be weighed against the potential performance of your site overall.

Until next time.

In my previous post, I added to my series of entries on making sense of your ASP.NET event log error messages.  Note that this is entry #4 in this series.  The previous three entries can be found here:

• Part 1:  Parsing ASP.NET event log error messages for fun and profit
• Part 2:  Don’t guess when it comes to performance…
• Part 3:  Pivoting your ASP.NET event log error messages

In that last post, I walked through the PAuthorLib.dll and showed you how to crawl through your event log error messages and create a pivot collection.  The result of that initial effort was a nice view into our events:

While this certainly got the job done and is a very powerful and compelling view into our data, we need to realize that as our data grow, the amount of entries in our linked collection is limited.  From the Developer Overview, we see that the maximum number of items we should have in a single collection is 3,000:

So, while a simple collection will get the job done for your smaller amounts of data, you will really run into some challenges with your larger datasets like our ASP.NET event log error messages.  To combat this limitation you can create what’s called a Linked Collection.  The idea is that it’s just a way for you to link together related collections in order to provide a seamless experience for your users.  In our case, a natural break for our collections will be based upon the exception type with a summary collection and then a separate collection for each exception type.  If I were to draw this out: 

Event Log Header Collection Source

The idea behind this structure is that the Exception summary would simply link to each of these exception collections.  First, we’ll create a colleciton source for our exception summary.  As in our previous collection source (in my last blog post), we inherit from the AbstractCollectionSource class and use the LoadHeaderData() method to add our facet categories to the collection.  In this case, we’ll create two categories – the number of Occurrences and the Urls where the exception occurred.  Another difference is that we are going to pass the already parsed collection of messages into the constructor.  The reason for that is so we don’t have to repeat the parsing of the event log messages multiple times.

class EventLogHeaderCollectionSource : AbstractCollectionSource

{


private IEnumerable<EventLogMessage> m_messages = null;


public EventLogHeaderCollectionSource(IEnumerable<EventLogMessage> messages, 


string inputFile)

: base(inputFile)

{


m_messages = messages;



}


#region Facets


private const string OCCURRENCES = "Occurrences";

private const string URLS = "Urls";


#endregion


protected override void LoadHeaderData()

{

this.CachedCollectionData.FacetCategories.

Add(new PivotFacetCategory(OCCURRENCES, PivotFacetType.Number));

this.CachedCollectionData.FacetCategories.

Add(new PivotFacetCategory(URLS, PivotFacetType.String));


this.CachedCollectionData.Name = 


"ASP.NET Error Messages - Summary";

this.CachedCollectionData.Copyright = 


new PivotLink("Source", "http://www.samuraiprogrammer.com");


}

}

Then, in the LoadItems() method, we provide the logic to generate the PivotItem collection.  The one key item to make note of is the use of the Href property of the PivotItem object.  This is where we specify the collection we wish to link to this item.  Since each of the PivotItems will be a summary of the number of each exception type – we’ll name the sub-collections by its exception type.  For example, NullReferenceException.cxml, SqlException.cxml, etc.

protected override IEnumerable<PivotItem> LoadItems()

{

var results = from log in m_messages

group log by log.Exceptiontype into l

orderby l.Count() descending, l.Key

select new

{

ExceptionType = l.Key,

ExceptionCount = l.Count()

};



int index = 0;

foreach (var result in results)

{

PivotItem item = new PivotItem(index.ToString(), this); 


item.Name = result.ExceptionType;

item.Description = "# of Exceptions: " + result.ExceptionCount.ToString();

item.AddFacetValues(OCCURRENCES, result.ExceptionCount);

item.Href = result.ExceptionType + ".cxml";


... 



index++;

yield return item;

}


yield break;

}

Event Log Collection Source Redux

Previously, when we generated the pivot collections, we were outputting all of the records into a single collection.  Now that we are generating a collection for each exception type, we will need to put a filter in our exception collection and then incorporate that filter into our item generation.  Other than that, the code we wrote previously remains largely unchanged, so I left the majority of it out and only included the snippets that we care about below.

class EventLogCollectionSource : AbstractCollectionSource

{

private IEnumerable<EventLogMessage> m_messages = null;

private string m_exceptionType = string.Empty;


public EventLogCollectionSource(

IEnumerable<EventLogMessage> messages, 


string exceptionType, 


string path)

: base(path)

{

m_messages = messages;

m_exceptionType = exceptionType;

}


protected override void LoadHeaderData()

{

...

this.CachedCollectionData.Name = 


string.Format("{0} Error Messages", m_exceptionType);

...

}


protected override IEnumerable<PivotItem> LoadItems()

{

var results = (from message in m_messages

where message.Exceptiontype == m_exceptionType

select message);


int index = 0;

foreach (EventLogMessage message in results)

{

PivotItem item = 


new PivotItem(index.ToString(), this);

item.Name = message.Exceptiontype;

item.Description = message.Exceptionmessage;


...


index++;

yield return item;

}

yield break;

}

}

Generate and test the collection

Then, the only thing we have left to do is generate and test our linked collections.  I won’t go into a lengthy explanation of how we generate the collections because I did that in the last blog entry.  I will show the broad strokes required to tie this all together, though:

// Load the raw messages into a collection

IEnumerable<EventLogMessage> messages = 


LoadEventLogMessages(inputFile).ToList();


// Generate summary pivot collection

EventLogHeaderCollectionSource sourceSummary = 


new EventLogHeaderCollectionSource(messages, inputFile);

...

summaryTargetFilter1.Write(sourceSummaryFilter1);


// Get the aggregate results so we know the filters

// for our exception pivot collections

var summaryResults = from log in messages

group log by log.Exceptiontype into l

orderby l.Count() descending, l.Key

select new

{

ExceptionType = l.Key,

ExceptionCount = l.Count()

};


foreach (var resultItem in summaryResults)

{

// Generate pivots for each exception type

EventLogCollectionSource source = 


new EventLogCollectionSource(messages, 


resultItem.ExceptionType, 


inputFile);

...

targetFilter1.Write(sourceFilter1);

}

Once we we have this code and everything has been generated, if we open the output folder, we’ll see the following structure:

We see our ExceptionSummary pivot collection and all of the deep zoom folders.  So, when we open the Pivot tool, we’ll see a nice parent collection:

This gives us a nice breakdown of the number of occurrences for each exception in our source data.  Immediately we see an outlier (more on that later) between the 6,000 and 7,000 item mark and when we select that tile, we see the following:

We also see a green “Open” box (surrounded in a red rectangle, my emphasis) which links to our NullReferenceException.cxml.  When we click that box, the tool will immediately open that collection in the UI for our perusal – providing a very similar look to what we saw in the last entry:

Closing Thoughts

Now, you may have noticed a contradiction above.  I said that a collection should have no more than 3,000 items and yet, with the NullReferenceException collection, we saw in the summary that it had over 6,000 items.  That is a very good point and will be a subject of a future blog post.  I wanted to illustrate the simple collections and the linked collections before we got into that third type of collection from above – the Dynamic Collection.  Stay tuned!

Unless you’ve been hiding under the proverbial rock, you’ve probably seen the recent Pivot hoopla.  If you’re not familiar with it, it’s a way to visualize a large amount of data in a nice filterable format.  The nice thing about it is that it’s really easy to put together a pivot collection and there are a ton of tools available for just this purpose.  Just do a search on CodePlex for Pivot and you’ll get about 40’ish good results for tools you can use to create a Pivot Collection. 

So, I was putting together a proof-of-concept for an internal project and thought I would continue on with my series of blog posts on ASP.NET Error Message event logs with a post on how to visualize this data using a pivot.  You may wish to read parts 1 and 2 here:

• Part 1:  Parsing ASP.NET event log error messages for fun and profit
• Part 2:  Don’t guess when it comes to performance…

So, when I put together my pivot, I worked out a 3 step process:

1. Figure out what you want to Pivot
2. Find an API and convert the data
3. Generate and Test the collection

Let’s begin, shall we.

Figure out what you want to Pivot

The structure for the Pivot Collection is deceptively simple -

<?xml version="1.0"?> 


<Collection Name="Hello World Collection" …>

<FacetCategories> 


<FacetCategory Name="Hello World Facet Category One" Type="String"/> 


</FacetCategories> 


<Items ImgBase="helloworld.dzc"> 


<Item Img="#0" Id="0" Href="http://www.getpivot.com"
Name="Hello World!"> 


<Description> This is the only item in the collection.</Description> 


<Facets> 


<Facet Name="Hello World Facet Category One"> 


<String Value="Hello World Facet Value"/> 


</Facet> 


</Facets> 


</Item> 


</Items> 


</Collection>

The way that I think about the Items in the Collection are in the same way that you might think about an object.  For example, a Car object might have the following properties:

• Advertising blurb
• Car and Driver Reviews
• Color
• Make
• Model
• Engine
• 0-60mph time
• Max Speed

The common values like the Color, Make, Model, 0-60mph time and max speed become the facets or attributes that describe your object in relation to other instances of objects.  Things like the advertising blurbs and car and driver reviews or descriptions belong instead as properties of your Item directly in the Description element.

For our data, namely ASP.NET exceptions, we’re going to define an exception as the following:

• Item
• Name = Exception Type
• Description = Exception Message
• Facets
• Request Path
• Stack Trace
• Event Time
• Top Method of Stack Trace
• Top My Code Method of Stack Trace

This should allow us to group and drill through the common properties that might link exceptions together and still provide detailed error information when necessary.

Find an API and code it

The second step here is to find some code/API/tool that we can enhance for our purposes.  There are some great tools published by the Live Labs team – for example:

• Pivot Collection Tool for the Command Line
• Pivot Collection Tool for Microsoft Excel

While both tools could be used in this instance, in part 2 we found that some of our Event Logs we were parsing contained more than 10,000 items and I wanted a bit more control over how I converted the data.  “No touching” is the phrase of the day.  Fortunately, the command line tool was published on CodePlex with an API we can use.  Once you download the product you see that it contains 3 assemblies:

The last item there is the PauthorLib.dll which encapsulates many of the extension points within this great tool.  In-fact, it exposes about 7 different namespaces for our purposes:

For our purposes, we are going to focus on the Streaming set of namespaces.  Why?  Well, this is namely because we are going to be dealing with a lot of data and I didn’t want to load everything into memory before writing it to disk.  If you look at the contents of the Streaming namespace, you’ll see a great class called “AbstractCollectionSource”.  This looks fairly promising because it exposes two main methods:

class EventLogExceptionCollectionSource : AbstractCollectionSource

{

protected override void LoadHeaderData()

{

throw new NotImplementedException();

}


protected override IEnumerable<PivotItem> LoadItems()

{

throw new NotImplementedException();

}

}

Before we do anything, though, we need a constructor.  The constructor will be responsible for taking a string representing the path to our data and passing it to our base class’s constructor.

public EventLogExceptionCollectionSource(string filePath)

: base(filePath)

{


// Do nothing else.


}

protected override void LoadHeaderData()

{


this.CachedCollectionData.FacetCategories.Add(

new PivotFacetCategory(STACKTRACE, 


PivotFacetType.LongString));

this.CachedCollectionData.FacetCategories.Add(

new PivotFacetCategory(REQUESTPATH, 


PivotFacetType.String));

this.CachedCollectionData.FacetCategories.Add(

new PivotFacetCategory(EVENTTIME, 


PivotFacetType.DateTime));

this.CachedCollectionData.FacetCategories.Add(

new PivotFacetCategory(TOPMETHOD, 


PivotFacetType.String));

this.CachedCollectionData.FacetCategories.Add(

new PivotFacetCategory(TOPAPPMETHOD, 


PivotFacetType.String));


this.CachedCollectionData.Name = "Event Log Error Messages";



}

The second method, LoadItems(), is responsible for doing exactly what it suggests – this is where we load the data from whichever source we care about and then convert it into our PivotItem collection.  For our purposes, we’re going to load the XML file we defined in Part 1 of this series into a list of EventLogMessage objects and then convert those EventLogMessage objects into PivotItem objects:

protected override IEnumerable<PivotItem> LoadItems()

{

// Load XML file

XDocument document = XDocument.Load(this.BasePath);


// Populate collection of EventLogMessage objects

var messages = from message in document.Descendants("Message")

select EventLogMessage.Load(message.Value);


int index = 0;

foreach (EventLogMessage message in messages)

{


PivotItem item = new PivotItem(index.ToString(), this);

item.Name = message.Exceptiontype;

item.Description = message.Exceptionmessage;

item.AddFacetValues(REQUESTPATH, message.Requestpath);

item.AddFacetValues(STACKTRACE, message.Stacktrace);

item.AddFacetValues(EVENTTIME, message.Eventtime);

item.AddFacetValues(TOPMETHOD, message.StackTraceFrames[0].Method);

item.AddFacetValues(TOPAPPMETHOD, GetFirstNonMicrosoftMethod(message.StackTraceFrames));


index++;

yield return item;


}

}

The key method calls from above are the AddFacetValues(…) method calls.  This method essentially sets the attributes we wish to have our data pivot upon.  This, by itself, isn’t enough to generate our great pivot calls – we need to call our code from somewhere.  Since this is a simple app, we’re going to make it a console app.  For our Collection to get generated we need to use a few other objects included in this API:

• EventLogExceptionCollectionSource – The class we created above.
• HtmlImageCreationSourceFilter – This class will generate the tile in the Pivot based upon some HTML template we specify.
• LocalCxmlCollectionTarget – Generates the Collection XML file at the path we specify.
• DeepZoomTargetFilter – Generates the deep zoom files to support our collection XML file and also enables all of our fancy transitions.

In practice, the code is pretty simple and straight forward and I applaud the people who wrote this library:

private static void GenerateExceptionPivot(string inputFile, string outputFolder)

{

string collectionName = Path.Combine(outputFolder, "MyExceptions.cxml");


EventLogExceptionCollectionSource source = 


new EventLogExceptionCollectionSource(inputFile);

HtmlImageCreationSourceFilter sourceFilter1 = 


new HtmlImageCreationSourceFilter(source);

sourceFilter1.HtmlTemplate = 


"<html><body><h1>{name}</h1>{description}</body></html>";

sourceFilter1.Width = 600;

sourceFilter1.Height = 600;


LocalCxmlCollectionTarget target = 


new LocalCxmlCollectionTarget(collectionName);

DeepZoomTargetFilter targetFilter1 = 


new DeepZoomTargetFilter(target);

targetFilter1.Write(sourceFilter1);


}

That last statement, targetFilter1.Write(…) is what will actually execute everything and write our resultant files to disk.

Generate and Test the collection

So, now if we run our console application and call that GenerateExceptionPivot(…) method, we’ll get some great output.

What’s nice about the Library is that it provides progress as it iterates through your data (in the red rectangle) and also in the blue rectangle, we need that it’s multi-threaded by default.  This is primarily for the most intensive part of the operation – the creation of the deep zoom artifacts.  If you have one of those new fangled machines with 2+ cores, you can tweak the number of threads that it will spawn for this operation by setting the ThreadCount property of the DeepZoomTargetFilter object.  This may or may not improve your performance but it’s nice that the option is available.

...

DeepZoomTargetFilter targetFilter1 = 


new DeepZoomTargetFilter(target);

targetFilter1.ThreadCount = 100;
targetFilter1.Write(sourceFilter1);

...

Once our collection has been generated, we can browse it in an explorer.exe window just to get an idea of what our code has wrought:

And then to test it, you can just point the Live Labs Pivot application at our “MyExceptions.cxml” file and view the wonderful data.  For example, you can look at the Event Time in the histogram view to see how your exceptions broke down over time.  You can also filter your data by things like the RequestPath (the page that threw the exception) or the Method that was at the top of the callstack.

Then, you can zoom in on a specific time slice you care about:

Then, if you want to view the details for a specific instance, just click the corresponding tile.  Then, a new side bar will appear on the right hand side with all of the details we stored in this record:

We generated a single collection in this blog post.  One thing to keep in mind is that each collection should have no more than 3,000 items.  For collections in which you want to have more than 3,000 items, you should look at potentially creating a Linked Collection.  That will be the subject of an upcoming blog post. 

Until next time!

Sometimes a customer will ask me to look at their site and make some recommendations on what can be improved.  One of the many things I’ll look at is their event logs.  One of the nice things about ASP.NET is that when you encounter an unhandled exception, an event will be placed into your Application event log.  The message of the event log entry will usually include lots of good stuff like the application, path, machine name, exception type, stack trace, etc.  Loads of great stuff and all for free.  For customers that don’t have a centralized exception logging strategy, this can be a gold mine.

The way it usually works is that they will provide me an EVTX from their servers.  If you’re not aware, an EVTX is just an archive of the events from the event log you specify.  By itself, looking at the raw event logs from a server can be quite daunting.  There are usually thousands of entries in the event log and filtering down to what you actually care about can be exhausting.  Even if you do find a series of ASP.NET event log messages, the problem has always been – how do you take all of this great information that’s just dumped into the Message property of the event log entry and put it into a format you can easily report on, generate statistics, etc.  Fortunately, I have a non-painful solution. 

I’ve broken this down into a relatively simple 4-step process:

• Get the EVTX
• Generate a useful XML file
• Parse into an object model
• Analyze and report on the data

Let’s get to it.

Step 1:  Get the EVTX

This step is pretty short and sweet.  In the Event Log manager, select the “Application” group and then select the “Save All Events As…” option. 

That will produce an EVTX file with whatever name you specify.  Once you have the file, transfer it to your machine as you generally do not want to install too many tools in your production environment.

Step 2:  Generate a useful XML file

Now that we have the raw EVTX file, we can get just the data we care about using a great tool called LogParser.  Jeff Atwood did a nice little write-up on the tool but simply put it’s the Swiss Army knife of parsing tools.  It can do just about anything data related you would wish using a nice pseudo-SQL language.  We’ll use the tool to pull out just the data from the event log we want and dump it into an XML file.  The query that we can use for this task is daunting in its simplicity:

            SELECT Message INTO MyData.xml
FROM ‘*.evtx’
WHERE EventID=1309

The only other thing we need to tell LogParser is the format in which it the data is coming in and the format to put it into.  This makes our single command the following:

C:\>logparser -i:EVT -o:XML

"SELECT Message INTO MyData.xml FROM ‘*.evtx’ WHERE EventID=1309" 

This will produce a nice XML file that looks something like the following:

            <?
            xml
            version
            ="1.0"
            encoding
            ="ISO-10646-UCS-2"
            standalone
            ="yes" ?>
<ROOTDATE_CREATED="2010-08-29
06:04:20"CREATED_BY="Microsoft
Log Parser V2.2">
<ROW>
<Message>Event
code: 3005 Event message: An unhandled exception has occurred... 

</Message>
</ROW>

...
</ROOT>

One thing that you may notice is that all of the nicely formatted data from our original event log message is munged together into one unending string.  This will actually work in our favor but more on that in the next step.

Step 3:  Parse into an object model

So, now that we have an XML file with all of our event details, let’s do some parsing.  Since all of our data is in one string, the simplest method is to apply a RegEx expression with grouping to grab the data we care about. 

In a future post, I’ll talk about a much faster way of getting this type of data without a RegEx expression.  After all, refactoring is a way of life for developers .

            private
            const
            string LargeRegexString
= @"Event code:(?<Eventcode>.+)" +
@"Event message:(?<Eventmessage>.+)" +
@"Event time:(?<Eventtime>.+)" +
@"Event time \(UTC\):(?<EventtimeUTC>.+)" +
@"Event ID:(?<EventID>.+)" +
@"Event sequence:(?<Eventsequence>.+)" +
@"Event occurrence:(?<Eventoccurrence>.+)" +
@"Event detail code:(?<Eventdetailcode>.+)" +
@"Application information:(?<Applicationinformation>.+)" +
@"Application domain:(?<Applicationdomain>.+)" +
@"Trust level:(?<Trustlevel>.+)" +
@"Full Application Virtual Path:(?<FullApplicationVirtualPath>.+)" +
@"Application Path:(?<ApplicationPath>.+)" +
@"Machine name:(?<Machinename>.+)" +
@"Process information:(?<Processinformation>.+)" +
@"Process ID:(?<ProcessID>.+)" +
@"Process name:(?<Processname>.+)" +
@"Account name:(?<Accountname>.+)" +
@"Exception information:(?<Exceptioninformation>.+)" +
@"Exception type:(?<Exceptiontype>.+)" +
@"Exception message:(?<Exceptionmessage>.+)" +
@"Request information:(?<Requestinformation>.+)" +
@"Request URL:(?<RequestURL>.+)" +
@"Request path:(?<Requestpath>.+)" +
@"User host address:(?<Userhostaddress>.+)" +
@"User:(?<User>.+)" +
@"Is authenticated:(?<Isauthenticated>.+)" +
@"Authentication Type:(?<AuthenticationType>.+)" +
@"Thread account name:(?<Threadaccountname>.+)" +
@"Thread information:(?<Threadinformation>.+)" +
@"Thread ID:(?<ThreadID>.+)" +
@"Thread account name:(?<Threadaccountname>.+)" +
@"Is impersonating:(?<Isimpersonating>.+)" +
@"Stack trace:(?<Stacktrace>.+)" +
@"Custom event details:(?<Customeventdetails>.+)";

Now that we have our RegEx, we’ll just write the code to match it against a string and populate our class.   While I’ve included the entire regex above, I’ve only included a partial implementation of the class population below.

            public
            class EventLogMessage

{

privatestatic Regex
s_regex = new Regex(LargeRegexString, RegexOptions.Compiled);

publicstatic EventLogMessage
Load(string rawMessageText)

{


Match myMatch = s_regex.Match(rawMessageText);

EventLogMessage message = new EventLogMessage();

message.Eventcode = myMatch.Groups["Eventcode"].Value;

message.Eventmessage = myMatch.Groups["Eventmessage"].Value;

message.Eventtime = myMatch.Groups["Eventtime"].Value;

message.EventtimeUTC = myMatch.Groups["EventtimeUTC"].Value;

message.EventID = myMatch.Groups["EventID"].Value;

message.Eventsequence = myMatch.Groups["Eventsequence"].Value;

message.Eventoccurrence = myMatch.Groups["Eventoccurrence"].Value;

...
return message;

}

publicstring Eventcode
{ get; set; }
publicstring Eventmessage
{ get; set; }
publicstring Eventtime
{ get; set; }
publicstring EventtimeUTC
{ get; set; }
publicstring EventID
{ get; set; }
publicstring Eventsequence
{ get; set; }
publicstring Eventoccurrence
{ get; set; }

...

}

The last step is just to read in the XML file and instantiate these objects.

XDocument document = XDocument.Load(@"<path
to data>\MyData.xml");


var messages = from message in document.Descendants("Message")

select EventLogMessage.Load(message.Value);

Now that we have our objects and everything is parsed just right, we can finally get some statistics and make sense of the data.

Step 4:  Analyze and report on the data

This last step is really the whole point of this exercise.  Fortunately, now that all of the data is an easily query’able format using our old friend LINQ, the actual aggregates and statistics are trivial.  Really, though, everyone’s needs are going to be different but I’ll provide a few queries that might be useful.

Query 1:  Exception Type Summary

For example, let’s say you wanted to output a breakdown of the various Exception Types in your log file.  The query you would use for that would be something like:

var results = from log in messages

group log by log.Exceptiontype into l

orderby l.Count() descending, l.Key

select new

{

ExceptionType = l.Key,

ExceptionCount = l.Count()

};

foreach (var result in results)

{


Console.WriteLine("{0} : {1} time(s)", 


result.ExceptionType, 


result.ExceptionCount);


}

This would then output something like:

WebException : 15 time(s)

InvalidOperationException : 7 time(s)

NotImplementedException : 2 time(s)

InvalidCastException : 1 time(s)

MissingMethodException : 1 time(s)

Query 2:  Exception Type and Request URL Summary

Let’s say that you wanted to go deeper and get the breakdown of which URL’s generated the most exceptions.  You can just expand that second foreach loop in the above snippet to do the following:

            foreach (var
result in results)

{


Console.WriteLine("{0} : {1} time(s)", 


result.ExceptionType, 


result.ExceptionCount);


var requestUrls = from urls in messages
where urls.Exceptiontype == result.ExceptionType

group urls by urls.RequestURL.ToLower() into url

orderby url.Count() descending, url.Key

select new

{

RequestUrl = url.Key,

Count = url.Count()

};

foreach (var url in requestUrls){


Console.WriteLine("\t{0} : {1} times ",

url.RequestUrl,

url.Count);

} 


}

This then would produce output like this:

WebException  : 15 time(s)

http://localhost/menusample/default.aspx : 11
times

http://localhost:63188/menusample/default.aspx
: 4 times

InvalidOperationException : 7 time(s)

http://localhost:63188/menusample/default.aspx
: 6 times

http://localhost/menusample/default.aspx : 1 times

NotImplementedException : 2 time(s)

http://localhost/samplewebsiteerror/default.aspx
: 2 times

InvalidCastException : 1 time(s)

http://localhost:63188/menusample/default.aspx
: 1 times

MissingMethodException : 1 time(s)

http://localhost:63188/menusample/default.aspx
: 1 times

Query 3:  Exception Type, Request URL and Method Name Summary

You can even go deeper, if you so desire, to find out which of your methods threw the most exceptions.  For this to work, we need to make a slight change to our EventLogMessage class to parse the Stack Trace data into a class.  First, we’ll start with our simple little StackTraceFrame class:

            public
            class StackTraceFrame

{
publicstring Method
{ get; set; }


}

Second, add a new property to our EventLogMessage class to hold a List<StackTraceFrame>:

            public List<StackTraceFrame>
StackTraceFrames { get; set; }

Lastly, add a method (and its caller) to parse out the stack frames and assign the resulting List to the StackTraceFrames property mentioned above:

            public EventLogMessage(string rawMessageText)

{

Match myMatch = s_regex.Match(rawMessageText);

...

Stacktrace = myMatch.Groups["Stacktrace"].Value;

...

StackTraceFrames = ParseStackTrace(Stacktrace);

}

private List<StackTraceFrame> ParseStackTrace(string stackTrace)

{

List<StackTraceFrame> frames = new List<StackTraceFrame>();
string[] stackTraceSplit = stackTrace.Split(newstring[]
{ " at " }, 


StringSplitOptions.RemoveEmptyEntries);
foreach (string st in stackTraceSplit)

{
if (!string.IsNullOrEmpty(st))

{

frames.Add(new StackTraceFrame() { Method = st
});

}

}
return frames;

}

Please Note:  You could enhance the ParseStackTrace(…) method to parse out the source files, line numbers, etc. I’ll leave this as an exercise for you, dear reader.

Now that we have the infrastructure in place, the query is just as simple.  We’ll just nest this additional query inside of our URL query like so:

            foreach (var
url in requestUrls){


Console.WriteLine("\t{0} : {1} times ",

url.RequestUrl,

url.Count);


var methods = from method in messages
wherestring.Equals(method.RequestURL, 


url.RequestUrl, 


StringComparison.InvariantCultureIgnoreCase) 


&&
string.Equals(method.Exceptiontype, 


result.ExceptionType, 


StringComparison.InvariantCultureIgnoreCase)

group method by method.StackTraceFrames[0].Method into mt

orderby mt.Count() descending, mt.Key

select new

{

MethodName = mt.Key,

Count = mt.Count()

};

foreach (var method in methods)

{

Console.WriteLine("\t\t{0} : {1} times ",

method.MethodName,

method.Count

);

}

} 

This would then produce output like the following:

WebException  : 15 time(s)

http://localhost/menusample/default.aspx : 11 times

System.Net.HttpWebRequest.GetResponse() : 11 times

http://localhost:63188/menusample/default.aspx : 4 times

System.Net.HttpWebRequest.GetResponse() : 4 times

InvalidOperationException : 7 time(s)

http://localhost:63188/menusample/default.aspx : 6 times

System.Web.UI.WebControls.Menu... : 6 times

http://localhost/menusample/default.aspx : 1 times

System.Web.UI.WebControls.Menu... : 1 times

One last thing you may notice is that the in the example above, the first frame for each of those exceptions are somewhere in the bowels of the .NET BCL.  You may want to filter this out even further to only return YOUR method.  This can be accomplished very easily with the method below.  It will simply loop through the StackTraceFrame List and return the first method it encounters that does not start with “System.” or “Microsoft.”.

            private
            static
            string GetMyMethod(List<StackTraceFrame>
frames)

{

foreach (StackTraceFrame frame in frames)

{

if (!frame.Method.StartsWith("System.")
&&

!frame.Method.StartsWith("Microsoft."))
return frame.Method;



}

return"No User
Code detected.";

}

Then, you can just call that method from the new query we wrote above:

var methods = from method in messages
where ...

group method by 


GetMyMethod(method.StackTraceFrames) into mt

...

Finally, with this new snippet in place, we’ll get output like this:

WebException  : 15 time(s)

http://localhost/menusample/default.aspx : 11 times

_Default.Page_Load(Object sender, EventArgs e)...: 8 times

No User Code detected. : 3 times


http://localhost:63188/menusample/default.aspx : 4 times

_Default.Page_Load(Object sender, EventArgs e)... : 1 times

No User Code detected. : 1 times

WebControls.CustomXmlHierarchicalDataSourceView.Select()... : 2 times

As you can see, the sky’s the limit.

Enjoy!

In my job as a PFE for Microsoft, I read, review and fix a lot of code.  A lot of code.  It’s a large part of what I love about my job.  The code is generally written by large corporations or for public websites.  Every now and again I’ll get pinged on an issue and after troubleshooting the issue, it’s pretty clear that the core issue is with some community code.  When I say community code, in this instance, I don’t mean a CodeProject or CodePlex project.  In this case, I am referring to a control that Denis Bauer created and then made available to the community on his website – the “DynamicControlsPlaceholder” control.  This is a great little control that inherits from a PlaceHolder and allows you to  create dynamic controls on the fly and then it will persist the controls you add on subsequent requests – like a postback.

The Problem

The customer was experiencing a problem that could only be replicated in a web farm when they don’t turn on sticky sessions.  They found that when a request went from one server to another server in their farm they would get a FileNotFoundException with the following details:

Type Of Exception:FileNotFoundException

Message:Error on page http://blahblahblah.aspx

Exception Information:System.IO.FileNotFoundException: 


Could not load file or assembly 'App_Web_myusercontrol.ascx.cc671b29.ypmqvhaw, 


Version=0.0.0.0, Culture=neutral, PublicKeyToken=null' or one of its dependencies. 


The system cannot find the file specified.

File name: 'App_Web_myusercontrol.ascx.cc671b29.ypmqvhaw, 


Version=0.0.0.0, Culture=neutral, PublicKeyToken=null'

at System.RuntimeTypeHandle.GetTypeByName(String name, 


Boolean throwOnError, 


Boolean ignoreCase, 


Boolean reflectionOnly, 


StackCrawlMark& stackMark)

...

at DynamicControlsPlaceholder.RestoreChildStructure(Pair persistInfo, 


Control parent)

at DynamicControlsPlaceholder.LoadViewState(Object savedState) 


at System.Web.UI.Control.LoadViewStateRecursive(Object savedState)

...

at System.Web.UI.Control.LoadViewStateRecursive(Object savedState)

at System.Web.UI.Page.LoadAllState()

at System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, 


Boolean includeStagesAfterAsyncPoint)

So, we can gleam a few things from the error details:

• They are using the ASP.NET website model (the “app_web_….dll” assembly is the clue).
• The error is occurring in the RestoreChildStructure method of the DynamicControlsPlaceholder control.

The Research

The way that ASP.NET Websites work is that each component of your site can be compiled into a separate assembly.  The assembly name is randomly generated.  This also means that on two servers, the name of the assemblies can end up being different.  So, an assumption to make is that something is trying to load an assembly by its name.  If we look at the RestoreChildStructure method, we see the following:

            

Type ucType = Type.GetType(typeName[1], true, true);

try

{

MethodInfo mi = typeof(Page).GetMethod("LoadControl", 

new Type[2] { typeof(Type), typeof(object[])
});

control = (Control) mi.Invoke(this.Page, newobject[2]
{ ucType, null });

}
catch (Exception e)

{
thrownew ArgumentException(String.Format("The
type '{0}' …", 


ucType.ToString()), e);

}

The important thing to look at here is the Type.GetType(…) call.  Since the code for the control is in a separate assembly from everything else, the “typeName[1]” value MUST BE A FULLY QUALIFIED ASSEMBLY NAME.  From the exception details, we can see that it is attempting to load the type from the following string:

App_Web_myusercontrol.ascx.cc671b29.ypmqvhaw, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null

The “typeName[1]” variable is loaded from ViewState because that’s where the control persists its child structure.  So, for some reason the fully qualified assembly name is stored in ViewState.  If we look at the code that inserts the value into ViewState (in the PersistChildStructure(…) method), we see:

            

typeName = "UC:" + control.GetType().AssemblyQualifiedName; 

So, here we see the AssemblyQualifiedName is being stored into ViewState – which is then used to persist the controls across postback using the above code.  As I mentioned, this won’t work with an ASP.NET website hosted in a web farm because the assembly qualified name will probably be different from server to server.  We even have a KB article that discusses this issue somewhat. 

The Fix

Fortunately, the fix is pretty simple. 

First, we need to store the path to the User Control instead of the AQN in ViewState.  To do this, you can comment out the “typeName = ….” line from directly above and replace it with:

            

UserControl uc = control as UserControl;

typeName = "UC:" + uc.AppRelativeVirtualPath;

So, now we store the path to the UserControl in ViewState.  Then, we need to fix the code that actually loads the control.  Replace the code from above in the RestoreChildStructure(…) method with this code:

            

            string path = typeName[1];

try

{

control = Page.LoadControl(path);

}
catch (Exception e)

{
thrownew ArgumentException(String.Format(
"The type '{0}' cannot be recreated from ViewState", 


path), e);

}

That’s all there is to it.  Just load the user control from where it is being stored in the site and ASP.NET will take care of loading the appropriate assembly.

Enjoy!