ASP.NET, Azure, Database, EntityFramework Performance Pointers

Introduction

Over the last few years, I’ve been involved in optimizing performance in a respectable amount of projects made by a lot of different developers. The quality of the codebase in each project has varied from the posterchild for best practice architecture to pure and utter insanity involving a mix of SQL queries being constructed inline in ASP.NET pages.

An interesting thing I’ve found is that the architectural patterns aren’t really indicative of the project’s overall performance. Regardless of “good” or “bad” code, there are mistakes being made, methods needing optimization and databases needing to work more than they should.

I want to make a post here and describe the most common issues, and steps one can take to fix these issues and make the world a much better and faster world.

I’m mentioning Azure in this topic as I’ve been involved in migrating and/or improving performance for quite a few Azure sites. The perceived initial reaction on migration is generally that “Azure is slow!” which usually tends to be indicative of a bigger problem. The fact is that Azure works fine, but it highlights the performance bottlenecks in an application, especially when it comes to database access. An on-site local database server will most likely be a lot more forgiving than an azure DTU-plan.

In general nowadays there are two main areas which end up as bottlenecks performance-wise, web-server or database-server. The Web-server can end up being the bottleneck if you have a lot of CPU bound operations, such as repeated loops to populate objects with various information or simply preparing and padding large amounts of data. The database server can have similar CPU-issues, usually as a result of complex queries, procedures/long running jobs or simply excessive amounts of queries. In addition there’s the possibility of huge amounts of data being requested, which might not be CPU-intensive, but it will cause the application to wait for a longer period of time while the data is being transferred.

I’d say that roughly 80% of performance issues I’ve dealt with are related to interactions with the database server, if you’re experience issues in your application, that’s usually the best place to start looking. Note that this doesn’t mean that things can be fixed exclusively on the server, in most cases it’s the actual code that needs to be modified to improve performance. To troubleshoot these issues you need to have a good grasp of SQL, know what queries are reasonable, and how execution plans work.

Database Performance

The primary tool you want to use to locate most of these issues is an SQL Profiler. I’d recommend using an actual SQL database profiler such as Microsoft’s SQL Server Profiler instead of the pseudo-profilers that are attached to ASP.NET applications, as the latter can’t measure database statistics like reads/writes/CPU, only duration. They’re also in my experience not 100% reliable in cases where you have threads/tasks or other web-requests firing off database queries.

I’m not going to write any pointers about how to fix issues exclusive to the SQL server as this requires more knowledge than simple pointers. In general though, these problems are usually related to missing indexes, complex procedures and inefficient views, which you would already require a good understanding of databases in general to improve, and most importantly, not make worse.

Entity Framework (EF)

I’m generally in favor of using EF as an OR/M, and I’m describing specific scenarios with EF here in detail. The concepts will most likely translate to other OR/Ms or data-access strategies as well. EF simplifies data-access, but you need to be aware of how it does this to generate code which will translate well into SQL. On a side-note, if you’re one of the people claiming that EF (or most mainstream OR/Ms) is “slow and horrible”, there’s a good chance you’re doing something in an inefficient way. Just because you can stab yourself with a pair of scissors, doesn’t mean it’s not extremely useful for cutting paper.

These pointers are based on actual real world issues I’ve come across.

Simplify complex LINQ EF queries – “Just because LINQ accepts it, doesn’t mean it’s a good idea!

Some of the queries I’ve seen generated tend to get slightly over the top complex when it’s translated into SQL. When you’re trying to obtain data from the database, be as straight-forward as you can, don’t try to do something extremely fancy. If you need to join in data from all over the place, group and summarize bits of it, filter parts of it and only retrieve a tiny bit of information – you should consider a dedicated Stored Procedure, or splitting parts of the LINQ EF query into pieces to make it easier on the database. These issues are usually found by looking for high CPU/Reads in SQL Profiler.

Include related tables when relevant – “Lazy-loading means the database gets busy!

When you’re querying a table, and always use the related tables, consider adding .Include(relatedTable) to ensure the related entities are already loaded rather than querying them individually. If you query a list of products and always want to access their metadata in another table, including that would prevent you from performing X+1 selects where X is the list of products.

Don’t *always* include related tables – “Too much data makes everything slow!

If you’re querying a table with a 1:VeryMany relation, the way EF handles this is by doing a standard join. This means that the data in the 1-part of the relation will be duplicated X amount of times before it’s transmitted from the database server. If there are enough rows combined, especially if the table being duplicated has a ton of data, this will often cause delays. If you’re only retrieving a single row, simply removing the include statement will cause it to lazy-load the needed data fairly efficiently. If you have a lot of rows returned, you will run into the issue in the previous paragraph which creates a lot of queries during lazy-loading. In this case, it can be beneficial to eagerly manually load the related entities, by first retrieving the rows in the primary table, then retrieving the rows from the joined table, using the ids from the first table as a parameter, then connecting the rows manually.

Only include the data you need for large queries – “YAGNI!

For large queries where you only want some information and don’t need the full entities, try to create queries where you only select the properties relevant for your operation. This is generally done when you end up requesting so much data that you see a noticeable delay on the data transfer from the server. Populating a wrapper-object directly from the IQueryable can greatly increase performance in these scenarios.

Don’t post-filter the query in code – “Think of the network!

