Ayende @ Rahien

Hi!
My name is Oren Eini
Founder of Hibernating Rhinos LTD and RavenDB.
You can reach me by phone or email:

ayende@ayende.com

+972 52-548-6969

, @ Q c

Posts: 10 | Comments: 37

filter by tags archive

Getting code ready for production

time to read 6 min | 1053 words

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

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

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

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

Ayende Rahien

Yep,

There is nothing meaningful that can be done.

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

@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

"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

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

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

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

Steve,

That is why I include the exception in.

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

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

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

@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

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

Ziv,

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

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

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

Are you sure you can handle OutOfMemoryExceptions this way?

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

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

Michael,

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

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

Comment preview

Comments have been closed on this topic.

FUTURE POSTS

  1. Production postmortem: The case of the memory eater and high load - about one day from now
  2. Production postmortem: The case of the lying configuration file - 2 days from now
  3. Production postmortem: The industry at large - 3 days from now
  4. The insidious cost of allocations - 4 days from now
  5. Find the bug: The concurrent memory buster - 5 days from now

And 4 more posts are pending...

There are posts all the way to Sep 10, 2015

RECENT SERIES

  1. Find the bug (5):
    20 Apr 2011 - Why do I get a Null Reference Exception?
  2. Production postmortem (10):
    14 Aug 2015 - The case of the man in the middle
  3. What is new in RavenDB 3.5 (7):
    12 Aug 2015 - Monitoring support
  4. Career planning (6):
    24 Jul 2015 - The immortal choices aren't
View all series

Syndication

Main feed Feed Stats
Comments feed   Comments Feed Stats