Tuesday 9 June 2009

Accessing Properties without reflection and magic strings

Whilst some great refactoring tools will take care of magic strings for you, the use of them still grates on me whenever I am forced into using them and whilst using reflection can be very powerful it can also have a performance hit when used frequently.

Now, what do I mean by accessing properties?

What if you need to tell some object to use a property and its value, but it may need to access this property several times and the value might change. The last is the crux of the problem here.

If you pass the property in using standard property accessors, you will get the value as it stands at that time. If the property is mutable then this maybe ok, but what if it's not or the mutable object is replaced?

Well, you could pass the object and a magic string and use reflection to access the property when the new objects needs access, but there is always a penalty to using this approach.

However, using Lambdas and the power of closures, you now have an alternative to this approach:

Take a look at the following code:


using System;
using System.Diagnostics;

namespace ConsoleApplication1
{
class Program
{
static void Main(string[] args)
{
var vio = new SomeVeryImportantObject { VeryImportantProperty = "Top Secret" };
var moreImportantObject = new NeedInfoToWork();

moreImportantObject.SetAnothersPropertyToUseLaterUsingDelegates(() => vio.VeryImportantProperty);
moreImportantObject.SetAnothersPropertyToUseLaterUsingReflection(vio, "VeryImportantProperty");


vio.VeryImportantProperty = "Ok, not so important";

Console.WriteLine(moreImportantObject.GetValueNowUsingReflection());
Console.WriteLine(moreImportantObject.GetValueUsingClousers());

const int timesToAccess = 1000000;

var sw = Stopwatch.StartNew();

for (int i = 0; i < timesToAccess; i++)
{
var value = moreImportantObject.GetValueNowUsingReflection();
}

sw.Stop();
Console.WriteLine("Time Taken using reflection {0}ms", sw.ElapsedMilliseconds);
sw.Reset();
sw.Start();

for (int i = 0; i < timesToAccess; i++)
{
var value = moreImportantObject.GetValueUsingClousers();
}

sw.Stop();
Console.WriteLine("Time Taken using closures {0}ms", sw.ElapsedMilliseconds);

Console.ReadKey();
}
}

public class SomeVeryImportantObject
{
public string VeryImportantProperty { get; set; }
}

public class NeedInfoToWork
{
private Func _propertyAccess;
private object _objectToAccess;
private string _propertyName;

public void SetAnothersPropertyToUseLaterUsingDelegates(Func propertyAccess)
{
_propertyAccess = propertyAccess;
}

public void SetAnothersPropertyToUseLaterUsingReflection(Object objectToGetPropertyValueFrom, string propertyName)
{
_objectToAccess = objectToGetPropertyValueFrom;
_propertyName = propertyName;
}

public string GetValueNowUsingReflection()
{
return _objectToAccess.GetType()
.GetProperty(_propertyName)
.GetValue(_objectToAccess, null)
.ToString();
}

public string GetValueUsingClousers()
{
return _propertyAccess();
}
}
}


This produced the following results on my computer:

> Ok, not so important
> Ok, not so important
> Time Taken using reflection 2076ms
> Take Taken using closures 56ms

Enough said.

We have improved performance and removed the use of magic strings.

Submit this story to DotNetKicks Shout it

Code Generation - yield and Lambdas

So, while I don't profess to be an expert on Code Generation, I do hope that some of the tips that I put up here may save someone else the time it took me to figure out how to accomplish what appear to be simple steps.

At the time of writing this post, and having spent several hours scouring the internet, I couldn't for the life of me find a way to get a yield return statement.

The reason for this will be explained in another post (TODO:addlink) but the basic premise was to have the following line in the generated class:

   01 yield return () => SomeStringProperty;

All the properties returned strings, so this was fine.