I’ve seen countless examples of cases where a query is done to retrieve data, only to have the next line of code ignore most of the data retrieved. If you’re implementing a restrictive filter, try your best to restrict it in the actual query to ensure that only the relevant information comes back. The worst case here is when people perform a ToList() on the base query to retrieve the entire table, and then filter. This happens more often than people think.

Group similar restrictive queries into one – “I know what I just said!

Despite the previous paragraph, there are a fair few queries that should be combined if possible. As an example, I’ve seen a *lot* of instances where some information is selected by a given status, then subsequent queries do the same thing with a different status. In these instances, it’s beneficial to group them together and share the result so you only perform one trip to the database.

Avoid the same queries in the same scope – “… but it’s so much easier!

In the more complex systems in the real world, where there’s more than an open connection and retrieve the hello world text, there’s often the chance that the same query is being requested several times by different controls during the same request. As an example, a web-site could require bits of customer information several places on the same page, which end up being located in different controls with no real knowledge of each other. Make your DAL able to share this information if it’s already been requested within the same page request without requiring additional database trips.

Don’t convert database types in queries – “… but it looks good in LINQ!

When you have types that don’t match, such as string value that is holding a number that you want to use to filter on ids, make sure that you convert the code type to the database type, ideally before the query. I’ve seen examples where these filters have been done the other way around, which creates a query where the SQL server needs to convert all the ids in the table to another format before it can perform the comparison and filter.

Stored Procedures can still be used – “… but it’s so boring to add to the model!

Keep Stored Procedures as a tool in your toolbox even with an OR/M, as it’s still extremely useful in the right scenarios. Typically if you have batch updates, cross-database joins, complicated reports or other larger sets of data that needs information from all over the database, it’s a good call to utilize a Stored Procedure over trying to complicate matters with the world’s largest LINQ-query. Keep in mind that it needs to be maintained independent of the solution and creates a slightly bigger maintenance overhead as a result, so it’s not something you’d want to do for most things, but keep it in mind for the special scenarios.

Know the difference between a Queryable/DbSet and a List – “… but they look alike …

Keep in mind when you design your DAL-strategy how far up you want to pass the Queryables. Make sure that everyone working with them knows when an actual query is being performed against the database, and knows that a List is something that has already been populated from the database. This is quite essential when lazy-loading comes into play, and making conscious decisions about when to filter data.

Cache static data – “… but we need changes NOW!

The biggest resource-saver is implementing some sort of caching mechanic for the frequently accessed data. In general, configuration-type data, type-tables and other data that only changes during deployments can be cached indefinitely, either through normal MemoryCache means or having the data in a static container. The issue comes when the frequently accessed data can change, at which point you need to determine on a case by case basis how long you can get away with caching data. From experience, no businesses want caching, they just want the performance that comes from it.

Web Server/Application

When the performance bottleneck is located in the web server area, symptoms include a very high CPU utilization on the server, there’s usually not a generic suggestion to fix it. You can diagnose issues by figuring out which areas are frequently accessed, which methods are frequently run, add diagnostic/time logging and check recently changed code areas if it’s a new issue.

There are, however, a few common scenarios which are easy to fix that often will cause these problems.

IEnumerables filtering in other lists

In larger datasets, there is an issue where you pass in an IEnumerable and filter it inside the query of another list or enumerable, as this will potentially cause the enumeration to happen for every other entity it’s being filtered on. A relatively simple query if you had been using a List would instead become an exponential CPU-nightmare. I strongly recommend using ToList() instead of enumerables in these cases for performance reasons, and in just about every other case for similar reasons. For further optimization, make sure you filter out the entities you know won’t be a match before doing the multiple query filtering, the fewer available entities to choose from the better.

Preparing cached objects for presentation

When you have frequently accessed objects, be it cached entities from the database or simpler objects, make sure you cache them as “prepared” for presentation as they can be. Given that they’re actually cached means they’re accessed fairly often. If you then need to do post-processing on these objects, for instance localize them, grab other information from other cached objects and so on – that becomes a costly process which should be replaced by caching the object *after* you have performed these operations.

Looping through large lists

If you know you have large lists of objects (say 50,000+), finding an object even if the list is cached might seem quick, but when these collections get accessed excessively without thought, this becomes a major CPU-drain. If you’re using a lookup based on an id for a large list, I strongly recommend using a dictionary with the id as the key, as this will improve performance by several magnitudes in these scenarios.

General loops

Whenever you loop there’s a chance that things don’t exactly go as smooth as you want. If you have performance issues, go through each line in a loop and make sure you don’t do anything costly. A few simple pointers include cutting the loop as quickly as you can, move as much code out of the loop as possible, ensure that you’re aware of anything performing database lookups and always test it with a worst case scenario number of items – as that’s how much it needs to be able to handle.

Summary

There’s a lot of different pitfalls when it comes to performance and even the best intentions can cause issues. Especially in high-performing/high-request applications even the slightest change can have major effects on the performance and stability of an application – and it’s in everyone’s best interest to ensure that developers are informed and keep this in mind while developing code.

Azure makes this a very interesting problem given that you’re now technically paying more upkeep (literally) when the code is performing badly. With this in mind it’s extremely important to keep your application from doing just that, as the price jump from one tier to the next can be quite noticeable on your monthly reports.

The good news is that it’s usually relatively straightforward to fix issues related to performance once you’re familiar with what’s causing it, and I do believe most software systems should be quite capable of running on the lower tiers of Azure with optimized code.

