[mono/monkeywrench] 91fa40ce: Add timed logging to all db queries.

   Branch: refs/heads/master
     Home: https://github.com/mono/monkeywrench
  Compare: https://github.com/mono/monkeywrench/compare/d1a7afabad4a...91fa40cefd19

   Commit: 91fa40cefd19abc4c404db830c8b28e32dc45523
   Author: Rolf Bjarne Kvinge <[email protected]> (rolfbjarne)
     Date: 2013-11-12 10:33:33 GMT
      URL: https://github.com/mono/monkeywrench/commit/91fa40cefd19abc4c404db830c8b28e32dc45523

Add timed logging to all db queries.

Changed paths:
  M MonkeyWrench.Database/DB.cs
  M MonkeyWrench.Database/MonkeyWrench.Database.csproj
  M MonkeyWrench/Logger.cs
Added paths:
  A MonkeyWrench.Database/LoggingCommand.cs

Modified: MonkeyWrench.Database/DB.cs
===================================================================
@@ -14,6 +14,7 @@
 using System.Collections.Generic;
 using System.Data;
 using System.Data.Common;
+using System.Diagnostics;
 using System.IO;
 using System.Text;
 
@@ -31,6 +32,9 @@ public class DB : IDisposable, IDB
 		LargeObjectManager manager;
 		TimeSpan db_time_difference;
 
