Showing posts with label performance. Show all posts
Showing posts with label performance. Show all posts

2009-08-06

Spring for .NET 1.3.0 Release Candidate available

Finally we made it: The next release of Spring for .NET is available for preview and brings a couple of new things as well as over 100 fixed bugs to the table. Grab the new release as usual from our website http://www.springframework.net and give it a test run. The final release is currently scheduled for the first week in September. Below I will give you a short introduction to the new features.

New Features

NVelocity Support

Erez Mazor joined the team in June and brought a nice integration of the NVelocity template library (part of the Castle project) with him. Let's asume you need to send a confirmation email after processing T-Shirt order to a customer. Most of this email will come from a template, just a few variables will be individual for each customer. Here's how such a template looks like using the Velocity Template Language: 

Dear#if ($sex == "F") Ms#else Mr#end $recipient,
 
We are happy to withdraw $1Mio from your account

Here's an example on how to use Spring.NET's integration to send an Email from your application. The configuration causes the NVelocityFactory to load templates from the NVelocityDemo assembly's "NVelocityDemo" namespace:

<objects xmlns="http://www.springframework.net" xmlns:nv="http://www.springframework.net/nvelocity">
  <nv:engine id="velocityEngine">
    <nv:resource-loader>
      <nv:spring uri="assembly://NVelocityDemo/NVelocityDemo/"/>
    </nv:resource-loader>
  </nv:engine>
 
  <object id="emailSendService" type="NVelocityDemo.EmailSendService">
    <property name="VelocityEngine" ref="velocityEngine" />
  </object>
</objects>

Here's the C# Code of my EmailSendService class:

public class EmailSendService
{
  public VelocityEngine VelocityEngine { get; private set; }

  public void SendEmail(string recipientName, string sex, string emailAddress, string subject)
  {
    Hashtable model = new Hashtable();
    model["email"] = emailAddress;
    model["recipient"] = recipientName;
    model["sex"] = sex;
    IContext modelContext = new VelocityContext(model);
    StringWriter sw = new StringWriter();
    this.VelocityEngine.MergeTemplate("confirmationEmail.vm", Encoding.UTF8.HeaderName, modelContext, sw);

    string emailContent = sw.ToString();

    // send mail
    Console.WriteLine("Sending email to {0} with subject '{1}':\n{2}", emailAddress, subject, emailContent);
  }
}

Running this example will inform our customer about our pricing for T-Shirts:

Sending email to foo@world.com with subject 'Thank you!':
Dear Mr Smith,

we are happy to withdraw $1Mio from your account
TIBCO Enterprise Message Service

Similar to our support for MSMQ and ActiveMQ, consequently there is now also support for Tibco's EMS. If you are already familiar with Spring's ActiveMQ support, you will quickly feel comfortable. To get started, check out our reference documentation and the upcoming blog post at Mark Pollack's Blog.

MS Test

Some of us are forced to write their unit tests using Microsoft's own testing framework. To support them, Spring.NET now also integrates support for writing unit and integration tests similar to the one already available for NUnit. You can find the supporting stuff in the Spring.Testing.Microsoft assembly.

Noteworthy Improvements

Testing

In response to a lot of requests, we upgraded our NUnit testing environment to the latest NUnit 2.5.1. There is also new support for writing database integration tests. Use the SimpleAdoTestUtils class to execute arbitrary SQL scripts to setup/teardown your database. An example is Spring's NHibernate Integration tests. Here is the SQL script to recreate our integration database:

IF  EXISTS (SELECT name FROM sys.databases WHERE name = N'Spring')
BEGIN
    ALTER DATABASE Spring 
        SET SINGLE_USER 
        WITH ROLLBACK IMMEDIATE

    DROP DATABASE Spring
END
GO

IF  EXISTS (SELECT * FROM sys.server_principals WHERE name = N'springqa2')
    DROP LOGIN [springqa2]
GO

CREATE DATABASE Spring
GO