To end with some self-promotion at the end, if you *do* need help with performance in your EF or general .NET application, head over to http://ignitiondevelopment.co.nz/ and leave a message.

Entity Framework - Code First or Database First?

One of the questions that tends to pop up in most new (and old) .NET projects using Entity Framework nowadays, is which approach to go for, either having a Code First approach, or Database First.

The Code First approach is relatively new, and gives developers the ability to essentially forget that there's a database involved, you simply create the classes you want to be represented as database tables, add properties to related classes, and the framework generates all the required tables, constraints and you never even have to know what SQL is to be up and running.

On the other hand, the Database First approach involves you creating the data model in the database, normally using either SQL Management Studio or some other tool, creating all tables, specifying values and adding on Primary Keys, Foreign Keys and various constraints if needed, the framework then extracts the database schema, and creates the .NET classes for you.

Apart from this process, the development is pretty much exactly the same, and developers working at the higher tiers don't have to know which approach was used, as they would use the generated code in the exact same way regardless.

Why then does it matter? Where is the difference?

For developers, the ease of access by never having to use any database tools gives Code First immediately an advantage over DB First. It's quite simply much easier and quicker to add a property to a class in the code than it is to add a column to a table, as you generally then also need to generate a database script to be able to use the added column in production, as well as regenerating the model once the column is added, while all this is covered automatically by Code First and its "Migrations" for database changes.

For DBAs, well, if you have DBAs in your organization or projects, as a developer you likely don't have much say in the matter, and projects will be DB first regardless. However, if you're a developer, you might want explicit control over how the data model looks and how it is constructed, and the best way to do this, is to do it at the database level.

What to choose then?

Personally, all my recent personal projects are Code First, and I don't see that changing any time soon. I might also endorse this approach for limited team projects or smaller data storage projects, but that's where it ends. For any major team effort, or major high-performing data storage project, I simply can't encourage this approach as opposed to creating the database first.

I will start off my reasoning by saying that in my career, I've generally been the go-to guy when something feels sluggish, or a page is slow. I'm just as comfortable looking at SQL as I am looking at code, and I've come to realize that I'm not the typical developer due to my high focus on performance which involves among other things always keeping SQL Profiler running on a second monitor while I'm developing and testing.

When I use Code First, I always verify the migration scripts thoroughly, verify the migration scripts, ensure that it's doing *exactly* what I want it to do. It's very easy, especially with relationships, to mess up and add unintended columns, join tables and lacking foreign keys by accident if you don't have the right attributes on your classes. I also verify that everything looks alright in SQL Management Studio once the changes have been made. 

This is the bare minimum I'd expect *anyone* to do if they're serious about their development work. The problem here is that most developers won't do this. It's an unfortunate fact for those of us who "live and breathe" development, you know the type - we get twitchy eyes and blood boiling when we see someone using a capitalized variable name for a scope variable, messing up the code "feng shui" that's implicit when we open any solution - not everyone is like this. For some (most?) this is "just a job", where the goal is to simply be done with your tasks/backlogs/defects in a timely manner and cash your paycheck. This is a reality of life, all developers are different, and I'm not saying everyone should be the embodiment of Code Complete 2nd edition, just that you should expect and anticipate that some developers want to do exactly what they're tasked with in the least complicated matter regardless of the implications.

As such, for general development in major projects and/or high performing solutions, I will strongly recommend database first. The developers who may not know how to do anything in SQL shouldn't be tasked with model changes that could potentially hugely affect database performance regardless. Leave that to the people who can and, most importantly, care about the overall health of the model and the performance of the database.

Common Entity Framework Errors and Performance Tips

I wanted to write a quick entry about Entity Framework and just point out some of the errors I’ve been asked to resolve, and some of the worst uses of EF I’ve seen performance-wise. All of these are done with the default EF4.0 settings and default entities with foreign keys exposed.

 

I should note that there are probably a ton of errors more frequent than these in the world, but this is based on my personal experience supervising and helping others use Entity Framework. If you have an error which keeps happening with your EF-application, add it to the comments below and I’ll try to write something about it in a future post.

 

Entity Framework Errors

System.InvalidOperationException: The relationship between the two objects cannot be defined because they are attached to different ObjectContext objects.

This error appears when you use entity objects from different contexts when specifying relations and attempt to persist the changes to the database, seeing how the state of the two objects are maintained by two different context instances, they can’t really know the exact state of the other object, and as such, refuse to go along with it. Typically this happens in real situations when you cache an entity or simply have a project which is designed to use more than one ObjectContext.

 

The best way to resolve this is to be consistent in terms of assigning related entities. For the most part I would recommend exposing the foreign key column and setting the id of the related entity directly rather than specifying the entire entity. When this isn’t an option, you either have to refresh the entity in the same context as the entity you want to add relations to, or explicitly detach the entity from its old context and attach it to the new one. The latter of these could be dangerous if it’s also referenced by its old context, so make sure you know what you’re doing if you go with that approach.

 

System.ObjectDisposedException: The ObjectContext instance has been disposed and can no longer be used for operations that require a connection.

This appears most often when you try to lazy-load entities related to an ObjectContext instance which has been disposed one way or another. I’ve seen quite a few instances of code which is similar to this approach:

 

 

