Menu
▾
▴
[Nhibernate-commit] SF.net SVN: nhibernate:[4513] branches/2.1.x/nhibernate/src/NHibernate
|
From: <aye...@us...> - 2009-06-23 05:57:26
|
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.
|
