One of the things that I avidly subscribe to is that when you are building server applications, visibility into what the application is doing is key. If you don’t have visibility into the application, you are left in the dark, stumbling and alone.

NH Prof is a good example of how you make things much more visible to developers, but I am doing this in many other places, Rhino Service Bus is another example of how important it is to have visibility into what your servers are doing. Being able to see what is actually going on in your apps is priceless!

However, that does come at a cost. And a pretty steep one at that.

Logging is expensive. It is expensive to gather the data to log, it is expensive to actually log the data, in order to produce coherent logs in multi threaded environment, you need to perform synchronization, etc.

One of the most common performance problems that people run into is when they push their debug logging configuration to production. If we will look into NHibernate as a good example, if you set the log level to debug, you are going to get tens of thousands of messages just for the startup! And you are going to get hundreds and thousands of log messages for routine operations.

That is going to slow things down, considerably.

Production configuration management is a big topic, and it deserves its own post, but the impact of setting the log level too low in production cannot be stressed strongly enough.

Pay attention to this, or it will make you pay attention to it.

In one notable case, several years ago, we re-implemented a whole module in the application (significantly optimizing it) to get exactly zero benefit (well, negative benefit, actually) from the exercise, since the actual problem was slow logging database.

In another, we improved performance by over 60% by simply raising the log level from DEBUG to ERROR.

I run into an annoyingly persistent error on a production server:

System.Messaging.MessageQueueException: Insufficient resources to perform operation.
   at System.Messaging.MessageQueue.SendInternal(Object obj, MessageQueueTransaction internalTransaction, MessageQueueTransactionType transactionType)
   at System.Messaging.MessageQueue.Send(Object obj)
   at ConsoleApplication1.Program.Main(String[] args)

This was generated from the following code:

class Program
{
    static void Main(string[] args)
    {
        try
        {
            var queue = new MessageQueue(@".\private$\MyQueue");
            queue.Send("test msg");
            Console.WriteLine("success"); 

        }
        catch (Exception e)
        {
            Console.WriteLine(e);
        }
    }
}

The error was happening on all queues, and persisted even after rebooting the machine. I should mention that we had a runaway message generation, and we have queues with lots of messages currently.  The queue that I was trying to send the message to was empty, however. And there was no reading/writing on the queues.

Nasty issue to figure out, I was pointed to this post, and indeed, suggestion #7 was it, we run over the machine quota for MSMQ, so it started rejecting messages.

No one really thought about it, because we never set the quota, but it seems that by default there is a 1GB quota for the entire machine. This is usually more than enough to handle things, I would assume, but when you run into a convoy situation, bad things will happen.

Karl has posted about his experience of porting an NHibernate application from SQL Server to PostgreSQL, long story short, he did it in 1 hour.

He does bring up a few points where the database that he was using bled into the code, hurting the database independence goal. I wanted to look at those and point out the builtin solutions that NHibernate provides for those.

Handling unique constraints violations, Karl has code like this:

try
{
    Session.SaveOrUpdate(user);
    transaction.Commit();
    return true;
}
catch (GenericADOException ex)
{
    transaction.Rollback();
    var sql = ex.InnerException as SqlException;
    if (sql != null && sql.Number == 2601)
    {
        return false;
    }
    throw;
}
catch (Exception)
{
    transaction.Rollback();
    throw;
}

Obviously, this code relies heavily on internal knowledge of SQL Server error codes, and wouldn’t translate to PostgreSQL.

With NHibernate, you deal with those issues by writing ISqlExceptionConverter, you can read Fabio’s post about this, but the gist of it is that you can provide your own exceptions in a database independent way.

The count function may return different types on different databases. NHibernate tries to stay true to whatever the database is giving it, so it wouldn’t truncate information. You can force the issue by overriding the count function definition by writing a derived dialect. You can see an example of that in this post.

Bits & Booleans, while SQL Server accepts 1 as a Boolean value, PostgreSQL requires that you would use ‘1’ instead. This is where NHibernate’s query.substitutions supports come in. I usually define substitutions for true and false and then use true and false in the queries. Based on the database that I am running on, I can select what will be substituted for those values.

Achieving database independence with NHibernate is very easy, as Karl’s 1 hour porting story proves.

One of the most horrible things that can happen to a code base is a production bug that needs to be fixed right now. At that stage, developers usually throw aside all attempts of creating well written code and just try to fix the problem using brute force.