which will subsequently die horribly due to the disposed context as a result of the using block. The typical real case scenario here is that you have a function which will return a list of products, then that list will be databound to a listview in a web application, and ProductModel.Name is evaluated there, resulting in much anger directed towards Entity Framework in general and a lot of creative workarounds as the deadline approaches.

 

To resolve this peacefully, a few different approaches should be considered. First off, if you maintain your ObjectContext in a way which lets the garbage collection deal with the entities, you shouldn’t have this problem at all unless you explicitly detach objects, resulting in you getting a nullreference exception instead of this exception.

 

If you explicitly dispose the context like it’s done here, you should always ensure that you have all the information you need by the time the context is disposed. If you work with more complex relations, you might want to consider creating some wrapper classes and populate them with all information needed, or simply specify include hints in the retrieval of the original object.

 

Entity Framework Common Performance Tips

First off, I would like to just mention that you really should run SQL Profiler or something to that extent while developing your EF-applications, especially if you’re new at this and not entirely sure what happens behind the scenes when you design your elegant LINQ queries. The ease of developing using Entity Framework as your data-layer comes with a certain responsibility to at least try to make efficient code. I also know some DBA types who really want to avoid the use of any O/RM due to the SQL it generates, so please think of the overall reputation of EF and try to keep things optimized. Again, these issues and suggestions I post here are based on my personal experiences with Entity Framework and optimizing actual code.

 

Do not ToList() before filtered iteration

Even though this one is a simple one, I’ve seen it slip through quite a few times. The standard way of messing up this way is to specify a query, add .ToList() to perform the query, and then filter it as we’d only want to see the first 500 entries regardless. When you’re developing on your own PC with a local SQL-server, you don’t really notice anything unless you’re profiling at the same time. In reality, you’re retrieving the entire table before you’re applying the filter, resulting in a lot more data transferred than what’s needed. Simply put, make sure you filter/select before you .ToList() a collection for re-use.

 

Related collections are *not* IQueryables

Something which is easy to forget, even if you laughed at the above point, is that the related collections when you have a one to many relationship are not IQueryables, but DataCollections. As a result of this, if you have a customer object and want to display his order number 123, doing customer.Order.Where(o=>o.OrderId == 123) is the same as retrieving all the orders for that customer from the database, then looking through the collection to find the right one. Rewrite this to retrieve the order based on both customerId and orderId to ensure you don’t end up with a lot more data than you need.

 

Be *very* careful when putting entities in ViewState

Avoid this as best you can, if you have to maintain objects in this fashion, try to make wrapper classes. Having the full entities in viewstate tend to be fairly huge compared to the relevant information that you want to keep track of, not to mention that if you have relations included, this will grow even bigger.

 

Avoid instantiating unnecessary ObjectContext-instances.

This is more of a CPU-performance issue, as the cost of creating the context is fairly high, so try to limit these and re-use a context as best you can, please do not put these things inside loops or loop-like scenarios such as partial class properties.

 

Includes

As EF4 rolled in and people could lazy-load without worrying about what was actually in the current context, it seemed to have the added effect of making developers a bit more lazy as well. The typical scenario where you really notice the improvement of a well placed include or two comes when you load up a decent set of data and databind it in an application, evaluating left and right across relations in the database, and EF simply serves up the data without any question at all.

 

It’s also very hard to give specific and definitive suggestions regarding when to use includes and when not to, as every situation tends to be different. Also, you need to consider whether or not this is for general use, or if it’s very specific for your one little area of code.

 

 

Here’s an example of 3 different ways to do the same thing, only difference is the amount of data being transferred and the amount of queries/stress being put on the SQL Server. For this example I want a report of 1000 sales from the AdventureWorks database, and I simulate requiring information from two related tables similar to how I’d do it with a report displayed nicely in a listview.

 

Now, the first method is slightly hard on my database with the amount of queries it’s performing, while the second one is the kindest, as it only requests the exact data it needs and returns it in an anonymous class, and the last one returns the same as the first one, only it does it in one query behind the scenes.

 

The obvious downside of the second option is that it’s an anonymous class and not very flexible. Creating a wrapper class to contain the specific information is okay to transfer it to other tiers of the application, but going down this road will most likely result in an insane amount of wrapperclasses for a ton of different data-subsets.

 

The third option provides the best option for flexibility when you need a lot of different data from all of these tables, but if you then re-use that method elsewhere and only want the specific information in the sales table, you’re all of a sudden getting a lot of extra information you’re not going to use.

 

So, as I’m unable to give one definitive answer here in terms of what to do, I can’t put enough emphasis on the importance of profiling your application while you’re developing. Go through the different database calls being done by your application on each page, and make sure each of them can be justified. You should also note that if you specify multiple includes, you really should ensure that it looks sane enough in a profiler and has a decent execution plan. Also, if you’re retrieving insane amounts of data, you really should avoid includes due to the sheer amount of data it will generate. If you’re loading a lot of metadata for caching, you should have a look at how the lazy loading works in this post, and keep messing around with SQL profiler to get the quickest loading time possible.

 

An additional note here on includes. I’ve seen a few of the generic data-layer/extensions which works with EF, but I haven’t seen one which enables you to specify include paths – as that’s not something that fits very well with the generic pattern in general, but something which must be done directly on the ObjectContext-table. Keep this in mind when you decide on such patterns and practices.

Entity Framework with Caching and ViewState

