Sorry if this already passed here, but 'search' didn't result in any postings about performance.

After successfully using Hibernate in a couple of Java projects, I'm now looking to introduce NHibernate in a new .NET project I'm managing. I've asked a developer to make a simple test-project that saves a data-structure with several different data-types in a SQL Server database using NHibernate.

Everything went very smoothly, just as I had hoped for given my Hibernate experience. However, when I asked him to do some performance tests things suddenly didn't look so good.

What we do is simple:

open a hibernate session.
for (i=0; i<1000;i++)
{
TestData newObject = new TestData(i);
session.Save(newObject)
session.Flush();
}

This simple test takes 16 seconds, which I find surprisingly long. Even worse, when I increase the loop from 1,000 to 10,000, it takes more than 10 minutes to finish.

When we print out how long each save takes, it starts out with some 15ms operations, usually followed by several that take less than 1ms. It slowly goes up however. In case of 10,000 iterations, one save at some point took 250ms and was still increasing.

If I move the session.Flush() out of the loop, it's very fast. However, I want to simulate a real world situation where I expect to have many clients saving a single object often. Without the Flush() call I expect to have problems when another thread reads from the table.

Has anyone seen this kind of behaviour? Is there a way to avoid it? Or is this a known issue that is being worked on? I'm well aware this project is still in beta, and I would have no problem with it as long as it looks like this is going to improve in later releases.

Thanks in advance for any comments.

Tesuji


P.S. The version we're using is 0.8

It's best to keep sessions small and short-lived. Flush has to traverse all the objects known to the session to check whether they have been modified, and if most of them aren't, it means a lot of wasted time. A better usage pattern would be to open a session, save the object, flush and close the session.

I'd be suprised if the Java version performed differently in this benchmark.

Sorry, I forgot to include this bit of information. The first time a session is opened it takes 300-400ms. Every subsequent time it takes 40-50ms, even if it then only writes a single row. So it seemed to me for performance reason we can't afford to open-close a session for each database-operation. I thought it was needed to open the session and reuse it as much as possible as the 40ms hit is too expensive to take each time.

I must say though that immediately after opening a session it starts a transaction, and it commits it before closing. Would it be faster not to use transations?

Anyway, your explanation that the Flush() call checks with each object for modification would explain our observation, so that already gives us a clue to what's going on. Thanks.

Some other quick checks when performance is not what you expect

how is log4net configured - nhibernate logs alot of messages if the log level is "ALL", "DEBUG", or "INFO". That can slow things down significantly. This is not a problem with log4net, it's caused by how much string concatenation happens while creating the log messages.

are you rebuilding the ISessionFactory or Configuration? That's where all the work takes place since there is alot of xml parsing. There is very little code in ISessionFactory.OpenSession() and the ctor for a Session.

It doesn't begin a transaction automatically, only when you call session.BeginTransaction(). There must be something else going on.

I'm not sure how log4net is configured, although I didn't see a whole lot of messages appear in the console. I'll have to check...

If I go on what the developer told me, the time measurement started just before the ISessionFactory.OpenSession() call and ended just after. When looking at the documentation it says that this call also creates a database connection. There's also an Opensession() call that takes a database connection as an argument. Would it be faster maybe to create a database connection once, and pass it in the OpenSession call each time?

The messages go in a file. The configuration of log4net should be in your App.config. In production env, I set the debug level to "WARN" so that I get warnings and errors (which should never appear).

Can you do the same test for Hibernate and tell us what you get ? (try to make exactly the same operations)

Using one connection won't help you much, I believe, since ADO.NET does connection pooling. But of course if you're counting milliseconds, it might win you some.

It is my understanding that the log messages are built ALL the time and based on how log4net is configured the message either gets logged or not. Or, are you saying that NHibernate checks the log4net config level and builds the messages or not?

Also, why is string concatenation used rather than a string builder. I'm sure you know using a string builder can increase performance exponentially compared to string concat, espesially if you make the SB large enought to hold the final string length expected. ???

THanks,
BOb

I would think this would be mitigated by wrapping logging statements with

if (ILog.Is(level)Enabled) {}

Even without that, though, not logging should be less expensive than logging.

Yep - most of the time the code looks like



the only (or should be the only) times we don't check the log level is if we just log a constant string.

Sure, StringBuilder could be more efficient, but when you've got the log level to DEBUG you're not going for efficiency. You're trying to figure out what's wrong :)

OK, I have a bit more information on all this. It turned out my developer gave me some unreliable information, so I decided to take a look myself.

As you guys suggested, I now open and close a session for each operation. This works much better. 10,000 insert statements now take 25-26 seconds. Doing the same using a stored procedure with a SqlClient.Sqlconnection takes 11 seconds. Still not great, but not as dramatic as before. But still I seem to get at least 100% extra overhead using NHibernate compared to using the SqlClient library.

Next I try to see what would happen if I simulate several clients writing to the DB at the same time. To my surprise the numbers run up linearly in all cases. Even though the database is on another computer on our LAN, the CPU goes to 95%. I would have expected that with 10 threads or more trying to access the DB simultaneously, the DB would become the bottleneck and the CPU load on my local computer would drop. Apparently the overhead of processing the SQL statement (whether through NHibernate or SqlClient) takes much more than the actual operation on the DB. Is this normal? This is the first time I have such a high performance requirements for accessing the DB so this is the first time I look at the performance of the persistence layer as ciritically as I do now.

If anyone can point me to ways to improve performance I would greatly appreciate it.

Tesuji

I'm now looking at the log4net configuration as several of you have pointed out, because of the potential overhead caused by the string concatenation. The code that I started with didn't configure log4net at all, resulting in an error message from log4net.

After I inserted the standard BasicConfigurator.Configure() call, I get loads of messages in my console window. Next I tried adding some XML to the App.config file as suggested above to configure log4net. This, however, doesn't seem to have any effect. Other ways to configure all failed in different ways. I tried many of the examples given by the log4net documentation, but these examples all seem to be for log4net version 1.2, whereas the log4net that came with NHibernate is version 1.1. There are considerable differences between these versions apparently, as most examples in the log4net documentation just don't compile.

The most basic example which I think should work is:



However this results in: "log4net:ERROR DOMConfigurator: ConfigureFromXML called with null 'element' parameter" as if it didn't find the XML file. (Although I'm not sure if this is because of this added code, this seems the default message it gives when something is wrong.)

Trying something similar through the XmlConfigurator as given in the log4net examples doesn't work because XmlConfigurator is not defined.

Anyone any clue here? I suppose I'm a bit swamped by trying to use several things for the first time at once.

Copy the log4net configuration in "nhibernate/src/NHibernate.Examples/App.config"
(replace the line "<priority value="ALL" />" by "<priority value="WARN" />")

You don't need to call "DOMConfigurator.Configure()" if you don't use Log4Net (NHibernate call it internally)

Thanks, that was a useful tip. I must say I'm impressed with the speed of responses and their quality on this forum.

As to performance: setting log4net to 'WARN' didn't affect anything. 10,000 inserts still take 25 sec like it did before. So either the string concatenation still happens, or it takes negligable time.