+		List<string> log;
+		Stopwatch watch;
+
 		public LargeObjectManager Manager
 		{
 			get
@@ -59,6 +63,8 @@ public IDbCommand CreateCommand (TimeSpan Timeout)
 		{
 			NpgsqlCommand result = dbcon.CreateCommand ();
 			result.CommandTimeout = (int) Timeout.TotalSeconds;
+			if (log != null)
+				return new LoggingCommand (this, result);
 			return result;
 		}
 
@@ -69,15 +75,33 @@ public IDbTransaction BeginTransaction ()
 
 		public DB ()
 		{
+			Initialize ();
 			Connect ();
 		}
 
 		public DB (bool Connect)
 		{
+			Initialize ();
 			if (Connect)
 				this.Connect ();
 		}
 
+		void Initialize ()
+		{
+			if (Configuration.LogVerbosity > 2) {
+				log = new List<string> ();
+				watch = new Stopwatch ();
+				watch.Start ();
+			}
+		}
+
+		public void Log (string format, params object[] args)
+		{
+			if (log == null)
+				return;
+			log.Add (string.Format ("[{0:yyyy/MM/dd HH:mm:ss.ffff}] {1}", DateTime.Now, string.Format (format, args)));
+		}
+
 		public static void CreateParameter (IDbCommand cmd, string name, object value)
 		{
 			DBRecord.CreateParameter (cmd, name, value);
@@ -96,25 +120,18 @@ private void Connect ()
 
 				dbcon = new NpgsqlConnection (connectionString);
 
-				Logger.Log (2, "Database connection string: {0}", connectionString);
+				Log ("Connecting to database, connection string: {0}", connectionString);
 
 				dbcon.Open ();
 
 				object db_now_obj = ExecuteScalar ("SELECT now();");
 				DateTime db_now;
 				DateTime machine_now = DateTime.Now;
-				const string format = "yyyy/MM/dd HH:mm:ss.ffff";
-
-				if (db_now_obj is DateTime) {
-					db_now = (DateTime) db_now_obj;
-				} else {
-					Logger.Log ("now () function return value of type: {0}", db_now_obj == null ? "null" : db_now_obj.GetType ().FullName);
-					db_now = machine_now;
-				}
 
+				db_now = (DateTime) db_now_obj;
 				db_time_difference = db_now - machine_now;
 
-				Logger.Log (2, "DB now: {0}, current machine's now: {1}, adjusted now: {3}, diff: {2} ms", db_now.ToString (format), machine_now.ToString (format), db_time_difference.TotalMilliseconds, Now.ToString (format));
+				Logger.Log (2, "DB now: {0:yyyy/MM/dd HH:mm:ss.ffff}, current machine's now: {1:yyyy/MM/dd HH:mm:ss.ffff}, adjusted now: {3}, diff: {2:yyyy/MM/dd HH:mm:ss.ffff} ms", db_now, machine_now, db_time_difference.TotalMilliseconds, Now);
 			} catch {
 				if (dbcon != null) {
 					dbcon.Dispose ();
@@ -130,6 +147,12 @@ public void Dispose ()
 				dbcon.Close ();
 				dbcon = null;
 			}
+			if (log != null) {
+				watch.Stop ();
+				Log ("Closed database connection. Total duration: {0} ms", watch.ElapsedMilliseconds);
+				log.Add (string.Empty);
+				Logger.LogRaw (string.Join ("\n", log.ToArray ()));
+			}
 		}
 
 		private class DBFileStream : Stream
@@ -251,7 +274,6 @@ public int GetSize (int file_id)
 
 		public int GetLargeObjectSize (int oid)
 		{
-			Console.WriteLine ("GetLargeObjectSize ({0})", oid);
 			using (IDbTransaction transaction = BeginTransaction ()) {
 				int result;
 				LargeObject obj = Manager.Open (oid);

Added: MonkeyWrench.Database/LoggingCommand.cs
===================================================================
@@ -0,0 +1,159 @@
+using System;
+using System.Data;
+using System.Diagnostics;
+
+namespace MonkeyWrench.Database
+{
+	public class LoggingCommand : IDbCommand
+	{
+		IDbCommand cmd;
+		DB db;
+
+		public LoggingCommand (DB db, IDbCommand command)
+		{
+			this.cmd = command;
+			this.db = db;
+		}
+
+		#region IDbCommand implementation
+
+		public void Cancel ()
+		{
+			cmd.Cancel ();
+		}
+
+		public IDbDataParameter CreateParameter ()
+		{
+			return cmd.CreateParameter ();
+		}
+
+		public int ExecuteNonQuery ()
+		{
+			var watch = new Stopwatch ();
+			watch.Start ();
+
+			try {
+				return cmd.ExecuteNonQuery ();
+			} finally {
+				watch.Stop ();
+				db.Log ("ExecuteNonQuery {1} ms: {0}", CommandText, watch.ElapsedMilliseconds);
+			}
+		}
+
+		public IDataReader ExecuteReader ()
+		{
+			var watch = new Stopwatch ();
+			watch.Start ();
+
+			try {
+				return cmd.ExecuteReader ();
+			} finally {
+				watch.Stop ();
+				db.Log ("ExecuteReader {1} ms: {0}", CommandText, watch.ElapsedMilliseconds);
+			}
+		}
+
+		public IDataReader ExecuteReader (CommandBehavior behavior)
+		{
+			var watch = new Stopwatch ();
+			watch.Start ();
+
+			try {
+				return cmd.ExecuteReader (behavior);
+			} finally {
+				watch.Stop ();
+				db.Log ("ExecuteReader ({2}) {1} ms: {0}", CommandText, watch.ElapsedMilliseconds, behavior);
+			}
+		}
+
+		public object ExecuteScalar ()
+		{
+			var watch = new Stopwatch ();
+			watch.Start ();
+
+			try {
+				return cmd.ExecuteScalar ();
+			} finally {
+				watch.Stop ();
+				db.Log ("ExecuteScalar {1} ms: {0}", CommandText, watch.ElapsedMilliseconds);
+			}
+		}
+
+		public void Prepare ()
+		{
+			cmd.Prepare ();
+		}
+
+		public string CommandText {
+			get {
+				return cmd.CommandText;
+			}
+			set {
+				cmd.CommandText = value;
+			}
+		}
+
+		public int CommandTimeout {
+			get {
+				return cmd.CommandTimeout;
+			}
+			set {
+				cmd.CommandTimeout = value;
+			}
+		}
+
+		public CommandType CommandType {
+			get {
+				return cmd.CommandType;
+			}
+			set {
+				cmd.CommandType = value;
+			}
+		}
+
+		public IDbConnection Connection {
+			get {
+				return cmd.Connection;
+			}
+			set {
+				cmd.Connection = value;
+			}
+		}
+
+		public IDataParameterCollection Parameters {
+			get {
+				return cmd.Parameters;
+			}
+		}
+
+		public IDbTransaction Transaction {
+			get {
+				return cmd.Transaction;
+			}
+			set {
+				cmd.Transaction = value;
+			}
+		}
+
+		public UpdateRowSource UpdatedRowSource {
+			get {
+				return cmd.UpdatedRowSource;
+			}
+			set {
+				cmd.UpdatedRowSource = value;
+			}
+		}
+
+		#endregion
+
+		#region IDisposable implementation
+
+		public void Dispose ()
+		{
+			cmd.Dispose ();
+		}
+
+		#endregion
+	}
+}
+

Modified: MonkeyWrench.Database/MonkeyWrench.Database.csproj
===================================================================
@@ -92,6 +92,7 @@
     <Compile Include="SchedulerBase.cs" />
     <Compile Include="SchedulerGIT.cs" />
     <Compile Include="SchedulerSVN.cs" />
+    <Compile Include="LoggingCommand.cs" />
   </ItemGroup>
   <ItemGroup>
     <ProjectReference Include="..\MonkeyWrench.DataClasses\MonkeyWrench.DataClasses.csproj">

Modified: MonkeyWrench/Logger.cs
===================================================================
@@ -49,26 +49,28 @@ public static void Log (string format, params object [] args)
 
 		public static void Log (int verbosity, string format, params object [] args)
 		{
-			string message;
-
 			try {
 				if (!IsVerbosityIncluded (verbosity))
 					return;
 
-				message = FormatLog (format, args);
-				if (string.IsNullOrEmpty (Configuration.LogFile)) {
-					Console.Write (message);
-				} else {
-					using (FileStream fs = new FileStream (Configuration.LogFile, FileMode.Append, FileAccess.Write, FileShare.ReadWrite)) {
-						using (StreamWriter st = new StreamWriter (fs)) {
-							st.Write (message);
-						}
-					}
-				}
+				LogRaw (FormatLog (format, args));
 			} catch (Exception ex) {
 				Console.WriteLine (FormatLog ("Builder.Logger: An exception occurred while logging: {0}", ex.ToString ()));
 				throw;
 			}
 		}
+
+		public static void LogRaw (string message)
+		{
+			if (string.IsNullOrEmpty (Configuration.LogFile)) {
+				Console.Write (message);
+			} else {
+				using (FileStream fs = new FileStream (Configuration.LogFile, FileMode.Append, FileAccess.Write, FileShare.ReadWrite)) {
+					using (StreamWriter st = new StreamWriter (fs)) {
+						st.Write (message);
+					}
+				}
+			}
+		}
 	}
 }


_______________________________________________
Mono-patches maillist  -  [email protected]
http://lists.ximian.com/mailman/listinfo/mono-patches