NHibernate Performance Testing
From OpenSimulator
Here are results from NHibernate performance tests run on SQLite and MySQL database. In the test 1000 rows are inserted, updated, selected and deletes against tables with 0 and 10000 rows initially. Remote MySQL is added to demonstrate the network lag effect when batch operations are not used (It seems NHibernate does not support batch inserts, updates and deletes for MySQL). Some background information:
- Local machine is Windows Vista 64 bit with Quad Core processor and 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.
- Local machine ping is 10 ms to the remote machine.
- Performance test is execute with NAnt and .NET-framework 2.0.
Contents |
Results with Initially Empty Tables
Remote MySQL results with MyISAM
2009-01-01 19:31:21,796 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Dialect: NHibernate.Dialect.MySQL5Dialect 2009-01-01 19:33:19,216 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Inserting 1000 objects to table with 0 initial objects. 2009-01-01 19:33:30,623 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:11.4070000 2009-01-01 19:33:30,624 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Updating 1000 objects to table with 0 initial objects. 2009-01-01 19:33:53,526 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:22.9030000 2009-01-01 19:33:53,528 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Selecting 1000 objects by id from table with 0 initial objects. 2009-01-01 19:34:37,263 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:43.7350000 2009-01-01 19:34:37,264 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Selecting 1000 objects at once from table with 0 initial objects. 2009-01-01 19:34:37,383 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.1190000 2009-01-01 19:34:37,384 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Deleting 1000 objects from table with 0 initial objects. 2009-01-01 19:34:48,952 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:11.5680000
Local MySQL results with InnoDB
2009-01-01 19:44:26,425 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Dialect: NHibernate.Dialect.MySQL5Dialect 2009-01-01 19:44:28,267 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Inserting 1000 objects to table with 10000 initial objects. 2009-01-01 19:44:28,429 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.1620000 2009-01-01 19:44:28,429 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Updating 1000 objects to table with 10000 initial objects. 2009-01-01 19:44:28,799 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.3700000 2009-01-01 19:44:28,800 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Selecting 1000 objects by id from table with 10000 initial objects. 2009-01-01 19:44:29,209 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.4090000 2009-01-01 19:44:29,210 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Selecting 1000 objects at once from table with 10000 initial objects. 2009-01-01 19:44:29,226 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0160000 2009-01-01 19:44:29,226 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Deleting 1000 objects from table with 10000 initial objects. 2009-01-01 19:44:29,358 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.1320000
Local MySQL results with MyISAM
2009-01-01 19:46:08,213 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Dialect: NHibernate.Dialect.MySQL5Dialect 2009-01-01 19:46:11,436 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Inserting 1000 objects to table with 10000 initial objects. 2009-01-01 19:46:11,550 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.1120000 2009-01-01 19:46:11,552 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Updating 1000 objects to table with 10000 initial objects. 2009-01-01 19:46:11,868 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.3160000 2009-01-01 19:46:11,870 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Selecting 1000 objects by id from table with 10000 initial objects. 2009-01-01 19:46:12,295 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.4250000 2009-01-01 19:46:12,296 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Selecting 1000 objects at once from table with 10000 initial objects. 2009-01-01 19:46:12,313 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0170000 2009-01-01 19:46:12,315 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Deleting 1000 objects from table with 10000 initial objects. 2009-01-01 19:46:12,456 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.1410000
Local SQLite results
2009-01-01 19:30:14,206 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Dialect: NHibernate.Dialect.SQLiteDialect 2009-01-01 19:30:14,923 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Inserting 1000 objects to table with 0 initial objects. 2009-01-01 19:30:15,169 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.2460000 2009-01-01 19:30:15,169 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Updating 1000 objects to table with 0 initial objects. 2009-01-01 19:30:15,391 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.2220000 2009-01-01 19:30:15,391 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Selecting 1000 objects by id from table with 0 initial objects. 2009-01-01 19:30:15,871 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.4800000 2009-01-01 19:30:15,872 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Selecting 1000 objects at once from table with 0 initial objects. 2009-01-01 19:30:15,891 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0190000 2009-01-01 19:30:15,891 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Deleting 1000 objects from table with 0 initial objects. 2009-01-01 19:30:15,937 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0460000
Results with Tables Containing Initially 10000 Rows
Remote MySQL results with MyISAM
2009-01-01 19:38:17,164 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Dialect: NHibernate.Dialect.MySQL5Dialect 2009-01-01 19:40:12,072 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Inserting 1000 objects to table with 10000 initial objects. 2009-01-01 19:40:23,514 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:11.4420000 2009-01-01 19:40:23,514 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Updating 1000 objects to table with 10000 initial objects. 2009-01-01 19:40:46,659 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:23.1450000 2009-01-01 19:40:46,660 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Selecting 1000 objects by id from table with 10000 initial objects. 2009-01-01 19:41:29,235 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:42.5750000 2009-01-01 19:41:29,236 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Selecting 1000 objects at once from table with 10000 initial objects. 2009-01-01 19:41:29,367 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.1310000 2009-01-01 19:41:29,367 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Deleting 1000 objects from table with 10000 initial objects. 2009-01-01 19:41:40,746 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:11.3790000
Local MySQL results with InnoDB
2009-01-01 19:17:44,493 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Inserting 100 objects. 2009-01-01 19:17:44,525 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0200000 2009-01-01 19:17:44,525 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Updating 100 objects. 2009-01-01 19:17:44,591 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0660000 2009-01-01 19:17:44,592 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Selecting 100 objects by id. 2009-01-01 19:17:44,642 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0500000 2009-01-01 19:17:44,643 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Selecting 100 objects at once. 2009-01-01 19:17:44,649 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0060000 2009-01-01 19:17:44,649 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Deleting 100 objects. 2009-01-01 19:17:44,675 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0260000
Local MySQL results with MyISAM
2009-01-01 19:20:07,657 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Inserting 100 objects. 2009-01-01 19:20:07,683 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0130000 2009-01-01 19:20:07,685 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Updating 100 objects. 2009-01-01 19:20:07,727 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0420000 2009-01-01 19:20:07,728 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Selecting 100 objects by id. 2009-01-01 19:20:07,774 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0460000 2009-01-01 19:20:07,776 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Selecting 100 objects at once. 2009-01-01 19:20:07,781 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0050000 2009-01-01 19:20:07,782 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Deleting 100 objects. 2009-01-01 19:20:07,799 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0170000
Local SQLite results
2009-01-01 19:47:14,320 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Dialect: NHibernate.Dialect.SQLiteDialect 2009-01-01 19:47:15,469 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Inserting 1000 objects to table with 10000 initial objects. 2009-01-01 19:47:15,881 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.4120000 2009-01-01 19:47:15,882 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Updating 1000 objects to table with 10000 initial objects. 2009-01-01 19:47:16,138 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.2560000 2009-01-01 19:47:16,138 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Selecting 1000 objects by id from table with 10000 initial objects. 2009-01-01 19:47:16,619 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.4810000 2009-01-01 19:47:16,619 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Selecting 1000 objects at once from table with 10000 initial objects. 2009-01-01 19:47:16,639 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.0200000 2009-01-01 19:47:16,640 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Deleting 1000 objects from table with 10000 initial objects. 2009-01-01 19:47:17,042 [TestRunnerThread] INFO Example.Library.Resources.DatabaseTest [(null)] - Took: 00:00:00.4020000
Performance Test Code and Configuration
NUnit 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 DatabasePerformanceTest
{
private static readonly ILog log = LogManager.GetLogger(typeof(DatabaseTest));
private ISessionFactory sessions;
private const int INITIAL_OBJECT_COUNT = 10000;
private const int TEST_OBJECT_COUNT = 1000;
[SetUp]
public void SetUp()
{
// log4net configuration
XmlConfigurator.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);
}
log.Info("Dialect: " + configuration.Properties["dialect"]);
sessions = configuration.BuildSessionFactory();
using (IStatelessSession session = sessions.OpenStatelessSession())
{
using (ITransaction transaction = session.BeginTransaction())
{
IQuery q = session.CreateQuery("from Example.Library.Resources.TestObject");
IList loadedObjects = q.List();
foreach (TestObject testObject in loadedObjects)
{
session.Delete(testObject);
}
transaction.Commit();
}
using (ITransaction transaction = session.BeginTransaction())
{
for (int i = 0; i < INITIAL_OBJECT_COUNT; i++)
{
TestObject newObject = new TestObject();
newObject.TestId = Guid.NewGuid();
newObject.Name = "test-object-" + i;
session.Insert(newObject);
}
transaction.Commit();
}
}
}
[Test]
public void TestDatabasePerformance()
{
List<TestObject> testObjects = new List<TestObject>();
DateTime timeStamp;
log.Info("Inserting " + TEST_OBJECT_COUNT + " objects to table with " + INITIAL_OBJECT_COUNT + " initial objects.");
timeStamp = DateTime.Now;
using (IStatelessSession session = sessions.OpenStatelessSession())
{
using (ITransaction transaction = session.BeginTransaction())
{
for (int i = 0; i < TEST_OBJECT_COUNT; i++)
{
TestObject newObject = new TestObject();
newObject.TestId = Guid.NewGuid();
newObject.Name = "test-object-" + i;
session.Insert(newObject);
testObjects.Add(newObject);
}
transaction.Commit();
}
}
log.Info("Took: " + DateTime.Now.Subtract(timeStamp));
timeStamp = DateTime.Now;
log.Info("Updating " + TEST_OBJECT_COUNT + " objects to table with " + INITIAL_OBJECT_COUNT + " initial objects.");
using (IStatelessSession session = sessions.OpenStatelessSession())
{
using (ITransaction transaction = session.BeginTransaction())
{
for (int i = 0; i < TEST_OBJECT_COUNT; i++)
{
TestObject oldObject = testObjects[i];
TestObject loadedObject = (TestObject)session.Get("Example.Library.Resources.TestObject", oldObject.TestId);
session.Update(loadedObject);
}
transaction.Commit();
}
}
log.Info("Took: " + DateTime.Now.Subtract(timeStamp));
timeStamp = DateTime.Now;
log.Info("Selecting " + TEST_OBJECT_COUNT + " objects by id from table with " + INITIAL_OBJECT_COUNT + " initial objects.");
using (IStatelessSession session = sessions.OpenStatelessSession())
{
for (int i = 0; i < TEST_OBJECT_COUNT; 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 " + TEST_OBJECT_COUNT + " objects at once from table with " + INITIAL_OBJECT_COUNT + " initial objects.");
using (IStatelessSession session = sessions.OpenStatelessSession())
{
IQuery q = session.CreateQuery("from Example.Library.Resources.TestObject");
q.SetMaxResults(TEST_OBJECT_COUNT);
IList loadedObjects = q.List();
foreach (TestObject testObject in loadedObjects)
{
// Make sure object is not lazy loaded.
Guid id = testObject.TestId;
String name = testObject.Name;
}
Assert.AreEqual(TEST_OBJECT_COUNT, testObjects.Count);
}
log.Info("Took: " + DateTime.Now.Subtract(timeStamp));
timeStamp = DateTime.Now;
log.Info("Deleting " + TEST_OBJECT_COUNT + " objects from table with " + INITIAL_OBJECT_COUNT + " initial objects.");
using (IStatelessSession session = sessions.OpenStatelessSession())
{
using (ITransaction transaction = session.BeginTransaction())
{
for (int i = 0; i < TEST_OBJECT_COUNT; i++)
{
TestObject loadedObject = testObjects[i];
session.Delete(loadedObject);
}
transaction.Commit();
}
}
log.Info("Took: " + DateTime.Now.Subtract(timeStamp));
timeStamp = DateTime.Now;
}
}
}
Value object code:
using System;
using System.Collections.Generic;
using System.Text;
namespace Example.Library.Resources
{
/// <summary>
/// Object for database tests.
/// </summary>
public class TestObject
{
private Guid testId=Guid.Empty;
public Guid TestId {
get
{
return testId;
}
set
{
testId = value;
}
}
private String name;
public String Name {
get
{
return name;
}
set
{
name = value;
}
}
}
}
Mapping configuration:
<?xml version="1.0" encoding="utf-8" ?>
<hibernate-mapping xmlns="urn:nhibernate-mapping-2.2">
<class name="Example.Library.Resources.TestObject, Example.Library" table="test_object" lazy="false">
<id name="TestId" column="TestId" type="Guid">
<generator class="assigned" />
</id>
<property name="Name" type="String" length="45" />
</class>
</hibernate-mapping>
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>