CREATE LOGIN [springqa2] WITH PASSWORD=N'springqa2', DEFAULT_DATABASE=[Spring], DEFAULT_LANGUAGE=[us_english]
GO

USE Spring
CREATE USER [springqa2] FOR LOGIN [springqa2] WITH DEFAULT_SCHEMA=[dbo]
EXEC sp_addrolemember 'db_owner', 'springqa2'
GO

Now, leveraging NUnit's [SetupFixture] feature, we can easily execute this and other scripts before the execution of each fixture:

[SetUpFixture]
public class Setup
{
  private const string DBConnection = "Data Source=SPRINGQA;Database=$DATABASE$;Trusted_Connection=False;User ID=springqa;Password=springqa";
  private readonly IResourceLoader resourceLoader = new ConfigurableResourceLoader();

  private IResource GetResource(object instance, string name)
  {
    string resourcePath = TestResourceLoader.GetAssemblyResourceUri(instance, name);
    return resourceLoader.GetResource(resourcePath);
  }

  [SetUp]
  public void InstallMSSQLDatabase()
  {
    IDbProvider dbProvider = DbProviderFactory.GetDbProvider("SqlServer-2.0");
    AdoTemplate ado = new AdoTemplate(dbProvider);

    // (re-)create database(s)
    dbProvider.ConnectionString = DBConnection.Replace("$DATABASE$", "master");
    SimpleAdoTestUtils.ExecuteSqlScript(ado, GetResource(this, "RecreateDatabases.sql"));

    // create tables
    dbProvider.ConnectionString = DBConnection.Replace("$DATABASE$", "Spring");
    SimpleAdoTestUtils.ExecuteSqlScript(ado, GetResource(this, "Data.NHibernate/creditdebit.sql"));
    SimpleAdoTestUtils.ExecuteSqlScript(ado, GetResource(this, "Data.NHibernate/testObject.sql"));
  }
}

Using the new NVelocity integration, you could even easily parameterize your SQL scripts for different environments.

Configuration Error Handling

Previously sometimes it was hard to read configuration errors. I put some effort into reducing this pain and make the error messages much more explicit. Now you get the exact filename + linenumber of the offending object definition and also a more detailled explanation, what is causing the problem.

AOP Performance

The performance of AOP proxies at runtime improved, but also *creating* such singleton proxies at startup time could cause some issues. You now get a bunch of different Auto-Proxy processor implementations to choose from to better suite your exact needs.

Sometimes using <tx:attribute-driven /> or <aop:config> could cause issues when an additional XXXAutoProxyCreator was defined in your configuration. This roots in the fact that those 2 configuration elements silently registered their own DefaultAutoProxyCreator under the hoods. This is now taken care of and it is guaranteed that infrastructure AOP elements will not interfere with user-defined ones anymore.

Feedback welcome

The release will be in ~ 3-4 weeks, so please grab a copy of the release candidate and give it a whirl - We'd be happy to get your feedback!

2009-05-04

Common Logging 2.0 for .NET Released

Last week I released a new version of Common Logging 2.0 for the .NET platform. You can get the distribution as well as online API and User Reference documentation from the project website. For users of previous versions there is also a section about upgrading to 2.0.

What is Common.Logging?

Similar to Java's Apache commons-logging, Common.Logging is an ultra-thin brigde between different .NET logging implementations based on original work done by the iBatis.NET team. A framework or library using Common.Logging can be used with any logging implementation at runtime and thus doesn't lock a user to a specific framework or worse letting him struggle with different frameworks using different logging implementations.

image

Common.Logging comes with adapters for all popular logging implementations like log4net and Enterprise Library Logging.

Bridging between logging implementations

You might run into the problem, that libraries used by your application use different logging implementations. Common.Logging allows you to route from those implementations into any logging system of your choice:

image

Please see reference documentation for an example on how to configure such a bridging scenario.

What's new in 2.0?

Several extensions and improvements were made, namly

  • Dropped .NET 1.1 Support
  • Added support for Enterprise Library 4.1 Logging
  • Extended and improved ILog Interface
  • Convenience LogManager.GetCurrentClassLogger() Method
  • Bi-directional log event routing between logging implementations (see bridging above)
  • Improved performance