Trying to generate this was proving a problem, until I came across this...hmm...workaround (don't want to use the word hack here)
While it ties the generated code to be specifically C#, this, again was not a problem for the code base that we were working against.

Here is the code that produced the line:

  01 generatedProperty.GetStatements.Add(new CodeSnippetExpression(string.Format("yield return () => {0}", existingProperty.Name)));

The genereatedProperty is of type CodeMemberProperty as is the existingProperty.

I wouldn't recommend this for all solutions, but it worked in this case where we were not trying to add to a generic code generator.

Submit this story to DotNetKicks Shout it

Wednesday 3 June 2009

Code Generation - Attributes with Enum Values

Adding attributes to a class seemed straight forward when writting a class to do some code generation, adding Enum values to the attribute didn't.

Here is the code for adding an attribute with a string value:

    1 type.CustomAttributes.Add(
    2     new CodeAttributeDeclaration(new CodeTypeReference(typeof (RangeAttribute)),
    3                                  new CodeAttributeArgument("Min",
    4                                                            new CodePrimitiveExpression("1"))));

Knowing how to add the Enum wasn't at first obvious until (after some googling and experimentation) I figured out that an enum value is really a field...obvious...

...ok, not so, but here is the result:

    1 var enumTypeExpression = new CodeTypeReferenceExpression(typeof(Format));
    2 var enumValueExpression = new CodeFieldReferenceExpression(enumTypeExpression, Format.Bool.ToString());
    3 
    4 type.CustomAttributes.Add(
    5     new CodeAttributeDeclaration(
    6         new CodeTypeReference(typeof (FormatAttribute)),
    7         new CodeAttributeArgument("Format", enumValueExpression)));

Submit this story to DotNetKicks Shout it

Testing Code Generation and System.Xml file version

I found a very interesting problem the other day whilst trying to write automated test for a class that generated code.

I started by creating a file with what I expected the generated code to look like as my code generator was dumping its output straight to a file and then comparing the outcome. All went well and my tests past. Things only started to get strange when I checked in my code and it hit the CI server. The test started to fail.

By default the Code generator was putting the following attribute at the top of my classes:

[System.CodeDom.Compiler.GeneratedCodeAttribute("System.Xml", "TOKEN_VERSION")]

Where TOKEN_VERSION was the file version of the System.Xml.dll assembly. Wierdly enough the version of this file on the CI server was different, but only at the file level. Now My machine and the CI server bothe had 3.5 SP1 installed and so I was baffled. I did some googling and found that many different applications can install different version of this file. So then I decided to use a token in my expected file and change this with the actual version when the test was ran. I could have chosen to remove the attribute altogether, but this was the chosen path...

I was unaware of the following class but found it very useful in getting the file version, here is the end code:

    1 var assembly = AppDomain.CurrentDomain.GetAssemblies().First(a => a.GetName().Name == "System.Xml");
    2 
    3 var version = FileVersionInfo.GetVersionInfo(new Uri(assembly.CodeBase).AbsolutePath).ProductVersion;

Simple eh?

Submit this story to DotNetKicks Shout it

Performance - Lambdas and closures

Whilst performance tuning a recent application, I noticed that the logging was taking an awfully long time, now, whilst this may not come as a surprise in some cases, it came as a surprise being as logging was turned off. Let me explain...

In the application, all BOs use reflection to create a string version of themselves. We were using log4net to do our logging and we were even checking that specific levels of logging were turned on before performing the logging using the simple checks:

    1 private static void WriteToLog(LogLevel logLevel, ILog log, string msg, Exception e)
    2 {
    3     switch (logLevel)
    4     {
    5         case LogLevel.All:
    6         case LogLevel.Trace:
    7             if (log.IsTraceEnabled)
    8             {
    9                 if (e == null) log.Trace(msg);
   10                 else log.Trace(msg, e);
   11             }
   12             break;
   13         case LogLevel.Debug:
   14             if (log.IsDebugEnabled)
   15             {
   16                 if (e == null) log.Debug(msg);
   17                 else log.Debug(msg, e);
   18             }
   19             break;
   20         case LogLevel.Error:
   21             if (log.IsErrorEnabled)
   22             {
   23                 if (e == null) log.Error(msg);
   24                 else log.Error(msg, e);
   25             }
   26             break;
   27         case LogLevel.Fatal:
   28             if (log.IsFatalEnabled)
   29             {
   30                 if (e == null) log.Fatal(msg);
   31                 else log.Fatal(msg, e);
   32             }
   33             break;
   34         case LogLevel.Info:
   35             if (log.IsInfoEnabled)
   36             {
   37                 if (e == null) log.Info(msg);
   38                 else log.Info(msg, e);
   39             }
   40             break;
   41         case LogLevel.Warn:
   42             if (log.IsWarnEnabled)
   43             {
   44                 if (e == null) log.Warn(msg);
   45                 else log.Warn(msg, e);
   46             }
   47             break;
   48         case LogLevel.Off:
   49         default:
   50             break;
   51     }
   52 }

So we were taking all the precautions except the most obvious one: we were creating the msg to log even if we didn't log the msg.

The problem that I was now facing was that we had a generic method for writting the log but the methods that wanted to be called on demand didn't. This is where lambdas and closures came in nice and handy. By creating a lambda and passing in the arguments for creating the message in, this defered the execution of the creation of the message until it was time to write the message:

    1 private static void WriteToLog(LogLevel logLevel, ILog log, Func<string> getMessage, Exception e)
    2 {
    3     switch (logLevel)
    4     {
    5         case LogLevel.All:
    6         case LogLevel.Trace:
    7             if (log.IsTraceEnabled)
    8             {
    9                 if (e == null) log.Trace(getMessage());
   10                 else log.Trace(getMessage(), e);
   11             }
   12             break;
   13         case LogLevel.Debug:
   14             if (log.IsDebugEnabled)
   15             {
   16                 if (e == null) log.Debug(getMessage());
   17                 else log.Debug(getMessage(), e);
   18             }
   19             break;
   20         case LogLevel.Error:
   21             if (log.IsErrorEnabled)
   22             {
   23                 if (e == null) log.Error(getMessage());
   24                 else log.Error(getMessage(), e);
   25             }
   26             break;
   27         case LogLevel.Fatal:
   28             if (log.IsFatalEnabled)
   29             {
   30                 if (e == null) log.Fatal(getMessage());
   31                 else log.Fatal(getMessage(), e);
   32             }
   33             break;
   34         case LogLevel.Info:
   35             if (log.IsInfoEnabled)
   36             {
   37                 if (e == null) log.Info(getMessage());
   38                 else log.Info(getMessage(), e);
   39             }
   40             break;
   41         case LogLevel.Warn:
   42             if (log.IsWarnEnabled)
   43             {
   44                 if (e == null) log.Warn(getMessage());
   45                 else log.Warn(getMessage(), e);
   46             }
   47             break;
   48         case LogLevel.Off:
   49         default:
   50             break;
   51     }
   52 }


And then the calls to the logging could be called as such:

    1 try
    2 {
    3     WriteToLog(LogLevel, log, () => GetEntryMessage(invocation, uniqueIdentifier), null);
    4     returnValue = invocation.Proceed();
    5 }
    6 catch (ThreadAbortException)
    7 {

   10     exitThroughException = false;
   11     throw;
   12 }
   13 catch (Exception e)
   14 {
   15     TimeSpan executionTimeSpan = DateTime.Now - startTime;
   16     WriteToLog(LogLevel, log, () => GetExceptionMessage(invocation, e, executionTimeSpan, uniqueIdentifier), e);
   17     exitThroughException = true;
   18     throw;
   19 }
   20 finally
   21 {
   22     if (!exitThroughException)
   23     {
   24         TimeSpan executionTimeSpan = DateTime.Now - startTime;
   25         WriteToLog(LogLevel, log, () => GetExitMessage(invocation, returnValue, executionTimeSpan, uniqueIdentifier), null);
   26     }
   27     ClearLogContext();
   28 }
   29 
   30 return returnValue;

No need to worry about creating overrides of the logging function to take in the different parameters or creating a master version which handled null arguments.

Submit this story to DotNetKicks Shout it

Linq Performance

Something to think carefully when using Linq is performance of certain extensions.

If you have a large in memory collection that you wish to find an element in and you know that there is only one, your first instinct maybe to use the Single operator. Now, unless you explicitly want to check that there is only one item that matches your predicate, then you will incur the overhead of always searching the entire list. But, if you know that there is only one item that should match your predicate and ensuring this isn't called for, then First should be the operator of choice as this will stop searching as soon as it finds the item that matches the predicate.

Now, whilst this might seem like a small saving, it is saving that doesn't take much thought to implement.

Submit this story to DotNetKicks Shout it

Thursday 12 March 2009

yield and iterators

I've just implemented an iterator using the new c#2 yield keyword, it took me about 5 mins and worked so easy. I love this new feature. It makes things so easy.

I had a DateTimeRange class and I needed to get the first day of every month that was covered by the range.

Here is the code:

   49 public IEnumerable<DateTime> MonthStarts

   50 {

   51     get

   52     {

   53         var current = new DateTime(Start.Year, Start.Month, 1);

   54 

   55         while (current <= End)

   56         {

   57             yield return current;

   58             current = current.AddMonths(1);

   59         }

   60     }

   61 }



This can then be used in simple foreach statements.

Submit this story to DotNetKicks Shout it

Tuesday 10 March 2009

Blogging and including code

Being new to the blogging world, my first attempt took rather longer than I thought as I was having to format all of my code in my previous blog.

After starting to do this by hand I knew that there must be an easier way but couldn't see it in the built in creator.

After a simple google search I came across this really helpful tool:

Copy Source as HTML

So, I installed this and away I went. More minutes of my life saved.

Thanks to Colin Coller for doing the work up front for this.

Submit this story to DotNetKicks Shout it

log4net logging causing the computer to beep

Whilst working on my current project, I came across a rather annoying problem:

During service calls, we log the input and output params. When we started to integration test the system and a user performed a search, a beeping could be heard from the computer.
This, obviously caused some distress to anyone near the PC as it was constant and annoying.

As this was only being heard during a search service call the first, and very incorrect thought, was that the search was very poor and sql server was struggling.

After 5 seconds of debugging I found the following line to be the cause of the problem:

logger.Info(GetExitMessage(invocation, returnValue, executionTimeSpan));

We were using reflection to generate our message and log4net as the logger. I was still unsure of what the problem was.

I looked at the message that was being generated and replicated the problem in a simple console application. I eventually got the following piece of code to reproduce the mysterious beep:

    1 using System;

    2 using log4net;

    3 

    4 namespace log4netProblem

    5 {

    6     class Program

    7     {

    8         static ILog _logger = LogManager.GetLogger(typeof(Program));

    9 

   10         static void Main(string[] args)

   11         {

   12             try

   13             {

   14                 log4net.Config.BasicConfigurator.Configure();

   15                 string s = "•";

   16                 _logger.Info(s);

   17             }

   18             catch (Exception e)

   19             {

   20                 Console.Write(e);

   21             }

   22             finally

   23             {

   24                 Console.WriteLine("Press any key to exit...");

   25                 Console.ReadKey();

   26             }

   27         }

   28     }

   29 }



Yes yes yes, I see the problem now. "•" was the shortcut for making a console beep.

It turns out that in my haste of setting up the appenders in the web application, I had left the console appender in there and the PC wasn't about to catch fire at all.

All I can say is oops.

Submit this story to DotNetKicks Shout it

Monday 2 March 2009

Debugging web apps with Visual Studio and logging with log4net

If like myself you use log4net and develop in Visual Studio, you may want to see what is being logged without having to leave the comfort of the IDE and look at a text file.

To get your logged output to appear in the output window of visual studio add this appender to your log4net configuration:

<appender name="ASPNETDebugger" type="log4net.Appender.TraceAppender">
    <layout type="log4net.Layout.SimpleLayout" />
</appender>

I've often found that I forget this little snippet of code but find it very useful when debugging a web app.

Submit this story to DotNetKicks Shout it