Ayende @ Rahien

Refunds available at head office

Getting code ready for production

I am currently doing the production-ready pass through the Rhino DivanDB code base, and I thought that this change was interesting enough to post about:

public void Execute()
{
    while(context.DoWork)
    {
        bool foundWork = false;
        transactionalStorage.Batch(actions =>
        {
           var task = actions.GetFirstTask();
           if(task == null)
           {
               actions.Commit(); 
               return;
           }
           foundWork = true;

           task.Execute(context);

           actions.CompleteCurrentTask();

           actions.Commit();
        });
        if(foundWork == false)
            context.WaitForWork();
    }
}

This is “just get things working” phase. When getting a piece of code ready for production, I am looking for several things:

  • If this is running in production, and I get the log file, will I be able to understand what is going on?
  • Should this code handle any exceptions?
  • What happens if I send values from a previous version? From a future version?
  • Am I doing unbounded operations?
  • For error handling, can I avoid any memory allocations?

The result for this piece of code was:

public void Execute()
{
    while(context.DoWork)
    {
        bool foundWork = false;
        transactionalStorage.Batch(actions =>
        {
            var taskAsJson = actions.GetFirstTask();
            if (taskAsJson == null)
            {
                actions.Commit();
                return;
            }
            log.DebugFormat("Executing {0}", taskAsJson);
            foundWork = true;

            Task task;
            try
            {
                task = Task.ToTask(taskAsJson);
                try
                {
                    task.Execute(context);
                }
                catch (Exception e)
                {
                    if (log.IsWarnEnabled)
                    {
                        log.Warn(string.Format("Task {0} has failed and was deleted without completing any work", taskAsJson), e);
                    }
                }
            }
            catch (Exception e)
            {
                log.Error("Could not create instance of a task from " + taskAsJson, e);
            }

            actions.CompleteCurrentTask();
            actions.Commit();
        });
        if(foundWork == false)
            context.WaitForWork();
    }
}

The code size blows up really quickly.

Comments

Andrey Shchekin
03/06/2010 10:51 AM by
Andrey Shchekin

So if the warnings are not enabled there is no way to tell that task has thrown an exception? Is it generally ok for task to throw an exception?

Ayende Rahien
03/06/2010 11:09 AM by
Ayende Rahien

Andrey,

The assumption is that WARN is enabled for production.

The server keeps track of the last 50 errors and can show them on request.

Ziv Caspi
03/06/2010 06:30 PM by
Ziv Caspi

catch (Exception) w/o rethrow in production code?

Ayende Rahien
03/06/2010 06:38 PM by
Ayende Rahien

Yep,

There is nothing meaningful that can be done.

masklinn
03/06/2010 08:32 PM by
masklinn

Goodness gracious, is this .Net's built-in logging API? It looks downright dreadful, why in science's name do you have different methods depending on whether you want to do formatting by hand or not, and why do you end up using 3 different kinds of formatting?

Terry
03/06/2010 09:16 PM by
Terry

@masklinn

How is that you are so ignorant of .NET yet still choose to criticize? Since you really don't know what you're talking about here's a little FYI: there is no built-in logging API in .NET.

Ziv Caspi
03/06/2010 09:50 PM by
Ziv Caspi

"There is nothing meaningful that can be done":

