NHibernate Performance Testing

Revision as of 08:45, 1 January 2009

Here are results from performance tests run on SQLite and MySQL database.

Empty Tables

Remote MySQL results with 10ms ping with MyISAM:

2009-01-01 18:41:08,928 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Inserting 100 objects.
2009-01-01 18:41:10,182 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:01.2540000
2009-01-01 18:41:10,183 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Updating 100 objects.
2009-01-01 18:41:12,691 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:02.5080000
2009-01-01 18:41:12,691 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Selecting 100 objects by id.
2009-01-01 18:41:17,160 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:04.4690000
2009-01-01 18:41:17,161 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Selecting 100 objects at once.
2009-01-01 18:41:17,299 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.1380000
2009-01-01 18:41:17,299 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Deleting 100 objects.
2009-01-01 18:41:18,664 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:01.3650000

Local MySQL results with InnoDB:

2009-01-01 18:39:23,637 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Inserting 100 objects.
2009-01-01 18:39:23,661 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0230000
2009-01-01 18:39:23,663 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Updating 100 objects.
2009-01-01 18:39:23,724 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0610000
2009-01-01 18:39:23,726 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Selecting 100 objects by id.
2009-01-01 18:39:23,769 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0430000
2009-01-01 18:39:23,771 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Selecting 100 objects at once.
2009-01-01 18:39:23,844 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0730000
2009-01-01 18:39:23,846 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Deleting 100 objects.
2009-01-01 18:39:23,866 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0200000

Local MySQL results with MyISAM:

2009-01-01 18:38:39,584 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Inserting 100 objects.
2009-01-01 18:38:39,598 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0130000
2009-01-01 18:38:39,599 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Updating 100 objects.
2009-01-01 18:38:39,639 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0400000
2009-01-01 18:38:39,640 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Selecting 100 objects by id.
2009-01-01 18:38:39,686 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0460000
2009-01-01 18:38:39,686 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Selecting 100 objects at once.
2009-01-01 18:38:39,762 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0760000
2009-01-01 18:38:39,763 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Deleting 100 objects.
2009-01-01 18:38:39,777 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0140000

Local SQLite results:

2009-01-01 18:44:02,623 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Inserting 100 objects.
2009-01-01 18:44:02,660 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0370000
2009-01-01 18:44:02,660 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Updating 100 objects.
2009-01-01 18:44:02,710 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0500000
2009-01-01 18:44:02,711 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Selecting 100 objects by id.
2009-01-01 18:44:02,751 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0400000
2009-01-01 18:44:02,752 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Selecting 100 objects at once.
2009-01-01 18:44:02,823 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0710000
2009-01-01 18:44:02,823 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Deleting 100 objects.
2009-01-01 18:44:02,860 [TestRunnerThread] INFO  Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0370000

Test test code:

using System;
using System.Collections.Generic;
using System.Text;
using NUnit.Framework;
using NHibernate;
using NHibernate.Cfg;
using System.IO;
using NHibernate.Tool.hbm2ddl;
using log4net.Repository.Hierarchy;
using log4net;
using log4net.Config;
using System.Collections;

namespace Example.Library.Resources
{

    [TestFixture]
    public class DatabaseTest
    {
        private static readonly ILog log = LogManager.GetLogger(typeof(DatabaseTest));
        private ISessionFactory sessions;

        [SetUp]
        public void SetUp()
        {
            // log4net configuration
            XmlConfigurator.Configure(); 
            //BasicConfigurator.Configure();


            // hibernate configuration
            Configuration configuration = new Configuration();
            configuration.AddAssembly(this.GetType().Assembly);
            
            if (configuration.Properties["dialect"].Equals("NHibernate.Driver.SQLite20Driver")&&
                !File.Exists("OpenSimExample.db"))
            {
                SchemaExport schemaExport = new SchemaExport(configuration);
                schemaExport.Create(true, true);
            }

            foreach(String key in configuration.Properties.Keys)
            {
                log.Info(key+": "+configuration.Properties[key]);
            }

            sessions = configuration.BuildSessionFactory();
        }

        [Test]
        public void TestDatabase()
        {

            using (IStatelessSession session = sessions.OpenStatelessSession())
            {

                using (ITransaction transaction = session.BeginTransaction())
                {

                    TestObject newObject = new TestObject();
                    newObject.TestId = Guid.NewGuid();
                    newObject.Name = "test-name";
                    session.Insert(newObject);

                    TestObject loadedObject = (TestObject)session.Get("Example.Library.Resources.TestObject", newObject.TestId);
                    Assert.AreEqual(newObject.Name,loadedObject.Name);

                    session.Delete(loadedObject);
                    transaction.Commit();

                }

            }
          
        }