I already blogged about comparing Common.Logging performance to System.Diagnostics.Trace. According to a thread on stackoverflow, log4net seems even slower than System.Diagnostics.Trace.

Configuring Common.Logging

For examples on how to configure and use Common.Logging and bridge different logging implementations, please see the user refererence guide. The API documentation contains configuration and usage examples on each adapter implementation. Here is an example for configuring Common.Logging to write messages to the console:

<configuration>
<configSections>
 <sectionGroup name="common">
   <section name="logging"
            type="Common.Logging.ConfigurationSectionHandler, Common.Logging"
            requirePermission="false" />
 </sectionGroup>
</configSections>
<common>
 <logging>
   <factoryAdapter type="Common.Logging.Simple.ConsoleOutLoggerFactoryAdapter, Common.Logging">
     <arg key="level" value="ALL" />
   </factoryAdapter>
 </logging>
</common>
</configuration>

Using Common.Logging

Using Common.Logging is as simple as shown below:

ILog log = LogManager.GetCurrentClassLogger();
log.DebugFormat("Hi {0}", "dude");

Hint: When using NET 3.5, you can leverage lambda syntax for logging to avoid any performance penalties:

log.Debug( m=>m("value= {0}", obj.ExpensiveToCalculateInformation()) );

This is the equivalent to writing

if (log.IsDebugEnabled)
{
 log.Debug("value={0}", obj.ExpensiveToCalculateInformation());
}

and ensures that you don't have to pay for calculating the debug information message in case level "Debug" is disabled.

Further Roadmap

The following features and improvements are planned for the next release, some of them already in the works:

Of course I would like to invite you to submit any feature request, bug reports or other improvement suggestions to the project's issue tracker.

Happy logging!

2009-01-27

Thoughts on System.Diagnostics Trace vs. Common.Logging

While working on the final bits for Common.Logging 2.0 I just looked a bit closer into NET’s trace model and tried to compare it to Common.Logging. I must admit that, being a long-time user of first log4net and then Common.Logging, I never much cared about <system.diagnostics>. Revisiting assumptions from time to time is a good habit, thus I dived into .NET tracing. Here’s what I found…

Configure and use <system.diagnostics>

The .NET trace system basically works by using TraceSources (="Logger" in log4net) to write events to a list of TraceListeners (="Appenders") that decide whether a message to log by consulting a list of TraceFilters. This could be useful, alas there is no "batch" configuration possible, means you need to configure this chain for each TraceSource. Here's a minimum example what one needs to do:

<system.diagnostics>
    <sharedListeners>
        <add name="myListener"
             type="MyTestTraceListener, MyAssembly" />
    </sharedListeners>
    <sources>
        <source name="mySource" switchValue="All">
            <listeners>
                <add name="myListener" />
            </listeners>
        </source>
    </sources>
</system.diagnostics>    

Your code will then look like this:

class MyClass
{
    readonly TraceSource trace = new TraceSource("mySource");
    void Foo(object someArg)
    {
        try
        {
            Bar(someArg);
        }
        catch (Exception ex)
        {
            trace.TraceEvent(TraceEventType.Information, -1,
            "error arg={0}:{1}", someArg, ex);
        }
    }

    void Bar(object someArg) { /* do something */}
}

A nice tutorial on tracing is given in this blog, some criticism is found here.

Performance Considerations

Of course you don’t want to pay much performance costs for your logging infrastructure. Fortunately tracing doesn’t cost you too much. I wrote some tests in Common.Logging to compare both and found Common.Logging twice as fast as Trace. Note, that we are talking about 2s vs. 4s for passing 100.000.000 log entries through the chain. I do not think that this is an issue for anyone except for applications generating an insane number of log entries.

Things get interesting when evaluating a log message becomes expensive. Take for example the line from the example above:

  trace.TraceEvent(TraceEventType.Information, -1,
"error arg={0}:{1}", someArg, ex);