Add to that the fact that very often we don’t have the exact cause of the production bug, and you get an interesting experiment in the scientific method. The devs form a hypothesis, try to build a fix, and “test” that on production. Repeat until something make the problem go away, which isn’t necessarily one of the changes that the developers intended to make.

Consider that this is a highly stressful period of time, with very little sleep (if any), and you get into a cascading problem situation. A true mess.

Here is an example from me trying to figure out an error in NH Prof’s connectivity:

This is not how I usually write code, but it was very helpful in narrowing down the problem.

But this post isn’t about the code example, it is about the implications on the code base. It is fine to cut corners in order to resolve a production bug. One thing that you don’t want to do is to commit those to source control, or to keep them in production. In one memorable case, during the course of troubleshooting a production issue, I enabled full logging on the production server, then forgot about turning them off when we finally resolved the issue. Fast forward three months later, and we had a production crash because of a full hard disk.

Another important thing is that you should only try one thing at a time when you try to troubleshoot a production error. I often see people try something, and when it doesn’t work, they try something else on top of the modified code base.

That change that you just made may be important, so by all means save it in a branch and come back to it later, but for production emergency fixes, you want to always work from the production code snapshot, not on top of increasingly more franticly changed code base.

My 3 days course about NHibernate will be delivered at Paris , on 04 Nov 2009 by Sebastien Lambla.

This course is squeezing into 3 days everything that you need to go from an NHibernate newbie to a proficient craftsman.

An interesting tidbit, the last time that Sebastien gave the course, I got amazing feedback about the course.

You can register here.

I have this piece of code:

public static string FirstCharacters(this string self, int numOfChars)
{
    if (self == null)
        return "";
    if (self.Length < numOfChars)
        return self;
    return self
        .Replace(Environment.NewLine, " ")
        .Substring(0, numOfChars - 3) + "...";
}

And the following exception was sent to me:

System.ArgumentOutOfRangeException: Index and length must refer to a location within the string.
Parameter name: length
  at System.String.InternalSubStringWithChecks(Int32 startIndex, Int32 length, Boolean fAlwaysCopy)
  at StringExtensions.FirstCharacters(String self, Int32 numOfChars)

It actually took me a while to figure out what is going on. Partly that is because we have an “impossible” stack trace (the JIT seems to have inlined the Substring call). When I did figure what the bug was, i is a head slapping moment.

As I already mentioned, this presentation had me thinking. Billy presented a system called Redis, which is a Key/Value store which is intended for an attribute based storage.

That means that storing something like User { Id = 123, Name = “billy”, Email = “billy@example.org”} is actually stored as:

{ "uid:123:name": "billy" } 
{ "uid:123:email": "billy@example.org" }
{ "uname:billy": "123" } 

Each of those lines represent a different key/value pair in the Redis store. According to Billy, this has a lot of implications. On the advantage side, you get no schema and very easy support for just adding stuff as you go along. On the other hand, Redis supports not transactions and it is easy to “corrupt” the database during development (usually as a result of a programming bug).

What actually bothered me the most was the implications on the number of remotes calls that are being made. The problem shows itself very well in this code sample, (a twitter clone), which show inserting a new twit:

long postid = R.str_long.incr("nextPostId"); 
long userId = PageUtils.getUserID(request); 
long time = System.currentTimeMillis(); 
string post = Long.toString(userId)+"|" + Long.toString(time)+"|"+status; 
R.c_str_str.set("p:"+Long.toString(postid), post);
List<long> followersList = R.str_long.smembers(Long.toString(userId)+":followers"); 
if(followersList == null) 
   followersList - new ArrayList<Long>(); 
HashSet<long> followerSet = new HashSet<long>(followersList); 
followerSet.add(userid); 
long replyId = PageUtils.isReply(status); 
if(replyId != -1) 
   followerSet.add(replyId); 
for(long i : followerSet) 
    R.str_long.lpush(Long.toString(i)+":posts", postid); 
// -1 uid is global timeline 
String globalKey = Long.toString(-l)+":posts"; 
R.str_long.lpush(globalKey,postid); 
R.str_long.ltrim(globolKey, 200);

I really don’t like the API, mostly because it reminds me of C, but the conventions are pretty easy to figure out.

• R is the static gateway into the Redis API
• str_long = store ong
• c_str_str – store string and keep it in nearby cache