I’ve been doing quite a few projects now using Entity Framework with .NET 4.0 and wanted to post a few hints and tips based on my experiences dealing with entities and caching.

 

First off I’d like to mention that my experience with Entity Framework has been very positive in general. I’ve been using it since its .NET 3.5 version both for commercial and private projects and found it to be very useful and easy to use. I also intend to keep using it as my DAL for future projects.

 

As far as performance goes, and to prevent relatively static data from being retrieved from the database, it’s usually preferred to cache or somehow temporarily store the data to minimize the load on the database as much as possible. For Entity Framework this usually means storing the individual entities or a collection of them.

 

A very quick and  simple generic way to cache results in the memory here is used regardless of entities could be as follows, using the System.Runtime.Caching implemented in .NET 4.0. (Previously found in System.Web)

 

 

This will simply store the results from GetStuffFromDatabase for 24 hours in a sane matter, the double cache check with lock is to prevent multiple simultaneous requests from accessing the database at the same time.

 

The important thing to note here when using this with the regular entities from Entity Framework – is that by default, this will include the DataContext which the objects are attached to. Meaning that, for instance, the entities will be able to access linked related objects through this specific context – which also means it will perform additional queries against the database later as long as you don’t explicitly dispose of the specific context.

 

It’s also important to note that if you intend to use the cached objects as references for other entities later on, you will most likely use a separate context and can’t use the objects directly. The simplest workaround for this is either to use exposed foreign key ids on the entities, or re-load the entity in the other context. An example to demonstrate this using the GetStuff method above is as follows, assuming that the AddAndSave will add the object to a fresh context and the GetStuff data has already been cached. Also, if you don’t expose foreign key id columns (4.0 feature), you won’t be able to do this, but need to reload the object instead.

 

When it comes to ViewState in ASP.NET applications, you want to be very careful when it comes to storing entities there. As with entities cached in memory, the ones you store in viewstate will also include the context, which might seem fine when you’re doing simple testing. However, a worse scenario could be if you for some reason retrieve 1000 entities and decide that you want to store one of them in the viewstate for a given page, the entire context will still be included, so the actual size will end up being that of all 1000 entities in the context.

 

There are a few relatively simple workarounds to this, the quickest one is to detach the entity from the context before you put it into the viewstate, meaning that only the actual entity will be stored there. It should be noted that you wouldn’t be able to access any foreign key related entity properties once you decided to do this unless you explicitly re-attach it to a context – which typically is not something you want to explicitly keep track of in an ASP.NET application.

 

The other, and slightly smarter way, includes creating a custom simple wrapper class including only the properties you deem relevant for the page being presented. This will effectively minimize the size of the viewstate and provide a much more defined way of saying to developers that it’s *not* an actual entity which can use its relations to access more data like a detached entity might say – but an object which already should have the data needed for the specific page. For anyone using entities and really wanting to optimize the page presented to the user and still need to use viewstate, this is the way to go. It’s really as lightweight as possible, and you weed out any extra properties and general overhead that you would still have in a POCO-entity/detached state. For more static data, you could combine this with the memory cache to store wrapped entities for the best performance.

 

In short, I’m quite happy with Entity Framework! It’s all incorporated nicely into the core of the .NET framework now, and it has in my opinion improved quite a bit in its 4.0 version. Getting it set up and working with the performance improvements you get from cached entities is also very simple and effective once you see the pitfalls related to how the contexts actually behave.

 

Setting up the data layer of any application in the most optimal way obviously depends on the nature of the different applications, but I hope this post has given a few pointers regarding how you can use Entity Framework with the standard .NET memory-caching.

ASP.NET Web Performance Trace Debugging with Log4net

I’ve recently worked a fair bit with checking out performance and pinpointing errors within web applications where performance is a priority, which, to be fair, really should be all web applications out there. Over the course of my performance adventures, I’ve returned to messing around with something I don’t really see a lot of people use to the extent which they could/should, the ASP.NET Trace.

 

For those not familiar with this, it’s information about the current page request, including specifics regarding everything conceivable about the current request plus server information, and in particular when it comes to performance, it provides specific load times and a view of the control hierarchy – including render size and viewstate size.

 

I’ve made a quick and very simple sample to illustrate what you can do with this, and in my little sample, the load time trace information on my default page looks a little something like this.

  

This table shows the load times for each of the steps, and by the looks of things, there are things happening in the Page Load which takes an unusually high amount of time to load!

 

To get detailed information about which specific portions of the web page which spends the most time delaying my page from rendering, I’m starting by adding a simple log4net entry to the trace appender in my web.config file, and configuring it on application start.

 

My Page Load consists of 3 simple calls, I want to figure out which calls are being the most painful ones, and I wrap each of them with debug messages for testing, like this.

  

Keep in mind, this is just for a quick sample, in reality with complex systems you’d most likely want to place such messages inside the functions, and probably give them slightly more relevant information. Even better is if you already have a decent debug scenario set up across your solution, in which case you get a lot of free debugging here!

 

I recompile my solution now, and check the trace again, and find that the log4net messages have now decided to join in with the other trace messages, which adds a few more lines in-between the page load, as shown here. It’s important to note that the log4net messages now “break up” the step between begin and end load, as the trace counter simply counts from the last event, which log4net is now hooked up to.

 

