Menu
▾
▴
[Nhibernate-commit] SF.net SVN: nhibernate:[3816] trunk/nhibernate/src/NHibernate
|
From: <fab...@us...> - 2008-10-08 15:17:06
|
Revision: 3816
http://nhibernate.svn.sourceforge.net/nhibernate/?rev=3816&view=rev
Author: fabiomaulo
Date: 2008-10-08 15:16:52 +0000 (Wed, 08 Oct 2008)
Log Message:
-----------
Log info per Operation Threshold in statistics (from H3.2.6)
Modified Paths:
--------------
trunk/nhibernate/src/NHibernate/Action/CollectionRecreateAction.cs
trunk/nhibernate/src/NHibernate/Action/CollectionRemoveAction.cs
trunk/nhibernate/src/NHibernate/Action/CollectionUpdateAction.cs
trunk/nhibernate/src/NHibernate/Action/EntityDeleteAction.cs
trunk/nhibernate/src/NHibernate/Action/EntityIdentityInsertAction.cs
trunk/nhibernate/src/NHibernate/Action/EntityInsertAction.cs
trunk/nhibernate/src/NHibernate/Action/EntityUpdateAction.cs
trunk/nhibernate/src/NHibernate/Engine/Loading/CollectionLoadContext.cs
trunk/nhibernate/src/NHibernate/Engine/TwoPhaseLoad.cs
trunk/nhibernate/src/NHibernate/Event/Default/DefaultInitializeCollectionEventListener.cs
trunk/nhibernate/src/NHibernate/Event/Default/DefaultLoadEventListener.cs
trunk/nhibernate/src/NHibernate/Hql/Classic/QueryTranslator.cs
trunk/nhibernate/src/NHibernate/Loader/Loader.cs
trunk/nhibernate/src/NHibernate/Stat/IStatistics.cs
trunk/nhibernate/src/NHibernate/Stat/IStatisticsImplementor.cs
trunk/nhibernate/src/NHibernate/Stat/QueryStatistics.cs
trunk/nhibernate/src/NHibernate/Stat/StatisticsImpl.cs
trunk/nhibernate/src/NHibernate.Test/Stats/StatsFixture.cs
Modified: trunk/nhibernate/src/NHibernate/Action/CollectionRecreateAction.cs
===================================================================
--- trunk/nhibernate/src/NHibernate/Action/CollectionRecreateAction.cs 2008-10-05 13:07:29 UTC (rev 3815)
+++ trunk/nhibernate/src/NHibernate/Action/CollectionRecreateAction.cs 2008-10-08 15:16:52 UTC (rev 3816)
@@ -1,4 +1,5 @@
using System;
+using System.Diagnostics;
using NHibernate.Collection;
using NHibernate.Engine;
using NHibernate.Event;
@@ -13,8 +14,18 @@
: base(persister, collection, key, session) { }
/// <summary> Execute this action</summary>
+ /// <remarks>
+ /// This method is called when a new non-null collection is persisted
+ /// or when an existing (non-null) collection is moved to a new owner
+ /// </remarks>
public override void Execute()
{
+ bool statsEnabled = Session.Factory.Statistics.IsStatisticsEnabled;
+ var stopWath = new Stopwatch();
+ if (statsEnabled)
+ {
+ stopWath.Start();
+ }
IPersistentCollection collection = Collection;
PreRecreate();
@@ -26,10 +37,10 @@
Evict();
PostRecreate();
-
- if (Session.Factory.Statistics.IsStatisticsEnabled)
+ if (statsEnabled)
{
- Session.Factory.StatisticsImplementor.RecreateCollection(Persister.Role);
+ stopWath.Stop();
+ Session.Factory.StatisticsImplementor.RecreateCollection(Persister.Role, stopWath.Elapsed);
}
}
Modified: trunk/nhibernate/src/NHibernate/Action/CollectionRemoveAction.cs
===================================================================
--- trunk/nhibernate/src/NHibernate/Action/CollectionRemoveAction.cs 2008-10-05 13:07:29 UTC (rev 3815)
+++ trunk/nhibernate/src/NHibernate/Action/CollectionRemoveAction.cs 2008-10-08 15:16:52 UTC (rev 3816)
@@ -1,4 +1,5 @@
using System;
+using System.Diagnostics;
using NHibernate.Collection;
using NHibernate.Engine;
using NHibernate.Event;
@@ -56,6 +57,13 @@
public override void Execute()
{
+ bool statsEnabled = Session.Factory.Statistics.IsStatisticsEnabled;
+ var stopWath = new Stopwatch();
+ if (statsEnabled)
+ {
+ stopWath.Start();
+ }
+
PreRemove();
if (!emptySnapshot)
@@ -73,9 +81,10 @@
PostRemove();
- if (Session.Factory.Statistics.IsStatisticsEnabled)
+ if (statsEnabled)
{
- Session.Factory.StatisticsImplementor.RemoveCollection(Persister.Role);
+ stopWath.Stop();
+ Session.Factory.StatisticsImplementor.RemoveCollection(Persister.Role, stopWath.Elapsed);
}
}
Modified: trunk/nhibernate/src/NHibernate/Action/CollectionUpdateAction.cs
===================================================================
--- trunk/nhibernate/src/NHibernate/Action/CollectionUpdateAction.cs 2008-10-05 13:07:29 UTC (rev 3815)
+++ trunk/nhibernate/src/NHibernate/Action/CollectionUpdateAction.cs 2008-10-08 15:16:52 UTC (rev 3816)
@@ -1,4 +1,5 @@
using System;
+using System.Diagnostics;
using NHibernate.Cache;
using NHibernate.Cache.Entry;
using NHibernate.Collection;
@@ -29,6 +30,13 @@
IPersistentCollection collection = Collection;
bool affectedByFilters = persister.IsAffectedByEnabledFilters(session);
+ bool statsEnabled = session.Factory.Statistics.IsStatisticsEnabled;
+ var stopWath = new Stopwatch();
+ if (statsEnabled)
+ {
+ stopWath.Start();
+ }
+
PreUpdate();
if (!collection.WasInitialized)
@@ -72,9 +80,10 @@
PostUpdate();
- if (Session.Factory.Statistics.IsStatisticsEnabled)
+ if (statsEnabled)
{
- Session.Factory.StatisticsImplementor.UpdateCollection(Persister.Role);
+ stopWath.Stop();
+ Session.Factory.StatisticsImplementor.UpdateCollection(Persister.Role, stopWath.Elapsed);
}
}
Modified: trunk/nhibernate/src/NHibernate/Action/EntityDeleteAction.cs
===================================================================
--- trunk/nhibernate/src/NHibernate/Action/EntityDeleteAction.cs 2008-10-05 13:07:29 UTC (rev 3815)
+++ trunk/nhibernate/src/NHibernate/Action/EntityDeleteAction.cs 2008-10-08 15:16:52 UTC (rev 3816)
@@ -1,4 +1,5 @@
using System;
+using System.Diagnostics;
using NHibernate.Cache;
using NHibernate.Engine;
using NHibernate.Event;
@@ -34,6 +35,13 @@
ISessionImplementor session = Session;
object instance = Instance;
+ bool statsEnabled = Session.Factory.Statistics.IsStatisticsEnabled;
+ var stopWath = new Stopwatch();
+ if (statsEnabled)
+ {
+ stopWath.Start();
+ }
+
bool veto = PreDelete();
object tmpVersion = version;
@@ -83,9 +91,10 @@
PostDelete();
- if (Session.Factory.Statistics.IsStatisticsEnabled && !veto)
+ if (statsEnabled && !veto)
{
- Session.Factory.StatisticsImplementor.DeleteEntity(Persister.EntityName);
+ stopWath.Stop();
+ Session.Factory.StatisticsImplementor.DeleteEntity(Persister.EntityName, stopWath.Elapsed);
}
}
Modified: trunk/nhibernate/src/NHibernate/Action/EntityIdentityInsertAction.cs
===================================================================
--- trunk/nhibernate/src/NHibernate/Action/EntityIdentityInsertAction.cs 2008-10-05 13:07:29 UTC (rev 3815)
+++ trunk/nhibernate/src/NHibernate/Action/EntityIdentityInsertAction.cs 2008-10-08 15:16:52 UTC (rev 3816)
@@ -1,4 +1,5 @@
using System;
+using System.Diagnostics;
using NHibernate.Engine;
using NHibernate.Event;
using NHibernate.Persister.Entity;
@@ -57,6 +58,13 @@
IEntityPersister persister = Persister;
object instance = Instance;
+ bool statsEnabled = Session.Factory.Statistics.IsStatisticsEnabled;
+ var stopWath = new Stopwatch();
+ if (statsEnabled)
+ {
+ stopWath.Start();
+ }
+
bool veto = PreInsert();
// Don't need to lock the cache here, since if someone
@@ -84,9 +92,10 @@
}*/
PostInsert();
- if (Session.Factory.Statistics.IsStatisticsEnabled && !veto)
+ if (statsEnabled && !veto)
{
- Session.Factory.StatisticsImplementor.InsertEntity(Persister.EntityName);
+ stopWath.Stop();
+ Session.Factory.StatisticsImplementor.InsertEntity(Persister.EntityName, stopWath.Elapsed);
}
}
Modified: trunk/nhibernate/src/NHibernate/Action/EntityInsertAction.cs
===================================================================
--- trunk/nhibernate/src/NHibernate/Action/EntityInsertAction.cs 2008-10-05 13:07:29 UTC (rev 3815)
+++ trunk/nhibernate/src/NHibernate/Action/EntityInsertAction.cs 2008-10-08 15:16:52 UTC (rev 3816)
@@ -1,4 +1,5 @@
using System;
+using System.Diagnostics;
using NHibernate.Cache;
using NHibernate.Cache.Entry;
using NHibernate.Engine;
@@ -41,6 +42,13 @@
object instance = Instance;
object id = Id;
+ bool statsEnabled = Session.Factory.Statistics.IsStatisticsEnabled;
+ var stopWath = new Stopwatch();
+ if (statsEnabled)
+ {
+ stopWath.Start();
+ }
+
bool veto = PreInsert();
// Don't need to lock the cache here, since if someone
@@ -87,9 +95,10 @@
PostInsert();
- if (factory.Statistics.IsStatisticsEnabled && !veto)
+ if (statsEnabled && !veto)
{
- factory.StatisticsImplementor.InsertEntity(Persister.EntityName);
+ stopWath.Stop();
+ factory.StatisticsImplementor.InsertEntity(Persister.EntityName, stopWath.Elapsed);
}
}
Modified: trunk/nhibernate/src/NHibernate/Action/EntityUpdateAction.cs
===================================================================
--- trunk/nhibernate/src/NHibernate/Action/EntityUpdateAction.cs 2008-10-05 13:07:29 UTC (rev 3815)
+++ trunk/nhibernate/src/NHibernate/Action/EntityUpdateAction.cs 2008-10-08 15:16:52 UTC (rev 3816)
@@ -1,4 +1,5 @@
using System;
+using System.Diagnostics;
using NHibernate.Cache;
using NHibernate.Cache.Entry;
using NHibernate.Engine;
@@ -46,6 +47,13 @@
IEntityPersister persister = Persister;
object instance = Instance;
+ bool statsEnabled = Session.Factory.Statistics.IsStatisticsEnabled;
+ var stopWath = new Stopwatch();
+ if (statsEnabled)
+ {
+ stopWath.Start();
+ }
+
bool veto = PreUpdate();
ISessionFactoryImplementor factory = Session.Factory;
@@ -119,9 +127,10 @@
PostUpdate();
- if (factory.Statistics.IsStatisticsEnabled && !veto)
+ if (statsEnabled && !veto)
{
- factory.StatisticsImplementor.UpdateEntity(Persister.EntityName);
+ stopWath.Stop();
+ factory.StatisticsImplementor.UpdateEntity(Persister.EntityName, stopWath.Elapsed);
}
}
Modified: trunk/nhibernate/src/NHibernate/Engine/Loading/CollectionLoadContext.cs
===================================================================
--- trunk/nhibernate/src/NHibernate/Engine/Loading/CollectionLoadContext.cs 2008-10-05 13:07:29 UTC (rev 3815)
+++ trunk/nhibernate/src/NHibernate/Engine/Loading/CollectionLoadContext.cs 2008-10-08 15:16:52 UTC (rev 3816)
@@ -1,6 +1,7 @@
using System.Collections;
using System.Collections.Generic;
using System.Data;
+using System.Diagnostics;
using Iesi.Collections.Generic;
using log4net;
using NHibernate.Cache;
@@ -238,6 +239,13 @@
ISessionImplementor session = LoadContext.PersistenceContext.Session;
EntityMode em = session.EntityMode;
+ bool statsEnabled = session.Factory.Statistics.IsStatisticsEnabled;
+ var stopWath = new Stopwatch();
+ if (statsEnabled)
+ {
+ stopWath.Start();
+ }
+
bool hasNoQueuedAdds = lce.Collection.EndRead(persister); // warning: can cause a recursive calls! (proxy initialization)
if (persister.CollectionType.HasHolder(em))
@@ -268,9 +276,10 @@
log.Debug("collection fully initialized: " + MessageHelper.InfoString(persister, lce.Key, session.Factory));
}
- if (session.Factory.Statistics.IsStatisticsEnabled)
+ if (statsEnabled)
{
- session.Factory.StatisticsImplementor.LoadCollection(persister.Role);
+ stopWath.Stop();
+ session.Factory.StatisticsImplementor.LoadCollection(persister.Role, stopWath.Elapsed);
}
}
Modified: trunk/nhibernate/src/NHibernate/Engine/TwoPhaseLoad.cs
===================================================================
--- trunk/nhibernate/src/NHibernate/Engine/TwoPhaseLoad.cs 2008-10-05 13:07:29 UTC (rev 3815)
+++ trunk/nhibernate/src/NHibernate/Engine/TwoPhaseLoad.cs 2008-10-08 15:16:52 UTC (rev 3816)
@@ -1,3 +1,4 @@
+using System.Diagnostics;
using log4net;
using NHibernate.Cache;
using NHibernate.Cache.Entry;
@@ -47,6 +48,14 @@
public static void InitializeEntity(object entity, bool readOnly, ISessionImplementor session, PreLoadEvent preLoadEvent, PostLoadEvent postLoadEvent)
{
//TODO: Should this be an InitializeEntityEventListener??? (watch out for performance!)
+
+ bool statsEnabled = session.Factory.Statistics.IsStatisticsEnabled;
+ var stopWath = new Stopwatch();
+ if (statsEnabled)
+ {
+ stopWath.Start();
+ }
+
IPersistenceContext persistenceContext = session.PersistenceContext;
EntityEntry entityEntry = persistenceContext.GetEntry(entity);
if (entityEntry == null)
@@ -140,9 +149,10 @@
if (log.IsDebugEnabled)
log.Debug("done materializing entity " + MessageHelper.InfoString(persister, id, session.Factory));
- if (factory.Statistics.IsStatisticsEnabled)
+ if (statsEnabled)
{
- factory.StatisticsImplementor.LoadEntity(persister.EntityName);
+ stopWath.Stop();
+ factory.StatisticsImplementor.LoadEntity(persister.EntityName, stopWath.Elapsed);
}
}
Modified: trunk/nhibernate/src/NHibernate/Event/Default/DefaultInitializeCollectionEventListener.cs
===================================================================
--- trunk/nhibernate/src/NHibernate/Event/Default/DefaultInitializeCollectionEventListener.cs 2008-10-05 13:07:29 UTC (rev 3815)
+++ trunk/nhibernate/src/NHibernate/Event/Default/DefaultInitializeCollectionEventListener.cs 2008-10-08 15:16:52 UTC (rev 3816)
@@ -1,4 +1,5 @@
using System;
+using System.Diagnostics;
using log4net;
using NHibernate.Cache;
using NHibernate.Cache.Entry;
@@ -20,6 +21,13 @@
IPersistentCollection collection = @event.Collection;
ISessionImplementor source = @event.Session;
+ bool statsEnabled = source.Factory.Statistics.IsStatisticsEnabled;
+ var stopWath = new Stopwatch();
+ if (statsEnabled)
+ {
+ stopWath.Start();
+ }
+
CollectionEntry ce = source.PersistenceContext.GetCollectionEntry(collection);
if (ce == null)
throw new HibernateException("collection was evicted");
@@ -43,9 +51,10 @@
ce.LoadedPersister.Initialize(ce.LoadedKey, source);
log.Debug("collection initialized");
- if (source.Factory.Statistics.IsStatisticsEnabled)
+ if (statsEnabled)
{
- source.Factory.StatisticsImplementor.FetchCollection(ce.LoadedPersister.Role);
+ stopWath.Stop();
+ source.Factory.StatisticsImplementor.FetchCollection(ce.LoadedPersister.Role, stopWath.Elapsed);
}
}
}
Modified: trunk/nhibernate/src/NHibernate/Event/Default/DefaultLoadEventListener.cs
===================================================================
--- trunk/nhibernate/src/NHibernate/Event/Default/DefaultLoadEventListener.cs 2008-10-05 13:07:29 UTC (rev 3815)
+++ trunk/nhibernate/src/NHibernate/Event/Default/DefaultLoadEventListener.cs 2008-10-08 15:16:52 UTC (rev 3816)
@@ -1,4 +1,5 @@
using System;
+using System.Diagnostics;
using log4net;
using NHibernate.Cache;
using NHibernate.Cache.Entry;
@@ -328,11 +329,20 @@
protected virtual object LoadFromDatasource(LoadEvent @event, IEntityPersister persister, EntityKey keyToLoad, LoadType options)
{
ISessionImplementor source = @event.Session;
+
+ bool statsEnabled = source.Factory.Statistics.IsStatisticsEnabled;
+ var stopWath = new Stopwatch();
+ if (statsEnabled)
+ {
+ stopWath.Start();
+ }
+
object entity = persister.Load(@event.EntityId, @event.InstanceToLoad, @event.LockMode, source);
- if (@event.IsAssociationFetch && source.Factory.Statistics.IsStatisticsEnabled)
+ if (@event.IsAssociationFetch && statsEnabled)
{
- source.Factory.StatisticsImplementor.FetchEntity(@event.EntityClassName);
+ stopWath.Stop();
+ source.Factory.StatisticsImplementor.FetchEntity(@event.EntityClassName, stopWath.Elapsed);
}
return entity;
Modified: trunk/nhibernate/src/NHibernate/Hql/Classic/QueryTranslator.cs
===================================================================
--- trunk/nhibernate/src/NHibernate/Hql/Classic/QueryTranslator.cs 2008-10-05 13:07:29 UTC (rev 3815)
+++ trunk/nhibernate/src/NHibernate/Hql/Classic/QueryTranslator.cs 2008-10-08 15:16:52 UTC (rev 3816)
@@ -1,6 +1,7 @@
using System;
using System.Collections;
using System.Data;
+using System.Diagnostics;
using System.Reflection;
using System.Runtime.CompilerServices;
using System.Text;
@@ -1288,11 +1289,14 @@
public IEnumerable GetEnumerable(QueryParameters parameters, ISessionImplementor session)
{
- bool stats = session.Factory.Statistics.IsStatisticsEnabled;
- long startTime = 0;
- if (stats)
- startTime = DateTime.Now.Ticks;
+ bool statsEnabled = session.Factory.Statistics.IsStatisticsEnabled;
+ var stopWath = new Stopwatch();
+ if (statsEnabled)
+ {
+ stopWath.Start();
+ }
+
IDbCommand cmd = PrepareQueryCommand(parameters, false, session);
// This IDataReader is disposed of in EnumerableImpl.Dispose
@@ -1301,12 +1305,13 @@
HolderInstantiator.CreateClassicHolderInstantiator(holderConstructor, parameters.ResultTransformer);
IEnumerable result =
new EnumerableImpl(rs, cmd, session, ReturnTypes, ScalarColumnNames, parameters.RowSelection, hi);
- if (stats)
+ if (statsEnabled)
{
- session.Factory.StatisticsImplementor.QueryExecuted("HQL: " + queryString, 0, (DateTime.Now.Ticks - startTime));
+ stopWath.Stop();
+ session.Factory.StatisticsImplementor.QueryExecuted("HQL: " + queryString, 0, stopWath.Elapsed);
// NH: Different behavior (H3.2 use QueryLoader in AST parser) we need statistic for orginal query too.
// probably we have a bug some where else for statistic RowCount
- session.Factory.StatisticsImplementor.QueryExecuted(QueryIdentifier, 0, (DateTime.Now.Ticks - startTime));
+ session.Factory.StatisticsImplementor.QueryExecuted(QueryIdentifier, 0, stopWath.Elapsed);
}
return result;
}
Modified: trunk/nhibernate/src/NHibernate/Loader/Loader.cs
===================================================================
--- trunk/nhibernate/src/NHibernate/Loader/Loader.cs 2008-10-05 13:07:29 UTC (rev 3815)
+++ trunk/nhibernate/src/NHibernate/Loader/Loader.cs 2008-10-08 15:16:52 UTC (rev 3816)
@@ -2,6 +2,7 @@
using System.Collections;
using System.Collections.Generic;
using System.Data;
+using System.Diagnostics;
using System.Runtime.CompilerServices;
using Iesi.Collections;
using Iesi.Collections.Generic;
@@ -1686,11 +1687,11 @@
/// <returns></returns>
protected IList DoList(ISessionImplementor session, QueryParameters queryParameters)
{
- bool stats = Factory.Statistics.IsStatisticsEnabled;
- long startTime = 0;
- if (stats)
+ bool statsEnabled = Factory.Statistics.IsStatisticsEnabled;
+ var stopWath = new Stopwatch();
+ if (statsEnabled)
{
- startTime = DateTime.Now.Ticks;
+ stopWath.Start();
}
IList result;
@@ -1708,9 +1709,10 @@
throw ADOExceptionHelper.Convert(Factory.SQLExceptionConverter, sqle, "could not execute query", SqlString,
queryParameters.PositionalParameterValues, queryParameters.NamedParameters);
}
- if (stats)
+ if (statsEnabled)
{
- Factory.StatisticsImplementor.QueryExecuted(QueryIdentifier, result.Count, (DateTime.Now.Ticks - startTime));
+ stopWath.Stop();
+ Factory.StatisticsImplementor.QueryExecuted(QueryIdentifier, result.Count, stopWath.Elapsed);
}
return result;
}
Modified: trunk/nhibernate/src/NHibernate/Stat/IStatistics.cs
===================================================================
--- trunk/nhibernate/src/NHibernate/Stat/IStatistics.cs 2008-10-05 13:07:29 UTC (rev 3815)
+++ trunk/nhibernate/src/NHibernate/Stat/IStatistics.cs 2008-10-08 15:16:52 UTC (rev 3816)
@@ -1,12 +1,11 @@
using System;
+using System.Diagnostics;
namespace NHibernate.Stat
{
/// <summary>
- /// Statistics for a particular <tt>SessionFactory</tt>.
- /// Beware of milliseconds metrics, they are dependent of the JVM precision:
- /// you may then encounter a 10 ms approximation depending on your OS platform.
- /// Please refer to the JVM documentation for more information.
+ /// Statistics for a particular <see cref="ISessionFactory"/>.
+ /// Beware of metrics, they are dependent of the <see cref="Stopwatch"/> precision:
/// </summary>
public interface IStatistics
{
@@ -28,8 +27,8 @@
/// <summary> Global number of executed queries</summary>
long QueryExecutionCount { get;}
- /// <summary> The time in milliseconds of the slowest query.</summary>
- long QueryExecutionMaxTime { get;}
+ /// <summary> The <see cref="TimeSpan"/> of the slowest query.</summary>
+ TimeSpan QueryExecutionMaxTime { get; }
/// <summary> The query string for the slowest query.</summary>
string QueryExecutionMaxTimeQueryString { get;}
@@ -141,5 +140,11 @@
/// <summary> log in info level the main statistics</summary>
void LogSummary();
+
+ /// <summary>
+ /// The OperationThreshold to a value greater than <see cref="TimeSpan.MinValue"/> to enable logging of long running operations.
+ /// </summary>
+ /// <remarks>Operations that exceed the level will be logged.</remarks>
+ TimeSpan OperationThreshold { get; set; }
}
}
Modified: trunk/nhibernate/src/NHibernate/Stat/IStatisticsImplementor.cs
===================================================================
--- trunk/nhibernate/src/NHibernate/Stat/IStatisticsImplementor.cs 2008-10-05 13:07:29 UTC (rev 3815)
+++ trunk/nhibernate/src/NHibernate/Stat/IStatisticsImplementor.cs 2008-10-08 15:16:52 UTC (rev 3816)
@@ -1,3 +1,4 @@
+using System;
namespace NHibernate.Stat
{
/// <summary> Statistics SPI for the NHibernate core </summary>
@@ -7,20 +8,20 @@
void CloseSession();
void Flush();
void Connect();
- void LoadEntity(string entityName);
- void FetchEntity(string entityName);
- void UpdateEntity(string entityName);
- void InsertEntity(string entityName);
- void DeleteEntity(string entityName);
- void LoadCollection(string role);
- void FetchCollection(string role);
- void UpdateCollection(string role);
- void RecreateCollection(string role);
- void RemoveCollection(string role);
+ void LoadEntity(string entityName, TimeSpan time);
+ void FetchEntity(string entityName, TimeSpan time);
+ void UpdateEntity(string entityName, TimeSpan time);
+ void InsertEntity(string entityName, TimeSpan time);
+ void DeleteEntity(string entityName, TimeSpan time);
+ void LoadCollection(string role, TimeSpan time);
+ void FetchCollection(string role, TimeSpan time);
+ void UpdateCollection(string role, TimeSpan time);
+ void RecreateCollection(string role, TimeSpan time);
+ void RemoveCollection(string role, TimeSpan time);
void SecondLevelCachePut(string regionName);
void SecondLevelCacheHit(string regionName);
void SecondLevelCacheMiss(string regionName);
- void QueryExecuted(string hql, int rows, long time);
+ void QueryExecuted(string hql, int rows, TimeSpan time);
void QueryCacheHit(string hql, string regionName);
void QueryCacheMiss(string hql, string regionName);
void QueryCachePut(string hql, string regionName);
Modified: trunk/nhibernate/src/NHibernate/Stat/QueryStatistics.cs
===================================================================
--- trunk/nhibernate/src/NHibernate/Stat/QueryStatistics.cs 2008-10-05 13:07:29 UTC (rev 3815)
+++ trunk/nhibernate/src/NHibernate/Stat/QueryStatistics.cs 2008-10-08 15:16:52 UTC (rev 3816)
@@ -13,9 +13,9 @@
internal long cachePutCount;
private long executionCount;
private long executionRowCount;
- private long executionAvgTime;
- private long executionMaxTime;
- private long executionMinTime;
+ private TimeSpan executionAvgTime;
+ private TimeSpan executionMaxTime;
+ private TimeSpan executionMinTime = TimeSpan.MaxValue;
public QueryStatistics(string categoryName) : base(categoryName) { }
@@ -44,17 +44,17 @@
get { return executionRowCount; }
}
- public long ExecutionAvgTime
+ public TimeSpan ExecutionAvgTime
{
get { return executionAvgTime; }
}
- public long ExecutionMaxTime
+ public TimeSpan ExecutionMaxTime
{
get { return executionMaxTime; }
}
- public long ExecutionMinTime
+ public TimeSpan ExecutionMinTime
{
get { return executionMinTime; }
}
@@ -62,7 +62,7 @@
/// <summary> Add statistics report of a DB query </summary>
/// <param name="rows">rows count returned </param>
/// <param name="time">time taken </param>
- internal void Executed(long rows, long time)
+ internal void Executed(long rows, TimeSpan time)
{
if (time < executionMinTime)
executionMinTime = time;
@@ -70,7 +70,7 @@
executionMaxTime = time;
executionCount++;
executionRowCount += rows;
- executionAvgTime = (executionAvgTime * executionCount + time) / executionCount;
+ executionAvgTime = TimeSpan.FromTicks((executionAvgTime.Ticks * executionCount + time.Ticks) / executionCount);
}
public override string ToString()
Modified: trunk/nhibernate/src/NHibernate/Stat/StatisticsImpl.cs
===================================================================
--- trunk/nhibernate/src/NHibernate/Stat/StatisticsImpl.cs 2008-10-05 13:07:29 UTC (rev 3815)
+++ trunk/nhibernate/src/NHibernate/Stat/StatisticsImpl.cs 2008-10-08 15:16:52 UTC (rev 3816)
@@ -1,6 +1,7 @@
using System;
using System.Collections.Generic;
using System.Runtime.CompilerServices;
+using System.Text;
using System.Threading;
using log4net;
using NHibernate.Cache;
@@ -20,8 +21,10 @@
private long entityLoadCount;
private long entityFetchCount;
private long entityUpdateCount;
+ // log operations that take longer than this value
+ private TimeSpan operationThreshold = TimeSpan.MaxValue;
private long queryExecutionCount;
- private long queryExecutionMaxTime;
+ private TimeSpan queryExecutionMaxTime;
private string queryExecutionMaxTimeQueryString;
private long queryCacheHitCount;
private long queryCacheMissCount;
@@ -39,7 +42,6 @@
private long collectionRemoveCount;
private long collectionRecreateCount;
private DateTime startTime;
- private bool isStatisticsEnabled;
private long commitedTransactionCount;
private long transactionCount;
private long prepareStatementCount;
@@ -54,8 +56,22 @@
// entity statistics per query string (HQL or SQL)
private readonly Dictionary<string, QueryStatistics> queryStatistics = new Dictionary<string, QueryStatistics>();
+ internal const string OperationLoad = "load ";
+ internal const string OperationFetch = "fetch ";
+ internal const string OperationUpdate = "update ";
+ internal const string OperationInsert = "insert ";
+ internal const string OperationDelete = "delete ";
+ internal const string OperationLoadCollection = "loadCollection ";
+ internal const string OperationFetchCollection = "fetchCollection ";
+ internal const string OperationUpdateCollection = "updateCollection ";
+ internal const string OperationRecreateCollection = "recreateCollection ";
+ internal const string OperationRemoveCollection = "removeCollection ";
+ internal const string OperationExecuteQuery = "executeQuery ";
+ internal const string OperationEndTransaction = "endTransaction ";
+
public StatisticsImpl()
{
+ Clear();
}
public StatisticsImpl(ISessionFactoryImplementor sessionFactory)
@@ -107,7 +123,7 @@
get { return queryExecutionCount; }
}
- public long QueryExecutionMaxTime
+ public TimeSpan QueryExecutionMaxTime
{
get { return queryExecutionMaxTime; }
}
@@ -197,17 +213,13 @@
get { return startTime; }
}
- public bool IsStatisticsEnabled
- {
- get { return isStatisticsEnabled; }
- set { isStatisticsEnabled = value; }
- }
+ public bool IsStatisticsEnabled { get; set; }
public string[] Queries
{
get
{
- string[] result = new string[queryStatistics.Keys.Count];
+ var result = new string[queryStatistics.Keys.Count];
queryStatistics.Keys.CopyTo(result,0);
return result;
}
@@ -219,7 +231,7 @@
{
if (sessionFactory == null)
{
- string[] result = new string[entityStatistics.Keys.Count];
+ var result = new string[entityStatistics.Keys.Count];
entityStatistics.Keys.CopyTo(result, 0);
return result;
}
@@ -236,14 +248,14 @@
{
if (sessionFactory == null)
{
- string[] result = new string[collectionStatistics.Keys.Count];
+ var result = new string[collectionStatistics.Keys.Count];
collectionStatistics.Keys.CopyTo(result, 0);
return result;
}
else
{
ICollection<string> kc = sessionFactory.GetAllCollectionMetadata().Keys;
- string[] result = new string[kc.Count];
+ var result = new string[kc.Count];
kc.CopyTo(result, 0);
return result;
}
@@ -256,7 +268,7 @@
{
if (sessionFactory == null)
{
- string[] result = new string[secondLevelCacheStatistics.Keys.Count];
+ var result = new string[secondLevelCacheStatistics.Keys.Count];
secondLevelCacheStatistics.Keys.CopyTo(result, 0);
return result;
}
@@ -323,7 +335,7 @@
queryExecutionCount = 0;
queryCacheHitCount = 0;
- queryExecutionMaxTime = 0;
+ queryExecutionMaxTime = TimeSpan.MinValue;
queryExecutionMaxTimeQueryString = null;
queryCacheMissCount = 0;
queryCachePutCount = 0;
@@ -348,8 +360,7 @@
lock (SyncRoot)
{
EntityStatistics es;
- entityStatistics.TryGetValue(entityName, out es);
- if (es == null)
+ if (!entityStatistics.TryGetValue(entityName, out es))
{
es = new EntityStatistics(entityName);
entityStatistics[entityName] = es;
@@ -364,8 +375,7 @@
lock (SyncRoot)
{
CollectionStatistics cs;
- collectionStatistics.TryGetValue(role, out cs);
- if (cs == null)
+ if (!collectionStatistics.TryGetValue(role, out cs))
{
cs = new CollectionStatistics(role);
collectionStatistics[role] = cs;
@@ -380,8 +390,8 @@
lock (SyncRoot)
{
SecondLevelCacheStatistics slcs;
- secondLevelCacheStatistics.TryGetValue(regionName, out slcs);
- if (slcs == null)
+
+ if (!secondLevelCacheStatistics.TryGetValue(regionName, out slcs))
{
if (sessionFactory == null)
return null;
@@ -401,8 +411,7 @@
lock (SyncRoot)
{
QueryStatistics qs;
- queryStatistics.TryGetValue(queryString, out qs);
- if (qs == null)
+ if (!queryStatistics.TryGetValue(queryString, out qs))
{
qs = new QueryStatistics(queryString);
queryStatistics[queryString] = qs;
@@ -414,7 +423,7 @@
public void LogSummary()
{
log.Info("Logging statistics....");
- log.Info(string.Format("start time: {0}", startTime));// TODO change format to show ms
+ log.Info(string.Format("start time: {0}", startTime.ToString("o")));
log.Info("sessions opened: " + sessionOpenCount);
log.Info("sessions closed: " + sessionCloseCount);
log.Info("transactions: " + transactionCount);
@@ -441,9 +450,25 @@
log.Info("query cache puts: " + queryCachePutCount);
log.Info("query cache hits: " + queryCacheHitCount);
log.Info("query cache misses: " + queryCacheMissCount);
- log.Info("max query time: " + queryExecutionMaxTime + "ms");
+ log.Info("max query time: " + queryExecutionMaxTime.Milliseconds + "ms");
}
+ public TimeSpan OperationThreshold
+ {
+ get
+ {
+ return operationThreshold;
+ }
+ [MethodImpl(MethodImplOptions.Synchronized)]
+ set
+ {
+ lock (SyncRoot)
+ {
+ operationThreshold = value;
+ }
+ }
+ }
+
#endregion
#region IStatisticsImplementor Members
@@ -485,103 +510,143 @@
}
[MethodImpl(MethodImplOptions.Synchronized)]
- public void LoadEntity(string entityName)
+ public void LoadEntity(string entityName, TimeSpan time)
{
lock (SyncRoot)
{
entityLoadCount++;
GetEntityStatistics(entityName).loadCount++;
}
+ if (operationThreshold < time)
+ {
+ LogOperation(OperationLoad, entityName, time);
+ }
}
[MethodImpl(MethodImplOptions.Synchronized)]
- public void FetchEntity(string entityName)
+ public void FetchEntity(string entityName, TimeSpan time)
{
lock (SyncRoot)
{
entityFetchCount++;
GetEntityStatistics(entityName).fetchCount++;
}
+ if (operationThreshold < time)
+ {
+ LogOperation(OperationLoad, entityName, time);
+ }
}
[MethodImpl(MethodImplOptions.Synchronized)]
- public void UpdateEntity(string entityName)
+ public void UpdateEntity(string entityName, TimeSpan time)
{
lock (SyncRoot)
{
entityUpdateCount++;
GetEntityStatistics(entityName).updateCount++;
}
+ if (operationThreshold < time)
+ {
+ LogOperation(OperationUpdate, entityName, time);
+ }
}
[MethodImpl(MethodImplOptions.Synchronized)]
- public void InsertEntity(string entityName)
+ public void InsertEntity(string entityName, TimeSpan time)
{
lock (SyncRoot)
{
entityInsertCount++;
GetEntityStatistics(entityName).insertCount++;
}
+ if (operationThreshold < time)
+ {
+ LogOperation(OperationInsert, entityName, time);
+ }
}
[MethodImpl(MethodImplOptions.Synchronized)]
- public void DeleteEntity(string entityName)
+ public void DeleteEntity(string entityName, TimeSpan time)
{
lock (SyncRoot)
{
entityDeleteCount++;
GetEntityStatistics(entityName).deleteCount++;
}
+ if (operationThreshold < time)
+ {
+ LogOperation(OperationDelete, entityName, time);
+ }
}
[MethodImpl(MethodImplOptions.Synchronized)]
- public void LoadCollection(string role)
+ public void LoadCollection(string role, TimeSpan time)
{
lock (SyncRoot)
{
collectionLoadCount++;
GetCollectionStatistics(role).loadCount++;
}
+ if (operationThreshold < time)
+ {
+ LogOperation(OperationLoadCollection, role, time);
+ }
}
[MethodImpl(MethodImplOptions.Synchronized)]
- public void FetchCollection(string role)
+ public void FetchCollection(string role, TimeSpan time)
{
lock (SyncRoot)
{
collectionFetchCount++;
GetCollectionStatistics(role).fetchCount++;
}
+ if (operationThreshold < time)
+ {
+ LogOperation(OperationFetchCollection, role, time);
+ }
}
[MethodImpl(MethodImplOptions.Synchronized)]
- public void UpdateCollection(string role)
+ public void UpdateCollection(string role, TimeSpan time)
{
lock (SyncRoot)
{
collectionUpdateCount++;
GetCollectionStatistics(role).updateCount++;
}
+ if (operationThreshold < time)
+ {
+ LogOperation(OperationUpdateCollection, role, time);
+ }
}
[MethodImpl(MethodImplOptions.Synchronized)]
- public void RecreateCollection(string role)
+ public void RecreateCollection(string role, TimeSpan time)
{
lock (SyncRoot)
{
collectionRecreateCount++;
GetCollectionStatistics(role).recreateCount++;
}
+ if (operationThreshold < time)
+ {
+ LogOperation(OperationRecreateCollection, role, time);
+ }
}
[MethodImpl(MethodImplOptions.Synchronized)]
- public void RemoveCollection(string role)
+ public void RemoveCollection(string role, TimeSpan time)
{
lock (SyncRoot)
{
collectionRemoveCount++;
GetCollectionStatistics(role).removeCount++;
}
+ if (operationThreshold < time)
+ {
+ LogOperation(OperationRecreateCollection, role, time);
+ }
}
[MethodImpl(MethodImplOptions.Synchronized)]
@@ -627,7 +692,7 @@
}
[MethodImpl(MethodImplOptions.Synchronized)]
- public void QueryExecuted(string hql, int rows, long time)
+ public void QueryExecuted(string hql, int rows, TimeSpan time)
{
lock (SyncRoot)
{
@@ -643,6 +708,10 @@
qs.Executed(rows, time);
}
}
+ if (operationThreshold < time)
+ {
+ LogOperation(OperationExecuteQuery, hql, time);
+ }
}
[MethodImpl(MethodImplOptions.Synchronized)]
@@ -726,5 +795,34 @@
}
#endregion
+
+ private static void LogOperation(string operation, string entityName, TimeSpan time)
+ {
+ if (entityName != null)
+ log.Info(operation + entityName + " " + time.Milliseconds + "ms");
+ else
+ log.Info(operation); // just log that the event occurred
+ }
+
+ public override string ToString()
+ {
+ return
+ new StringBuilder().Append("Statistics[").Append("start time=").Append(startTime).Append(",sessions opened=").Append
+ (sessionOpenCount).Append(",sessions closed=").Append(sessionCloseCount).Append(",transactions=").Append(
+ transactionCount).Append(",successful transactions=").Append(commitedTransactionCount).Append(
+ ",optimistic lock failures=").Append(optimisticFailureCount).Append(",flushes=").Append(flushCount).Append(
+ ",connections obtained=").Append(connectCount).Append(",statements prepared=").Append(prepareStatementCount).Append
+ (",statements closed=").Append(closeStatementCount).Append(",second level cache puts=").Append(
+ secondLevelCachePutCount).Append(",second level cache hits=").Append(secondLevelCacheHitCount).Append(
+ ",second level cache misses=").Append(secondLevelCacheMissCount).Append(",entities loaded=").Append(entityLoadCount)
+ .Append(",entities updated=").Append(entityUpdateCount).Append(",entities inserted=").Append(entityInsertCount).
+ Append(",entities deleted=").Append(entityDeleteCount).Append(",entities fetched=").Append(entityFetchCount).Append
+ (",collections loaded=").Append(collectionLoadCount).Append(",collections updated=").Append(collectionUpdateCount).
+ Append(",collections removed=").Append(collectionRemoveCount).Append(",collections recreated=").Append(
+ collectionRecreateCount).Append(",collections fetched=").Append(collectionFetchCount).Append(
+ ",queries executed to database=").Append(queryExecutionCount).Append(",query cache puts=").Append(
+ queryCachePutCount).Append(",query cache hits=").Append(queryCacheHitCount).Append(",query cache misses=").Append(
+ queryCacheMissCount).Append(",max query time=").Append(queryExecutionMaxTime).Append(']').ToString();
+ }
}
}
Modified: trunk/nhibernate/src/NHibernate.Test/Stats/StatsFixture.cs
===================================================================
--- trunk/nhibernate/src/NHibernate.Test/Stats/StatsFixture.cs 2008-10-05 13:07:29 UTC (rev 3815)
+++ trunk/nhibernate/src/NHibernate.Test/Stats/StatsFixture.cs 2008-10-08 15:16:52 UTC (rev 3816)
@@ -155,7 +155,7 @@
Assert.IsNotNull(continentStats, "stats were null");
Assert.AreEqual(1, continentStats.ExecutionCount, "unexpected execution count");
Assert.AreEqual(results, continentStats.ExecutionRowCount, "unexpected row count");
- long maxTime = continentStats.ExecutionMaxTime;
+ var maxTime = continentStats.ExecutionMaxTime;
Assert.AreEqual(maxTime, stats.QueryExecutionMaxTime);
//Assert.AreEqual( continents, stats.QueryExecutionMaxTimeQueryString );
This was sent by the SourceForge.net collaborative development platform, the world's largest Open Source development site.
|
