Time profiling in XSLT transformations and DB requests

Builder/IISMainHandler/build.txt

@@ -1 +1 @@
-1968
+1969

FLocal.Common/Config.cs

@@ -54,7 +54,6 @@ namespace FLocal.Common {
 
 		protected Config(NameValueCollection data) : base(data) {
 			this.InitTime = DateTime.Now.ToLongTimeString();
-			this.mainConnection = new MySQLConnector.Connection(data["ConnectionString"], MySQLConnector.PostgresDBTraits.instance);
 			this.dataDir = data["DataDir"];
 			this.DirSeparator = System.IO.Path.DirectorySeparatorChar.ToString();
 			this.SaltMigration = data["SaltMigration"];
@@ -75,6 +74,7 @@ namespace FLocal.Common {
 			this.DefaultModernSkin = data["DefaultModernSkin"];
 			this.DefaultMachichara = data["DefaultMachichara"];
 			this.Logger = new SingleFileLogger(this);
+			this.mainConnection = new MySQLConnector.Connection(data["ConnectionString"], MySQLConnector.PostgresDBTraits.instance, this.Logger);
 		}
 
 		public static void Init(NameValueCollection data) {

FLocal.IISHandler/WebContext.cs

@@ -164,7 +164,9 @@ namespace FLocal.IISHandler {
 		public void WriteTransformResult(string templateName, System.Xml.Linq.XDocument data) {
 			this.httpresponse.ContentType = this.design.ContentType;
 			this.httpresponse.ContentEncoding = OutputEncoding;
+			DateTime start = DateTime.Now;
 			TemplateEngine.WriteCompiled(this.design.GetFSName(templateName), data, this.httpresponse.Output);
+			Config.instance.Logger.Log(templateName + " transformation took " + (DateTime.Now-start).TotalSeconds + " seconds");
 		}
 
 		public XElement exportSession() {

MySQLConnector/CommandExecutionLogger.cs

@@ -0,0 +1,26 @@
+using System;
+using System.Collections.Generic;
+using System.Linq;
+using System.Text;
+using Web.Core;
+
+namespace MySQLConnector {
+	class CommandExecutionLogger : IDisposable {
+
+		private readonly ILogger logger;
+
+		private readonly DateTime start;
+
+		public string commandText;
+
+		public CommandExecutionLogger(ILogger logger) {
+			this.logger = logger;
+			this.start = DateTime.Now;
+		}
+
+		void IDisposable.Dispose() {
+			this.logger.Log("Spent " + (DateTime.Now-start).TotalSeconds + " seconds while executing " + this.commandText);
+		}
+
+	}
+}

MySQLConnector/Connection.cs

@@ -12,13 +12,16 @@ namespace MySQLConnector {
 
 		internal readonly IDBTraits traits;
 
+		internal readonly ILogger logger;
+
 //		private DbConnection connection;
 		private string connectionString;
 
 		private HashSet<Transaction> transactions;
 
-		public Connection(string connectionString, IDBTraits traits) {
+		public Connection(string connectionString, IDBTraits traits, ILogger logger) {
 			this.traits = traits;
+			this.logger = logger;
 			this.connectionString = connectionString;
 			using(DbConnection connection = this.createConnection()) {
 				//just testing we can open a connection
@@ -26,6 +29,10 @@ namespace MySQLConnector {
 			this.transactions = new HashSet<Transaction>();
 		}
 
+		private CommandExecutionLogger CreateCommandExecutionLogger() {
+			return new CommandExecutionLogger(this.logger);
+		}
+
 		internal DbConnection createConnection() {
 			DbConnection connection = this.traits.createConnection(this.connectionString);
 			connection.Open();
@@ -33,6 +40,8 @@ namespace MySQLConnector {
 		}
 
 		private List<Dictionary<string, string>> _LoadByIds(DbCommand command, ITableSpec table, List<string> ids, bool forUpdate) {
+			using(var logger = this.CreateCommandExecutionLogger()) {
+
 				command.CommandType = System.Data.CommandType.Text;
 
 				ParamsHolder paramsHolder = new ParamsHolder();
@@ -41,7 +50,7 @@ namespace MySQLConnector {
 					placeholder.Add(this.traits.markParam(paramsHolder.Add(id)));
 				}
 
-			command.CommandText = "SELECT * FROM " + table.compile(this.traits) + " WHERE " + table.getIdSpec().compile(this.traits) + " IN (" + string.Join(", ", placeholder.ToArray()) + ")" + (forUpdate ? " FOR UPDATE" : "");
+				command.CommandText = logger.commandText = "SELECT * FROM " + table.compile(this.traits) + " WHERE " + table.getIdSpec().compile(this.traits) + " IN (" + string.Join(", ", placeholder.ToArray()) + ")" + (forUpdate ? " FOR UPDATE" : "");
 				//command.Prepare();
 				foreach(KeyValuePair<string, string> kvp in paramsHolder.data) {
 					command.AddParameter(kvp.Key, kvp.Value);
@@ -50,9 +59,9 @@ namespace MySQLConnector {
 				Dictionary<string, Dictionary<string, string>> rawResult = new Dictionary<string, Dictionary<string, string>>();
 				using(DbDataReader reader = command.ExecuteReader()) {
 					while(reader.Read()) {
-					Dictionary<string, string> row = new Dictionary<string,string>();
+						Dictionary<string, string> row = new Dictionary<string, string>();
 						for(int i=0; i<reader.FieldCount; i++) {
-//								throw new CriticalException("Name: " + reader.GetName(i));
+							//throw new CriticalException("Name: " + reader.GetName(i));
 							object value = reader.GetValue(i);
 							string sValue;
 							if(value is DateTime) {
@@ -68,7 +77,7 @@ namespace MySQLConnector {
 					}
 				}
 
-			List<Dictionary<string, string>> result = new List<Dictionary<string,string>>();
+				List<Dictionary<string, string>> result = new List<Dictionary<string, string>>();
 				foreach(string id in ids) {
 					if(rawResult.ContainsKey(id)) {
 						result.Add(rawResult[id]);
@@ -76,6 +85,7 @@ namespace MySQLConnector {
 				}
 				return result;
 			}
+		}
 
 		public List<Dictionary<string, string>> LoadByIds(ITableSpec table, List<string> ids) {
 			using(DbConnection connection = this.createConnection()) {
@@ -86,6 +96,8 @@ namespace MySQLConnector {
 		}
 
 		private List<string> _LoadIdsByConditions(DbCommand command, ITableSpec table, Web.Core.DB.conditions.AbstractCondition conditions, Diapasone diapasone, JoinSpec[] joins, SortSpec[] sorts, bool allowHugeLists) {
+			using(var logger = this.CreateCommandExecutionLogger()) {
+
 				command.CommandType = System.Data.CommandType.Text;
 
 				var conditionsCompiled = ConditionCompiler.Compile(conditions, this.traits);
@@ -126,7 +138,7 @@ namespace MySQLConnector {
 					command.AddParameter(kvp.Key, kvp.Value);
 				}
 
-			command.CommandText = "SELECT COUNT(*) " + queryMain;
+				command.CommandText = logger.commandText = "SELECT COUNT(*) " + queryMain;
 				object rawCount;
 				//try {
 				rawCount = command.ExecuteScalar();
@@ -157,6 +169,7 @@ namespace MySQLConnector {
 					return result;
 				}
 			}
+		}
 
 		public List<string> LoadIdsByConditions(ITableSpec table, Web.Core.DB.conditions.AbstractCondition conditions, Diapasone diapasone, JoinSpec[] joins, SortSpec[] sorts, bool allowHugeLists) {
 			using(DbConnection connection = this.createConnection()) {
@@ -167,6 +180,7 @@ namespace MySQLConnector {
 		}
 
 		public long GetCountByConditions(ITableSpec table, Web.Core.DB.conditions.AbstractCondition conditions, params JoinSpec[] joins) {
+			using(var logger = this.CreateCommandExecutionLogger()) {
 				using(DbConnection connection = this.createConnection()) {
 					using(DbCommand command = connection.CreateCommand()) {
 
@@ -185,7 +199,7 @@ namespace MySQLConnector {
 						}
 
 
-					command.CommandText = "SELECT COUNT(*) " + "FROM " + table.compile(this.traits) + " " + queryJoins + " " + queryConditions;
+						command.CommandText = logger.commandText = "SELECT COUNT(*) " + "FROM " + table.compile(this.traits) + " " + queryJoins + " " + queryConditions;
 						foreach(KeyValuePair<string, string> kvp in paramsHolder.data) {
 							command.AddParameter(kvp.Key, kvp.Value);
 						}
@@ -195,6 +209,7 @@ namespace MySQLConnector {
 					}
 				}
 			}
+		}
 
 		public Web.Core.DB.Transaction beginTransaction(System.Data.IsolationLevel iso) {
 			lock(this) {
@@ -210,29 +225,33 @@ namespace MySQLConnector {
 		}
 
 		public void lockTable(Web.Core.DB.Transaction _transaction, ITableSpec table) {
+			using(var logger = this.CreateCommandExecutionLogger()) {
 				Transaction transaction = (Transaction)_transaction;
 				lock(transaction) {
 					using(DbCommand command = transaction.sqlconnection.CreateCommand()) {
 						command.Transaction = transaction.sqltransaction;
 						command.CommandType = System.Data.CommandType.Text;
-					command.CommandText = "LOCK TABLE " + table.compile(this.traits);
+						command.CommandText = logger.commandText = "LOCK TABLE " + table.compile(this.traits);
 						command.ExecuteNonQuery();
 					}
 				}
 			}
+		}
 
 		public void lockRow(Web.Core.DB.Transaction _transaction, ITableSpec table, string id) {
+			using(var logger = this.CreateCommandExecutionLogger()) {
 				Transaction transaction = (Transaction)_transaction;
 				lock(transaction) {
 					using(DbCommand command = transaction.sqlconnection.CreateCommand()) {
 						command.Transaction = transaction.sqltransaction;
 						command.CommandType = System.Data.CommandType.Text;
-					command.CommandText = "SELECT * FROM " + table.compile(this.traits) + " where " + table.getIdSpec().compile(this.traits) + " = " + this.traits.markParam("id") + " FOR UPDATE";
+						command.CommandText = logger.commandText = "SELECT * FROM " + table.compile(this.traits) + " where " + table.getIdSpec().compile(this.traits) + " = " + this.traits.markParam("id") + " FOR UPDATE";
 						command.AddParameter("id", id);
 						command.ExecuteNonQuery();
 					}
 				}
 			}
+		}
 
 		public List<Dictionary<string, string>> LoadByIds(Web.Core.DB.Transaction _transaction, ITableSpec table, List<string> ids) {
 			Transaction transaction = (Transaction)_transaction;
@@ -255,6 +274,7 @@ namespace MySQLConnector {
 		}
 
 		public void update(Web.Core.DB.Transaction _transaction, ITableSpec table, string id, Dictionary<string, string> data) {
+			using(var logger = this.CreateCommandExecutionLogger()) {
 				Transaction transaction = (Transaction)_transaction;
 				lock(transaction) {
 					using(DbCommand command = transaction.sqlconnection.CreateCommand()) {
@@ -266,18 +286,20 @@ namespace MySQLConnector {
 
 						command.Transaction = transaction.sqltransaction;
 						command.CommandType = System.Data.CommandType.Text;
-					command.CommandText = "UPDATE " + table.compile(traits) + " set " + String.Join(", ", updates.ToArray()) + " where " + table.getIdSpec().compile(this.traits) + " = " + this.traits.markParam("id");
+						command.CommandText = logger.commandText = "UPDATE " + table.compile(traits) + " set " + String.Join(", ", updates.ToArray()) + " where " + table.getIdSpec().compile(this.traits) + " = " + this.traits.markParam("id");
 						command.AddParameter("id", id);
 						foreach(KeyValuePair<string, string> kvp in paramsholder.data) {
 							command.AddParameter(kvp.Key, kvp.Value);
 						}
-//					throw new CriticalException(command.CommandText + "; parameters: " + string.Join(", ", (from DbParameter parameter in command.Parameters select parameter.ParameterName + "='" + parameter.Value.ToString() + "'").ToArray()));
+						//					throw new CriticalException(command.CommandText + "; parameters: " + string.Join(", ", (from DbParameter parameter in command.Parameters select parameter.ParameterName + "='" + parameter.Value.ToString() + "'").ToArray()));
 						command.ExecuteNonQuery();
 					}
 				}
 			}
+		}
 
 		public string insert(Web.Core.DB.Transaction _transaction, ITableSpec table, Dictionary<string, string> data) {
+			using(var logger = this.CreateCommandExecutionLogger()) {
 				Transaction transaction = (Transaction)_transaction;
 				lock(transaction) {
 					using(DbCommand command = transaction.sqlconnection.CreateCommand()) {
@@ -291,7 +313,7 @@ namespace MySQLConnector {
 
 						command.Transaction = transaction.sqltransaction;
 						command.CommandType = System.Data.CommandType.Text;
-					command.CommandText = "INSERT INTO " + table.compile(this.traits) + " (" + String.Join(", ", updates.ToArray()) + ") VALUES (" + String.Join(", ", updatesPlaceholders.ToArray()) + ")";
+						command.CommandText = logger.commandText = "INSERT INTO " + table.compile(this.traits) + " (" + String.Join(", ", updates.ToArray()) + ") VALUES (" + String.Join(", ", updatesPlaceholders.ToArray()) + ")";
 						foreach(KeyValuePair<string, string> kvp in paramsholder.data) {
 							command.AddParameter(kvp.Key, kvp.Value);
 						}
@@ -301,19 +323,22 @@ namespace MySQLConnector {
 					}
 				}
 			}
+		}
 
 		public void delete(Web.Core.DB.Transaction _transaction, ITableSpec table, string id) {
+			using(var logger = this.CreateCommandExecutionLogger()) {
 				Transaction transaction = (Transaction)_transaction;
 				lock(transaction) {
 					using(DbCommand command = transaction.sqlconnection.CreateCommand()) {
 						command.Transaction = transaction.sqltransaction;
 						command.CommandType = System.Data.CommandType.Text;
-					command.CommandText = "DELETE FROM " + table.compile(traits) + " where " + table.getIdSpec().compile(this.traits) + " = " + this.traits.markParam("id");
+						command.CommandText = logger.commandText = "DELETE FROM " + table.compile(traits) + " where " + table.getIdSpec().compile(this.traits) + " = " + this.traits.markParam("id");
 						command.AddParameter("id", id);
 						command.ExecuteNonQuery();
 					}
 				}
 			}
+		}
 
 		internal void RemoveTransaction(Transaction transaction) {
 			lock(this) {

MySQLConnector/MySQLConnector.csproj

@@ -51,6 +51,7 @@
   <ItemGroup>
     <Compile Include="ConditionCompiler.cs" />
     <Compile Include="Connection.cs" />
+    <Compile Include="CommandExecutionLogger.cs" />
     <Compile Include="Extensions.cs" />
     <Compile Include="IDBTraits.cs" />
     <Compile Include="MySQLDBTraits.cs" />