This gives me an overview to work with stating that QuickStuff takes roughly 0.1 seconds to finish, SomeStuff roughly 2 seconds and LotsOfStuff is the winner with 5 seconds. Using these debug messages I can drill further down with more detailed debug messages to find the exact source of the "problem" and thus know exactly where I need to optimize code and/or queries to make the page load quicker.

 

By default, the ASP.NET Trace is disabled, and a lot of people tend to keep it that way, either by choice or by accident. To turn on this feature, you can add Trace=”true” to the page declaration of each individual page, but this does create some issues as you really don’t want to accidently put the trace out on a production site! I’ve found that a generic and more “on demand” way to enable trace on demand is to add a check for it through a querystring check in global.asax. Although, don’t put this in production either! :)

 

Doing something like this in global.asax will make the trace appear when you append ?trace=1 to whichever url you are working on, provided that it’s not overridden in the page declaration. It’s worth to note that working with ajax will sometimes mess up your trace, I tend to disable that temporarily if that’s the case – however, if I can’t work around this, I will add a fileappender to the log4net configuration, and check the delays between the entries there manually.

 

The last part I’d like to mention is the “page size” problem when it comes to performance. An issue which is more or less specific to ASP.NET WebForms is the added overhead with the viewstate. Using the Control Tree Information in the trace lets you detect how much of the page is viewstate, and how much is actual rendering.

 

I’ve adjusted my sample webpage to now have two labels, one of which has EnableViewState=”false”, both have had their Text properties set to Hello World! looped 100.000 times for over the top emphasis.

 

Here you can see the exact control hierarchy of all the controls and text on the page, total render size is 4mb, with each of the labels having 1.2mb of text and the label with the viewstate having 1.6mb on top of that in added viewstate.

 

Although this is a very far out example, it’s important to note that the viewstate of the label here is about 33% larger than the size of the actual label, and the client will have to download both of these, increasing the total download from a non-viewstate label to a viewstate by 133%. Also keep in mind that on client postbacks, the client will have to post the amount of viewstate back to the server, so if you’re having huge amounts of data to post for relatively simple operations, you might want to refactor or restructure your page if you’re experiencing performance issues.

 

A few obvious things I feel is worth pointing out here as a result of this is that if you have WebForm pages which don’t use postbacks at all, keep viewstate off! You can disable viewstate on a page level in the page declaration with an EnableViewState=”false”, the same goes for any controls you might have.

 

Furthermore, when binding complex objects, it’s ideal for performance to make sure you only bind objects with the properties you really need. If you’re using O/RMs in particular, you want to try to make as simple wrapper classes of your objects as possible, to ensure that you don’t keep pushing data you don’t need at all to both the client when it’s being read, but also on a potential postback to your server.

Logging with log4net

I’ve decided to write up a small post regarding logging in C#/ASP.NET applications, as there’s a fair few people over the years who have had questions and trouble regarding how and when they should log information, and what they should include in their logs.

 

First off, the disclaimer! These are my internal rules and thoughts based on my experiences and my personal preferences when it comes to logging. There are most likely other (and hopefully better) ways of implementing and maintaining a healthy level of logging. In this post I’m just trying to write down some of my basic guidelines and the thoughts behind them.

 

The logging implementation of choice for all my applications has always been log4net by Apache Logging Services. The simplicity, power and flexibility of the framework has all the requirements I’d like from such a framework covered nicely without me having to put any significant effort into it.

 

Setup and Installation of log4net is documented thoroughly at the official homepage http://logging.apache.org/log4net/index.html – I’ll skip that part and head to how to actually use logging in various applications.

 

Logging Goals

The main objective of logging at a debug-level should be to ensure that you have enough information to troubleshoot virtually any problem happening in your production systems, even if there isn’t an exception present. Having enough information to accurately reproduce a bug or scenario which happened in a controlled test environment will drastically reduce the time it takes to fix things as opposed to having to look at the problem and guess what went wrong.

 

Logging at an exception-level should be aimed towards making sure that critical exceptions are distributed to the right people as soon as possible for a quick response in regards to whatever needs fixing. A pre-requisite for this to work is to have decent exception-handling present in the system.

 

What this logging should *not* be, is a tool to use for business-related tasks. If you need to use logs generated by log4net as the main source to report anything or solve any business-related queries that aren’t a result of bugs or flaws in the system, you’re much better off writing custom logic and storing the data some place accessible through your reporting or support systems.

 

log4net Thresholds

All the messages generated by log4net has its own threshold value. These are in order from lowest to highest, Debug, Info, Warn, Error, Fatal. A typical setup will route different levels of errors to different handlers – common usage tends to be logging everything to a text file locally, while sending off error and fatal messages per mail. Setting a threshold in the configuration will return all messages at that threshold and above.

 

Here’s a relatively short overview of how I use the various thresholds with examples. It’s important to note that the intended use of thresholds must reflect the appenders used. If you want developers to get notified immediately when the system dies horribly, you want to make sure that only those messages have the highest threshold, and the instant notification appender only catches the messages with the highest threshold.

 

DEBUG

The lowest value and primarily used for what it says, debug information. These should be the messages with diagnostic information used to recreate what is happening during a given operation. They will also be the messages you’ll most likely end up having the most of in your system. As such, it’s important to not go overboard with the amount of these messages, all of them should have a good reason for being included.

 

