Thread: [Nhibernate-commit] SF.net SVN: nhibernate:[4513] branches/2.1.x/nhibernate/src/NHibernate

SourceForge Headquarters 225 Broadway Suite 1600 San Diego, CA 92101 +1 (858) 422-6466

Revision: 4513
          http://nhibernate.svn.sourceforge.net/nhibernate/?rev=4513&view=rev
Author:   ayenderahien
Date:     2009-06-23 05:57:17 +0000 (Tue, 23 Jun 2009)

Log Message:
-----------
Made openCommandCount and openReaderCount thread safe
Fixed NH-1850 NHibernate should log query duration

Modified Paths:
--------------
    branches/2.1.x/nhibernate/src/NHibernate/AdoNet/AbstractBatcher.cs
    branches/2.1.x/nhibernate/src/NHibernate/Driver/NHybridDataReader.cs
    branches/2.1.x/nhibernate/src/NHibernate.Test/NHibernate.Test.csproj

Added Paths:
-----------
    branches/2.1.x/nhibernate/src/NHibernate.Test/NHSpecificTest/NH1850/
    branches/2.1.x/nhibernate/src/NHibernate.Test/NHSpecificTest/NH1850/Customer.cs
    branches/2.1.x/nhibernate/src/NHibernate.Test/NHSpecificTest/NH1850/Fixture.cs
    branches/2.1.x/nhibernate/src/NHibernate.Test/NHSpecificTest/NH1850/Mappings.hbm.xml

Modified: branches/2.1.x/nhibernate/src/NHibernate/AdoNet/AbstractBatcher.cs
===================================================================