Somewhere within the tracing framework, the passed string and arguments must be evaluated and string.Format() gets called. But you do not want this to happen unless that message *really* gets logged – string.Format() calls both, someArg.ToString() and ex.ToString(), which might be very expensive to calculate!

To be safe, you need to wrap all your calls by

if ( trace.Switch.ShouldTrace(TraceEventType.Information) )
{
trace.TraceEvent(TraceEventType.Information, -1,
"error arg={0}:{1}", someArg, ex);
}

Unfortunately this doesn’t help in all cases. Most often you want all messages from all (or at least most) modules but only the informational ones (not the verbose). You can configure this using a filter:

<system.diagnostics>
    <sharedListeners>
        <add name="myListener"
             type="MyTestTraceListener, MyAssembly">
            <filter type="System.Diagnostics.EventTypeFilter"
                    initializeData="Information"/>
        </add>
    </sharedListeners>
    <sources>
        <source name="mySource" switchValue="All">
            <listeners>
                <add name="myListener" />
            </listeners>
        </source>
    </sources>
</system.diagnostics>

Using the configuration above, all messages will be passed into “myListener”, who’s filter will drop all messages above the information level. Unfortunately there is another issue: The framework automatically adds a DefaultTraceListener to all configured <source>s that will happily log all messages. To avoid this you need to write

<source name="mySource" switchValue="All">
    <listeners>
        <!-- prevent DefaultTraceListener from being added -->
        <clear />
        <add name="myListener" />
    </listeners>
</source>

I wrote some performance tests simulating the case where we only want to log Warnings. Messages are emitted at “Info” level, but the configuration should restrict messages to “Warning”s. On my box this resulted in

Time:00:00:01.9640000 - log.InfoFormat + NoOpLogger
Time:00:00:04.8410000 - traceSource.TraceEvent + unconfigured TraceSource
Time:00:00:03.6140000 - log.InfoFormat
Time:00:00:12.7380000 - traceSource.TraceEvent

As you can see, using tracing gets significant slower using the configuration above. Frankly I could not figure out what causes this. Things become unacceptable as soon as you forget to remove the DefaultTraceLogger:

Time:00:00:00.6670000 - log.InfoFormat + NoOpLogger 
Time:00:00:02.2950000 - traceSource.TraceEvent + unconfigured TraceSource 
Time:00:00:02.2250000 - log.InfoFormat 
Time:01:00:23.8650000 - traceSource.TraceEvent <= not kidding here!

For this reason, Common.Logging introduced a new signature for logging leveraging the power of lambda expressions:

  log.Info( m=>m("some logger info {0}", (object)myObj) )
Using this syntax you will always be on the safe side. Common.Logging will take care, that the message will only be evaluated in case it really gets logged.
Conclusion

What bothers me most is the pain of configuring & using the trace framework. Here are the major pain points I found with the built-in tracing framework:

  • It is possible to share listeners, but you need to configure the list of listeners for each TraceSource.
  • It is impossible to configure a default listener to be used by all TraceSources
  • There is no logging of exception objects possible
  • One can instruct a TraceListener to append the current callstack to the message, but this will include the System.Diagnostics stack(!)
  • No easy way for "batch" configuring log levels for multiple sources (like in log4net logger hierarchies), each source must be explicitly configured with level+listener
  • As soon as one configures the listeners for a TraceSource, a DefaultTraceListener will also be added to the list, causing each message to be logged to OutputDebugString as well (add a <clear/> element to the sample above.
  • It is incredible verbose to use, both tracing and configuring

If one insists on avoiding a dependency on Common.Logging or log4net, go with tracing – you’ve been warned.

For all others I recommend grabbing Common.Logging. It allows you to defer the decision of which logging framework to use until the moment you deploy your application. Simply plug in any other logging system you might want to use. If you need to turn off logging at all, configure NoOpLoggerFactoryAdapter and minimize the costs of your log statements to almost zero - guaranteed!