If I have a function which will add a customer to my system, I would start the function with a debug call saying which parameters I got passed into the function. If at a later stage in the function, there happens to be some complex logic related to which type of customer I’m going to add, with separate creation paths based on the result, I will add on another debug message here with the reasoning and result of the selection to show which code path was taken. At the end of the function where the customer will be saved to a database, another debug message should be fired off at the success of creating the customer, including the primary key of the Customer table to ensure that everything worked out.

 

In the event that there is something wrong with a Customer being entered here, a developer diagnosing the problem can bring up the logs and trace it easily by searching for the primary key of the Customer table and check backwards what was done during the creation, as well as getting the exact parameters used in the function. If the parameters passed or path choice listed can’t immediately explain what the problem here is, you can easily recreate the same customer being created in a testing environment by calling the same function with the same parameters.

 

If you manage to cover all relatively complex and vital functions in this manner you should be off to a great start in being able to track down problems.

 

A special mention here should go to external calls such as web services/MSMQ and so on – as you really want to log the source coming in there in addition to everything else to ensure that you can recreate anything that might be faulty outside of your code, always make sure you can prove that others are messing up!

 

For Data Access / External Interfaces there’s also the option of implementing very generic debug messages using object oriented approaches, you need to weigh the benefits of this compared to the amount of debug messages you will receive and plan accordingly.

 

INFO

I don’t really use this level a whole lot. Currently I only use it for saying when applications or services are starting and stopping, as the only other reason I see for this level is to use it for “important debug messages” – but I haven’t seen the need for this just yet, the debug messages are still debug messages!

 

WARN

The first of the thresholds more commonly used for exceptions. I’ve found myself using this more and more now for exceptions that happen without there being any decent business implications, but still something that might be looked at “at one point”™ or “when we have time”™. In addition to this, I also use this in cases where it’s something that probably isn’t dangerous, but if it happens a lot we should look at it.

 

An example of using this in an ASP.NET application could be if you handle a RequestValidation exception on a generic level, which typically comes from someone entering html/script accidentally in some form before submitting the page. This isn’t really something to be too worried about, but in the case of an actual attack, it’s worth mentioning in the logs if you skim through them on a Warn level.

 

It’s important to just add Warn messages when you actually might want to look at these messages, if you’re parsing some optional variable which might fail most of the time and using a try/catch to ensure that everything goes smooth regardless, you don’t want to log this at all.

 

A slight note here, the level is WARN not WARNING, if you happen to add WARNING as a threshold, log4net will be confused and revert to no threshold, giving you all Debug and Info messages as well.

 

ERROR

The Error level is the main way to handle exceptions. A rule of thumb here is that errors which will have some sort of business impact if ignored, or system errors which will need to be fixed should be put in this category.

 

A typical example of this for an ASP.NET application would be to add log4net calls to the Application_Error event in case the exception which has been thrown wasn’t handled better, and the user typically will be sent to a custom error page. This is typically behavior from the system which should be fixed, as such, an error message is warranted.

 

Make sure that you include the actual exception in the call to the error-logging here, along with an informative error message with as much information as you can get a hold of. Seeing how these messages usually are called from within catch blocks, be mindful that you code this information defensively, as you don’t want to accidently trigger a null-reference exception while doing a logging-call.

 

Keep in mind that as long as you include the exception, you will maintain a stack-trace in the message, so you don’t need to include detailed information which is already included in a standard stack-trace.

 

FATAL

The highest level is the one you ideally don’t want to see or use at all. I reserve this for critical errors resulting in the business or systems in general not being able to operate at all, or other errors requiring immediate attention.

 

I feel it’s extremely important to distinguish between the Fatal and Error levels at a business level, if you’re an e-commerce site and you get errors while trying to save a new customer it’s not quite at the same level as being completely unable to connect to the database containing all customer information. Receiving a “Shutdown in Progress” from the SQL Server would be quite Fatal, whereas “String or binary data would be truncated” is sad, but you probably won’t get too many developers cutting their lunch short to fix it.

 

In short, use this for exceptions where you get indications that the system is globally threatened, business-critical services stopping/not-starting or other situations where you would consider permanently relocating to Mexico if it’s not detected within 5mins and resolved within 30mins.

 

Threshold Summary

It’s very important to know the intended use of each level and follow the guidelines set by your company as best you can. When you’re writing code, keep in mind that debug messages will help immensely when you discover an issue in production. Even if you feel that it’s nice and safe code executing, you never know what the next person touching your code will do, and properly inserted debug messages across the application will help both of you when you try to figure out what “he” obviously did wrong.

 

When you do exception handling, think of all the various exceptions that could happen inside the catch block, catch them individually and log them according to the implications of that specific exception being unhandled. If you know you won’t need to worry about the exception, don’t log it as an Error!

 

log4net Appenders

The actual implementation of how to deal with the logging in your code will vary greatly depending on the applications, setup, infrastructure and other factors. It’s also important to point out that you can have multiple appenders set up with the same criteria so you can put the messages several places if you want to. It’s also very simple to create your own custom appenders with a bit of work if you want that SmsMessageAppender for the fatal errors for instance.

 

As a result of the differences in applications here I don’t really have an overall tip of how to do things here, just a few hints and tips on using the various common appenders.

 

A list of the default appenders provided by log4net is listed at http://logging.apache.org/log4net/release/sdk/log4net.Appender.html and examples of how to use them at http://logging.apache.org/log4net/release/config-examples.html – I recommend browsing through the latter and see which ones seem most reasonable.

 