I disagree. Either rethrow, and let the calling code decide what it wants to do with the exception, or do Environment.FailFast. Anything else (in particular if you're writing libraries, not the "top-level" apps) masks bugs and is usually very difficult to debug.

Ayende Rahien
03/06/2010 09:57 PM by
Ayende Rahien

Ziv,

There isn't any calling code, this is handled by a indexing background thread.

Rethrowing will kill the entire application, and having errors on indexing is expected

masklinn
03/06/2010 10:38 PM by
masklinn

How is that you are so ignorant of .NET yet still choose to criticize?

I don't need to know the .net apis to see that these logging calls are ducking ugly.

there is no built-in logging API in .NET.

Well that answers my first question with a negative (though I'm not sure it's a good thing)

Steve Py
03/06/2010 10:49 PM by
Steve Py

Looks pretty standard.

I'm asuming that:

        log.DebugFormat("Executing {0}", taskAsJson);

is conditional for Debug builds?

It might be worth while on your inner catch for the Execute to include details in the Warn about what exception was raised. (Why the task couldn't be executed.)

Ayende Rahien
03/06/2010 11:37 PM by
Ayende Rahien

Steve,

That is why I include the exception in.

Rory Primrose
03/07/2010 02:25 AM by
Rory Primrose

My 20c worth, the bit that screams ugly to me is the logging check around warning being enabled. The logging implementation should handle the outcome of whether warning level logging is enabled or not. To have this implemented by calling code seems like incorrect allocation of responsibility and duplicated logic.

Calling code should not be responsible for understanding the how/what/why of the logging implementation as it does here. If this is a restriction of the logging implementation when I would use a different logger.

Steve Py
03/07/2010 04:29 AM by
Steve Py

Ah, didn't see that. It overflowed into the sidebar.

Ziv Caspi
03/07/2010 07:18 AM by
Ziv Caspi

Are all kinds of errors expected? Does this include ImCorruptPleaseDontCallMeAgainOrIllFormatYourHardDrive? What about whoever submitted the job? If it doesn't care whether the job succeeds or not, you may as well ignore every second job -- performance would be way up. (Of course, this is all tongue-in-cheek.)

Rafal
03/07/2010 07:48 AM by
Rafal

@Rory

the check is done to avoid formatting a string if logging is disabled. If the exception is an abnormal situation, optimizing its handler seems unnecessary. And the logging API could handle that, for example NLog av oids formatting a string if the message won't get logged.

Ayende Rahien
03/07/2010 09:27 AM by
Ayende Rahien

Rory,

That isn't the reason for that.

The reason is that I want to avoid the perf hit of doing string formating if loging isn't enabled.

Ayende Rahien
03/07/2010 09:29 AM by
Ayende Rahien

Ziv,

Error tracking is handled else where for this scenario, and too many errors would disable a certain set of tasks

Frans Bouma
03/07/2010 10:35 AM by
Frans Bouma

Isn't this 'getting ready for production' really a waste of time? I mean: what if you try to write the code the first time already as if it's going to be for production. that would save you time, and you also don't run the risk of not having time to go over the code to make it ready for production. The bigger code base become, the more time it takes to write them, the more time it will take (and thus the lower the chance you'll do it) to make it production ready.

Ayende Rahien
03/07/2010 10:39 AM by
Ayende Rahien

Frans,

If I am writing code that I know how to work with, sure, you should do it right the first time around.

But this codebase represent me doing design & exploration along the way, taking the burden of production worthiness (along the other related taxes) would have made it too hard.

It was more efficient to do it in a two stage approach.

Steve Wagner
03/07/2010 04:53 PM by
Steve Wagner

Are you sure you can handle OutOfMemoryExceptions this way?

Paul Hatcher
03/07/2010 08:47 PM by
Paul Hatcher

One difference I would make here is to have two catches for SystemException and Exception; for the first, catch and re-throw as it caters for all of the OutOfMemoryException etc, the second you could swallow I suppose but it would be nicer to know what exceptions you could receive and handle them explicitly - though it does make the code more fragile.

Michael Teper
03/08/2010 05:57 AM by
Michael Teper

What Steve said. Seems like you are still doing allocations after the exception is thrown (one of the things you tried to avoid for production code)

Ayende Rahien
03/08/2010 06:56 AM by
Ayende Rahien

Michael,

Ah! Good, I was wondering when someone will catch that.

tobsen
03/12/2010 08:49 AM by
tobsen

Ayende, have you tried using the latest version of CommonLogging? You will get a much nicer syntax instead of if(log.IsDebugEnabled) you can simply write log.Warn(logm => logm(" Task {0} has failed and was deleted without completing any work", taskAsJson)); which will be evalutated only if warning is active. As a bonus, commonlogging will abstract the used logging framework and you can switch easily between logging implementations (system.trace (who wants that anyways?), log4net, nlog, simpleconsolelogger...). See Erich Eichinger's blogpost about the new features: eeichinger.blogspot.com/.../...r-net-released.html

Comments have been closed on this topic.