        [Test]
        public void TestDatabasePerformance()
        {
            int objectCount = 100;
            List<TestObject> testObjects = new List<TestObject>();
            DateTime timeStamp;

            log.Info("Inserting " + objectCount + " objects");

            timeStamp = DateTime.Now;
            using (IStatelessSession session = sessions.OpenStatelessSession())
            {

                using (ITransaction transaction = session.BeginTransaction())
                {

                    for (int i = 0; i < objectCount; i++)
                    {
                        TestObject newObject = new TestObject();
                        newObject.TestId = Guid.NewGuid();
                        newObject.Name = "test-name";
                        session.Insert(newObject);

                        testObjects.Add(newObject);
                    }

                    transaction.Commit();
                }
            
            }

            log.Info("Took: " + DateTime.Now.Subtract(timeStamp));
            timeStamp = DateTime.Now;
            log.Info("Selecting " + objectCount + " objects by id");

            using (IStatelessSession session = sessions.OpenStatelessSession())
            {

                for (int i = 0; i < objectCount; i++)
                {
                    TestObject oldObject = testObjects[i];

                    TestObject loadedObject = (TestObject)session.Get("Example.Library.Resources.TestObject", oldObject.TestId);
                    Assert.AreEqual(oldObject.Name, loadedObject.Name);
                    testObjects[i] = loadedObject;

                }

            }

            log.Info("Took: " + DateTime.Now.Subtract(timeStamp));
            timeStamp = DateTime.Now;
            log.Info("Selecting " + objectCount + " objects at once");

            using (IStatelessSession session = sessions.OpenStatelessSession())
            {

                IQuery q = session.CreateQuery("from Example.Library.Resources.TestObject");
                IList loadedObjects = q.List();

                foreach (TestObject testObject in loadedObjects)
                {
                }

                Assert.AreEqual(objectCount, testObjects.Count);

            }

            log.Info("Took: " + DateTime.Now.Subtract(timeStamp));
            timeStamp = DateTime.Now;
            log.Info("Deleting " + objectCount + " objects");

            using (IStatelessSession session = sessions.OpenStatelessSession())
            {

                using (ITransaction transaction = session.BeginTransaction())
                {

                    for (int i = 0; i < objectCount; i++)
                    {


                        TestObject loadedObject = testObjects[i];
                        session.Delete(loadedObject);

                    }

                    transaction.Commit();
                }

            }

            log.Info("Took: " + DateTime.Now.Subtract(timeStamp));
            timeStamp = DateTime.Now;

        }
    }
}

The configuration for the test dll:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>

  <configSections>    
    <section name="hibernate-configuration" type="NHibernate.Cfg.ConfigurationSectionHandler, NHibernate" />
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
  </configSections>

  <hibernate-configuration xmlns="urn:nhibernate-configuration-2.2">

    <!--
    <session-factory>
      <property name="connection.provider">NHibernate.Connection.DriverConnectionProvider</property>
      <property name="connection.driver_class">NHibernate.Driver.SQLite20Driver</property>
      <property name="connection.connection_string">
        Data Source=OpenSimExample.db;Version=3
      </property>
      <property name="dialect">NHibernate.Dialect.SQLiteDialect</property>
      <property name="query.substitutions">true=1;false=0</property>
      <property name="show_sql">false</property>
    </session-factory>
    -->

    <session-factory>
      
      <property name="connection.provider">
        NHibernate.Connection.DriverConnectionProvider, NHibernate
      </property>
      <property name="connection.connection_string">
        Server=server;Database=database;User ID=user;Password=password
      </property>
      <property name="dialect">NHibernate.Dialect.MySQL5Dialect</property>

    </session-factory>
    
  </hibernate-configuration>

  <log4net debug="false">
    
    <appender name="ColoredConsoleAppender" type="log4net.Appender.ColoredConsoleAppender">
      <mapping>
        <level value="ERROR" />
        <foreColor value="White" />
        <backColor value="Red, HighIntensity" />
      </mapping>
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread] %-5level %logger [%property{NDC}] - %message%newline" />
      </layout>
    </appender>
    <root>
      <priority value="ERROR" />
      <appender-ref ref="ColoredConsoleAppender" />
    </root>
    <logger name="Example.Library">
      <level value="INFO" />
    </logger>

  </log4net>


</configuration>