NHibernate Performance Testing

Revision as of 09:10, 1 January 2009

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

Empty Tables

Local machine is Windows Vista 64 bit with Quad Core processor with 4G memory. MySQL has factory settings.

Remote mysql database machine is Ubuntu Linux virtual machine with one virtual processor and 2G memory. MySQL has factory settings.

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>