--- branches/2.1.x/nhibernate/src/NHibernate/AdoNet/AbstractBatcher.cs	2009-06-23 05:55:51 UTC (rev 4512)
+++ branches/2.1.x/nhibernate/src/NHibernate/AdoNet/AbstractBatcher.cs	2009-06-23 05:57:17 UTC (rev 4513)
@@ -12,6 +12,10 @@
 
 namespace NHibernate.AdoNet
 {
+	using System.Collections.Generic;
+	using System.Diagnostics;
+	using System.Threading;
+
 	/// <summary>
 	/// Manages prepared statements and batching. Class exists to enforce separation of concerns
 	/// </summary>
@@ -34,6 +38,7 @@
 
 		private readonly ISet<IDbCommand> commandsToClose = new HashedSet<IDbCommand>();
 		private readonly ISet<IDataReader> readersToClose = new HashedSet<IDataReader>();
+		private readonly IDictionary<IDataReader, Stopwatch> readersDuration = new Dictionary<IDataReader, Stopwatch>();
 		private IDbCommand lastQuery;
 
 		private bool releasing;
@@ -197,7 +202,10 @@
 		{
 			CheckReaders();
 			Prepare(cmd);
-		    try
+			Stopwatch duration = null;
+			if(log.IsDebugEnabled)
+				duration = Stopwatch.StartNew();
+			try
 		    {
 		        return cmd.ExecuteNonQuery();
 		    }
@@ -207,14 +215,21 @@
 		    	log.Error("Could not execute command: " + cmd.CommandText, e);
 		        throw;
 		    }
+			finally
+		    {
+				if (log.IsDebugEnabled && duration != null)
+					log.DebugFormat("ExecuteNonQuery took {0} ms", duration.ElapsedMilliseconds);
+		    }
 		}
 
 		public IDataReader ExecuteReader(IDbCommand cmd)
 		{
 			CheckReaders();
 			Prepare(cmd);
-
-			IDataReader reader;
+			Stopwatch duration = null;
+			if (log.IsDebugEnabled)
+				duration = Stopwatch.StartNew();
+			IDataReader reader = null;
 		    try
 		    {
 		        reader = cmd.ExecuteReader();
@@ -225,6 +240,14 @@
 		    	log.Error("Could not execute query: " + cmd.CommandText, e);
 		        throw;
 		    }
+			finally
+		    {
+		    	if(log.IsDebugEnabled && duration != null && reader != null)
+		    	{
+		    		log.DebugFormat("ExecuteReader took {0} ms", duration.ElapsedMilliseconds);
+					readersDuration[reader] = duration;
+		    	}
+		    }
 
 		    if (!factory.ConnectionProvider.Driver.SupportsMultipleOpenReaders)
 			{
@@ -259,19 +282,17 @@
 			releasing = true;
 			try
 			{
-				foreach (IDataReader reader in readersToClose)
+				foreach (IDataReader reader in new HashedSet<IDataReader>(readersToClose))
 				{
 					try
 					{
-						LogCloseReader();
-						reader.Dispose();
+						CloseReader(reader);
 					}
 					catch (Exception e)
 					{
 						log.Warn("Could not close IDataReader", e);
 					}
 				}
-				readersToClose.Clear();
 
 				foreach (IDbCommand cmd in commandsToClose)
 				{
@@ -343,18 +364,26 @@
 			 */
 			// TODO NH: Study a way to use directly IDbCommand.ExecuteReader() outsite the batcher
 			// An example of it's use is the management of generated ID.
-			if (reader != null)
-			{
-				ResultSetWrapper rsw = reader as ResultSetWrapper;
-				readersToClose.Remove(rsw == null ? reader : rsw.Target);
-				CloseDataReader(reader);
-			}
-		}
+			if (reader == null) 
+				return;
 
-		private void CloseDataReader(IDataReader reader)
-		{
+			ResultSetWrapper rsw = reader as ResultSetWrapper;
+			var actualReader = rsw == null ? reader : rsw.Target;
+			readersToClose.Remove(actualReader);
 			reader.Dispose();
 			LogCloseReader();
+			
+			if (!log.IsDebugEnabled) 
+				return;
+
+			var nhReader = actualReader as NHybridDataReader;
+			actualReader = nhReader == null ? actualReader : nhReader.Target;
+
+			Stopwatch duration;
+			if (readersDuration.TryGetValue(actualReader, out duration)==false)
+				return;
+			readersDuration.Remove(actualReader);
+			log.DebugFormat("DataReader was closed after {0} ms", duration.ElapsedMilliseconds);
 		}
 
 		/// <summary></summary>
@@ -434,8 +463,8 @@
 		{
 			if (log.IsDebugEnabled)
 			{
-				openCommandCount++;
-				log.Debug("Opened new IDbCommand, open IDbCommands: " + openCommandCount);
+				int currentOpenCommandCount = Interlocked.Increment(ref openCommandCount);
+				log.Debug("Opened new IDbCommand, open IDbCommands: " + currentOpenCommandCount);
 			}
 
 			if (factory.Statistics.IsStatisticsEnabled)
@@ -448,8 +477,8 @@
 		{
 			if (log.IsDebugEnabled)
 			{
-				openCommandCount--;
-				log.Debug("Closed IDbCommand, open IDbCommands: " + openCommandCount);
+				int currentOpenCommandCount = Interlocked.Decrement(ref openCommandCount);
+				log.Debug("Closed IDbCommand, open IDbCommands: " + currentOpenCommandCount);
 			}
 
 			if (factory.Statistics.IsStatisticsEnabled)
@@ -462,8 +491,8 @@
 		{
 			if (log.IsDebugEnabled)
 			{
-				openReaderCount++;
-				log.Debug("Opened IDataReader, open IDataReaders: " + openReaderCount);
+				int currentOpenReaderCount = Interlocked.Increment(ref openReaderCount);
+				log.Debug("Opened IDataReader, open IDataReaders: " + currentOpenReaderCount);
 			}
 		}
 
@@ -471,8 +500,8 @@
 		{
 			if (log.IsDebugEnabled)
 			{
-				openReaderCount--;
-				log.Debug("Closed IDataReader, open IDataReaders :" + openReaderCount);
+				int currentOpenReaderCount = Interlocked.Decrement(ref openReaderCount);
+				log.Debug("Closed IDataReader, open IDataReaders :" + currentOpenReaderCount);
 			}
 		}
 

Modified: branches/2.1.x/nhibernate/src/NHibernate/Driver/NHybridDataReader.cs
===================================================================
--- branches/2.1.x/nhibernate/src/NHibernate/Driver/NHybridDataReader.cs	2009-06-23 05:55:51 UTC (rev 4512)
+++ branches/2.1.x/nhibernate/src/NHibernate/Driver/NHybridDataReader.cs	2009-06-23 05:57:17 UTC (rev 4513)
@@ -27,6 +27,8 @@
 		private IDataReader _reader;
 		private bool _isMidstream = false;
 
+		public IDataReader Target { get { return _reader; } }
+
 		/// <summary>
 		/// Initializes a new instance of the <see cref="NHybridDataReader"/> class.
 		/// </summary>

Copied: branches/2.1.x/nhibernate/src/NHibernate.Test/NHSpecificTest/NH1850/Customer.cs (from rev 4508, branches/2.1.x/nhibernate/src/NHibernate.Test/NHSpecificTest/NH1837/Customer.cs)
===================================================================
--- branches/2.1.x/nhibernate/src/NHibernate.Test/NHSpecificTest/NH1850/Customer.cs	                        (rev 0)
+++ branches/2.1.x/nhibernate/src/NHibernate.Test/NHSpecificTest/NH1850/Customer.cs	2009-06-23 05:57:17 UTC (rev 4513)
@@ -0,0 +1,12 @@
+using System;
+using System.Collections.Generic;
+using System.Text;
+
+namespace NHibernate.Test.NHSpecificTest.NH1850
+{
+	public class Customer
+	{
+		public virtual int Id { get; set; }
+		public virtual string Name { get; set; }
+	}
+}


Property changes on: branches/2.1.x/nhibernate/src/NHibernate.Test/NHSpecificTest/NH1850/Customer.cs
___________________________________________________________________
Added: svn:mergeinfo
   + 

Copied: branches/2.1.x/nhibernate/src/NHibernate.Test/NHSpecificTest/NH1850/Fixture.cs (from rev 4508, branches/2.1.x/nhibernate/src/NHibernate.Test/NHSpecificTest/NH1837/Fixture.cs)
===================================================================
--- branches/2.1.x/nhibernate/src/NHibernate.Test/NHSpecificTest/NH1850/Fixture.cs	                        (rev 0)
+++ branches/2.1.x/nhibernate/src/NHibernate.Test/NHSpecificTest/NH1850/Fixture.cs	2009-06-23 05:57:17 UTC (rev 4513)
@@ -0,0 +1,53 @@
+using System;
+using System.Collections.Generic;
+using System.Text;
+using NHibernate.Criterion;
+using NUnit.Framework;
+
+namespace NHibernate.Test.NHSpecificTest.NH1850
+{
+	using AdoNet;
+
+	[TestFixture]
+	public class Fixture:BugTestCase
+	{
+		[Test]
+		public void CanGetQueryDurationForDelete()
+		{
+			using (LogSpy spy = new LogSpy(typeof(AbstractBatcher)))
+			using (ISession session = OpenSession())
+			using (ITransaction tx = session.BeginTransaction())
+			{
+				session.CreateQuery("delete Customer").ExecuteUpdate();
+
+				var wholeLog = spy.GetWholeLog();
+				Assert.True(
+					wholeLog.Contains("ExecuteNonQuery took")
+					);
+
+				tx.Rollback();
+			}
+		}
+
+		[Test]
+		public void CanGetQueryDurationForSelect()
+		{
+			using (LogSpy spy = new LogSpy(typeof(AbstractBatcher)))
+			using (ISession session = OpenSession())
+			using (ITransaction tx = session.BeginTransaction())
+			{
+				session.CreateQuery("from Customer").List();
+
+				var wholeLog = spy.GetWholeLog();
+				Assert.True(
+					wholeLog.Contains("ExecuteReader took")
+					);
+				Assert.True(
+					wholeLog.Contains("DataReader was closed after")
+					);
+
+				tx.Rollback();
+			}
+		}
+	}
+}


Property changes on: branches/2.1.x/nhibernate/src/NHibernate.Test/NHSpecificTest/NH1850/Fixture.cs
___________________________________________________________________
Added: svn:mergeinfo
   + 

Copied: branches/2.1.x/nhibernate/src/NHibernate.Test/NHSpecificTest/NH1850/Mappings.hbm.xml (from rev 4508, branches/2.1.x/nhibernate/src/NHibernate.Test/NHSpecificTest/NH1837/Mappings.hbm.xml)
===================================================================
--- branches/2.1.x/nhibernate/src/NHibernate.Test/NHSpecificTest/NH1850/Mappings.hbm.xml	                        (rev 0)
+++ branches/2.1.x/nhibernate/src/NHibernate.Test/NHSpecificTest/NH1850/Mappings.hbm.xml	2009-06-23 05:57:17 UTC (rev 4513)
@@ -0,0 +1,13 @@
+<?xml version="1.0" encoding="utf-8" ?>
+<hibernate-mapping xmlns="urn:nhibernate-mapping-2.2" assembly="NHibernate.Test"
+                   namespace="NHibernate.Test.NHSpecificTest.NH1850"
+                   default-lazy="false">
+
+	<class name="Customer">
+		<id name="Id">
+			<generator class="native"/>
+		</id>
+		<property name="Name"/>
+	
+	</class>
+</hibernate-mapping>
\ No newline at end of file


Property changes on: branches/2.1.x/nhibernate/src/NHibernate.Test/NHSpecificTest/NH1850/Mappings.hbm.xml
___________________________________________________________________
Added: svn:mergeinfo
   + 

Modified: branches/2.1.x/nhibernate/src/NHibernate.Test/NHibernate.Test.csproj
===================================================================
--- branches/2.1.x/nhibernate/src/NHibernate.Test/NHibernate.Test.csproj	2009-06-23 05:55:51 UTC (rev 4512)
+++ branches/2.1.x/nhibernate/src/NHibernate.Test/NHibernate.Test.csproj	2009-06-23 05:57:17 UTC (rev 4513)
@@ -521,6 +521,8 @@
     <Compile Include="NHSpecificTest\NH1837\Customer.cs" />
     <Compile Include="NHSpecificTest\NH1837\Fixture.cs" />
     <Compile Include="NHSpecificTest\NH1837\Order.cs" />
+    <Compile Include="NHSpecificTest\NH1850\Customer.cs" />
+    <Compile Include="NHSpecificTest\NH1850\Fixture.cs" />
     <Compile Include="NHSpecificTest\NH473\Child.cs" />
     <Compile Include="NHSpecificTest\NH473\Fixture.cs" />
     <Compile Include="NHSpecificTest\NH473\Parent.cs" />
@@ -1931,6 +1933,7 @@
     <EmbeddedResource Include="Bytecode\Lightweight\ProductLine.hbm.xml" />
     <EmbeddedResource Include="DriverTest\MultiTypeEntity.hbm.xml" />
     <Content Include="DynamicEntity\package.html" />
+    <EmbeddedResource Include="NHSpecificTest\NH1850\Mappings.hbm.xml" />
     <EmbeddedResource Include="NHSpecificTest\NH1192\Mappings.hbm.xml" />
     <EmbeddedResource Include="NHSpecificTest\NH1734\Mappings.hbm.xml" />
     <EmbeddedResource Include="NHSpecificTest\NH1097\Mappings.hbm.xml" />


This was sent by the SourceForge.net collaborative development platform, the world's largest Open Source development site.




Thread: [Nhibernate-commit] SF.net SVN: nhibernate:[4513] branches/2.1.x/nhibernate/src/NHibernate

nhibernate-commit