The commonly used appenders would include FileAppender, RollingFileAppender, SmtpAppender, AdoNetAppender and in debug environments ColoredConsoleAppender/AspNetTraceAppender depending on the application.

 

FileAppenders

The FileAppender and RollingFileAppender are probably amongst the most common appenders used for Debug messages. They simply add messages to a file, with the option to roll over on a given size if you specify a RollingFileAppender.

 

When you use these, you need to make sure that the application running log4net has write access to the path/folder you specify as the log directory, or the IIS/ASPNET process if it’s a web application. It’s also important to make sure you don’t put the log file somewhere accessible from outside if you decide to use this on your web server.

 

It’s also common to add these appenders in test/development environments as they’re quite helpful alongside a tail-tool such as BareTail, adding color-coding to BareTail on a second monitor and pointing it to your logfile is an excellent way to see what’s happening behind the scenes when you’re doing things from the front-end.

 

It’s also nice to note that the RollingFileAppender has options which will let you roll over to new log files based on dates or hours, so you’re able to maintain a separate log-file per day/hour to simplify searches through the files.

 

SmtpAppender

This appender is probably the most used Error-threshold appender of them all. Sending an e-mail whenever something hits the threshold is quite useful and a decent way to notify developers that something is wrong.

 

A few notes on the BufferSize parameter here, BufferSize is used to specify how many messages *before* the actual error it should include. This means that if you get an error-message, it will also include a lot of debug-messages that happened before the error. This means that it’s even more important to include decent and descriptive debug messages if you intend to use the SmtpAppender.

 

AdoNetAppender

This appender is the one I’ve seen most people have problems using. It logs the messages over the given threshold to the database, nothing more, but it’s the most configuration-heavy appender out there.

 

There are two main causes for problems here,  the first is the specific configuration of every field you need to insert into. If the type or size is off, you won’t see anything enter the database at all – and you won’t get any sort of notification of this unless you have set the log4net debug options on and specified an output there. I recommend that you check out the “How do I enable log4net internal debugging?” in the http://logging.apache.org/log4net/release/faq.html document, and write the output to file, then check if there’s anything wrong with the setup in that log.

 

The second problem is mainly due to the fact that BufferSize doesn’t mean the same as with the SmtpAppender. For the AdoNetAppender, this specifies how many messages the buffer must have before it actually writes the batch to the database. If you’re testing that this actually works, you want to set this to 1 to write messages as they come.

 

There are some obvious drawbacks when it comes to using this appender, namely that you rely on a database being up to write entries, and it’s much too easy and tempting to also use the production database to store the logging data. Depending on the amount of logging data you expect, you should be very careful when deciding whether or not to use this logger, and extremely careful with the threshold you decide to set for it. Unless you really need the option to perform SQL-queries against the messages you have stored away, or need to further process them, there are most likely better options out there to cover your needs better with other appenders.

 

Other Appenders

There’s a variety of other appenders for the different scenarios you might encounter. When I’m debugging services as console applications, I always include the ColoredConsoleAppender to give me an overview of what’s happening on the fly.

 

For ASP.NET pages during development, you can simply enable trace and include the AspNetTraceAppender to add the log4net messages into the ASP.NET trace as well, all your debug messages will serve their purpose well when you double-check that the input values you provided resemble what’s being passed into the lower layers if you followed the debug pattern specified under thresholds.

 

The other appenders also have their uses, but are less common. The Remoting/UDP/network appenders have their use if you have a centralized logging server for instance, and you could most likely anger your administrator quite a bit by adding an EventLogAppender with a debug threshold to the web.config of your production web server!

 

Custom Appenders

If you have some specific  task you want done with the error messages that somehow isn’t covered here, you can easily specify your own appender by creating a class inheriting from the AppenderSkeleton class. This really isn’t as painful as it might sound, so if you have something fairly custom in mind, I recommend trying this out.

 

Uses here could be if you have your own task management system, and you receive errors coming in, you could add an appender which automatically transforms an error message to a task to be resolved.

 

Appender Summary

When deciding which logging approach and appenders to go for, you want to gather information regarding how/where the applications will be set up, what the infrastructure is like and how the overall logging is implemented in the applications.

 

As mentioned earlier, a simple web server application can go for a RollingFileAppender with threshold Debug + SmtpAppender at threshold Error. If things get a bit more complex and you have things like load balancing, multiple servers, multiple services and multiple applications, a good way to handle things could be to have a centralized application server receiving all the log messages and processing them further.

 

If you have an extremely business-critical service you need to have running at all times, you could go with a custom coded Appender which at the Fatal threshold will, not only send email to the developers, but also send SMSes to certain people at night, or if it’s during work hours – perform some custom task which will max out the volume on a PC in the office and start playing “Crazy Train” to ensure that everyone knows there’s tomfoolery afoot!

 

Summary

Having proper logging in place with a clearly defined logging strategy in your applications will help improve internal testing during development as well as being able to troubleshoot issues in production systems whenever bugs manage to sneak into the system.

 

Setting the right standards for when to use the available log-thresholds alongside the appenders and proper exception handling will ensure that any errors occurring in production environments can be found and diagnosed quickly with logs available.

 

In other news, I realize I wrote a bit more than I intended to, hope someone found it slightly useful at least!