The problem with this type of code is the number of remote calls and the locality of those calls. With a typical sharded set of servers, you are going to have lots of calls going all over the place. And when you get into people that have thousands and millions of followers, the application is simply going to die.

A better solution is required. Billy suggested using async programming or sending code to the data store to execute there.

I have a different variant on the solution.

We will start from the assumption that we really want to reduce remote calls, and that the system performance in the face of large amount of writes (without impacting reads) is important. The benefits of using something like Redis is that it is very easy to get started, very easy to change things around and great for rapid development mode. We want to keep that for now, so I am going to focus on a solution based on the same premise.

The first thing to go is the notion that a key can sit anywhere that it wants. In a key/value store, it is important to be able to control locality of reference. We change the key format so it is now: [server key]@[local key]. What does this mean? It means that for the previously mentioned user, this is the format it will be stored as:

{ "uid:123@name": "billy" } 
{ "uid:123@email": "billy@example.org" }
{ "uname@billy": "123" } 

We use the first part of the key (before the @) to find the appropriate server. This means that everything with a prefix of “uid:123” is known to reside on the same server. This allow you to do things like transactions on a single operation of setting multiple keys.

Once we have that, we can start adding to the API. Instead of getting a single key at a time, we can get a set of values in one remote call. That has the potential of significantly reducing the number of remote calls we will make.

Next, we need to consider repeated operations. By that I mean anything where we have a look in which we call to the store. That is a killer when you are talking about any data of significant size. We need to find a good solution for this.

Billy suggested sending JRuby script to the server (or similar) and executing it there, saving the network roundtrips. Which this is certainly possible, I think it would be a mistake. I have a much simpler solution. Teach the data store about repeated operations. Let us take as a good example the copying that we are doing of a new twit to all your followers. Instead of reading the entire list of followers into memory, and then writing the status to every single one of them, let us do something different:

Redis.PushToAllListFoundIn("uid:"+user_id+"@followers", status, "{0}@posts");

I am using the .NET conventions here because otherwise I would go mad. As you can see, we instruct Redis to go to a particular list, and copy the status that we pass it to all the keys found in the list ( after formatting the key with the pattern). This gives the data store enough information about this to be able to optimize this operation considerably.

With just these few changes, I think that you gain enormously, and you retain the very simple model of using a key/value store.

This is just something that really annoys me. There is a common misconception that compilers are mostly about parsing the code. This couldn’t be further from the truth. About the easiest step in building a compiler is parsing the text into some form of machine readable format. There are great tools to help you there, and a lot of information.

It is the next stage that is complex, taking the machine readable format (AST) and turning that into executable. There is a lot less information about that, and that tends to be a pretty gnarly sort of a problem.

As the title says, this post is here just to make sure that people distinguish between the two.

About two weeks ago I posted my spike results of porting NHProf to Linq to SQL, a few moments ago I posted screenshots of the code that is going to private beta.

I spent most of the last week working on the never-ending book, but that is a subject for a different post. Most of the time that I actually spent on the profiler wasn’t spent on integrating with Linq to SQL. To be frank, it took me two hours to do basic integration to Linq to SQL. That is quite impressive, considering that is from the point of view of someone who never did anything more serious with it than the hello world demo, and it was years ago. The Linq to SQL codebase is really nice.

Most of the time went into refactoring the profiler. I know that I am going to want to add additional OR/Ms (and other stuff) there, so I spent the time to make the OR/M into a concept in the profiler. That was a big change, but it was mostly mechanical. All the backend changes are done, and plugging in a new OR/M should take about two hours, I guess.

For Linq to SQL, however, the work is far from over, while we are now capable of intercepting, displaying and analyzing Linq to SQL output, the current Linq to SQL profiler, as you can see in the screen shots, is using the NHibernate Profiler skin, we need to adapt the skin to match Linq to SQL (different names, different options, etc).

That is the next major piece of work that we have left to do before we can call the idea of OR/Ms as a concept done, and release Linq to SQL as a public beta.

This is just to give you some ideas about what the new LinqToSql Profiler can do.

It can track statements and associate them to their data context, gives you properly formatted and highlighted SQL, including the parameters, in a way that you can just copy and execute in SQL Server:

The profiler can tell you when you are hitting the database too often.

All the usual reports, what methods caused what queries to be executed?

Reports about unique queries across the entire profiling session:

And overall usage reports: