public void MessageQueueFlushTest()
{
const int count = 10000;
MessageSourceProvider source = new MessageSourceProvider(0, true);
Gibraltar.Messaging.IMessengerPacket[] batch = new Gibraltar.Messaging.IMessengerPacket[count];
for (int i = 0; i < count; i++)
{
batch[i] = Log.MakeLogPacket(LogMessageSeverity.Verbose, "GibraltarTest", "Test.Core.LogMessage.Performance.Flush",
source, null, null, null, null, "Batch message #{0} of {1}", i, count);
}
Log.Write(LogMessageSeverity.Information, LogWriteMode.WaitForCommit, null, "Unit Tests", "Clearing message queue", null);
DateTimeOffset startWrite = DateTimeOffset.UtcNow;
Log.Write(batch, LogWriteMode.Queued);
DateTimeOffset startFlush = DateTimeOffset.UtcNow;
Log.Write(LogMessageSeverity.Information, LogWriteMode.WaitForCommit, null, "Unit Tests", "Message batch flushed",
"All {0} messages have been flushed.", count);
DateTimeOffset endFlush = DateTimeOffset.UtcNow;
TimeSpan writeDuration = startFlush - startWrite;
TimeSpan flushDuration = endFlush - startFlush;
Trace.TraceInformation("Write of {0:N0} messages to queue took {1:F3} ms and flush took {2:F3} ms.",
count, writeDuration.TotalMilliseconds, flushDuration.TotalMilliseconds);
for (int i = 0; i < count; i++)
{
batch[i] = Log.MakeLogPacket(LogMessageSeverity.Verbose, "GibraltarTest", "Test.Core.LogMessage.Performance.Flush",
source, null, null, null, null, "Batch message #{0} of {1}", i, count);
}
DateTimeOffset startWriteThrough = DateTimeOffset.UtcNow;
Log.Write(batch, LogWriteMode.WaitForCommit);
DateTimeOffset endWriteThrough = DateTimeOffset.UtcNow;
TimeSpan writeThroughDuration = endWriteThrough - startWriteThrough;
Trace.TraceInformation("Write of {0:N0} messages as WaitForCommit took {1:F3} ms.",
count, writeThroughDuration.TotalMilliseconds);
}
private void StartTrackingCommand(DbCommand command, DbCommandInterceptionContext context)
{
if (command == null)
{
return;
}
try
{
var messageBuilder = new StringBuilder(1024);
string caption, shortenedQuery;
if (command.CommandType == CommandType.StoredProcedure)
{
shortenedQuery = command.CommandText;
caption = string.Format("Executing Procedure '{0}'", shortenedQuery);
}
else
{
//we want to make a more compact version of the SQL Query for the caption...
var queryLines = command.CommandText.Split(new[] { '\r', '\n' });
//now rip out any leading/trailing white space...
var cleanedUpLines = new List <string>(queryLines.Length);
foreach (var queryLine in queryLines)
{
if (string.IsNullOrWhiteSpace(queryLine) == false)
{
string minimizedLine = queryLine.Trim();
if (string.IsNullOrWhiteSpace(minimizedLine) == false)
{
cleanedUpLines.Add(minimizedLine);
}
}
}
//and rejoin to make the shortened command.
shortenedQuery = string.Join(" ", cleanedUpLines);
if (shortenedQuery.Length > 512)
{
shortenedQuery = shortenedQuery.Substring(0, 512) + "(...)";
messageBuilder.AppendFormat("Full Query:\r\n\r\n{0}\r\n\r\n", command.CommandText);
}
caption = string.Format("Executing Sql: '{0}'", shortenedQuery);
}
string paramString = null;
if (command.Parameters.Count > 0)
{
messageBuilder.AppendLine("Parameters:");
var paramStringBuilder = new StringBuilder(1024);
foreach (DbParameter parameter in command.Parameters)
{
string value = parameter.Value.FormatDbValue();
messageBuilder.AppendFormat(" {0}: {1}\r\n", parameter.ParameterName, value);
paramStringBuilder.AppendFormat("{0}: {1}, ", parameter.ParameterName, value);
}
paramString = paramStringBuilder.ToString();
paramString = paramString.Substring(0, paramString.Length - 2); //get rid of the trailing comma
messageBuilder.AppendLine();
}
var trackingMetric = new DatabaseMetric(shortenedQuery, command.CommandText);
trackingMetric.Parameters = paramString;
if (command.Transaction != null)
{
messageBuilder.AppendFormat("Transaction:\r\n Id: {0:X}\r\n Isolation Level: {1}\r\n\r\n", command.Transaction.GetHashCode(), command.Transaction.IsolationLevel);
}
var connection = command.Connection;
if (connection != null)
{
trackingMetric.Server = connection.DataSource;
trackingMetric.Database = connection.Database;
messageBuilder.AppendFormat("Server:\r\n DataSource: {3}\r\n Database: {4}\r\n Connection Timeout: {2:N0} Seconds\r\n Provider: {0}\r\n Server Version: {1}\r\n\r\n",
connection.GetType(), connection.ServerVersion, connection.ConnectionTimeout, connection.DataSource, connection.Database);
}
var messageSourceProvider = new MessageSourceProvider(2); //It's a minimum of two frames to our caller.
if (LogCallStack)
{
messageBuilder.AppendFormat("Call Stack:\r\n{0}\r\n\r\n", messageSourceProvider.StackTrace);
}
Log.Write(_configuration.QueryMessageSeverity, LogSystem, messageSourceProvider, null, null, LogWriteMode.Queued, null, LogCategory, caption,
messageBuilder.ToString());
trackingMetric.MessageSourceProvider = messageSourceProvider;
//we have to stuff the tracking metric in our index so that we can update it on the flipside.
try
{
_databaseMetrics[command.GetHashCode()] = trackingMetric;
}
catch (Exception ex)
{
#if DEBUG
Log.Error(ex, LogCategory, "Unable to set database tracking metric for command due to " + ex.GetType(), "While storing the database metric for the current operation a {0} was thrown so it's unpredictable what will be recorded at the end of the operation.\r\n{1}", ex.GetType(), ex.Message);
#endif
GC.KeepAlive(ex);
}
}
catch (Exception ex)
{
#if DEBUG
Log.Error(ex, LogCategory, "Unable to record Entity Framework event due to " + ex.GetType(), "While calculating the log message for this event a {0} was thrown so we are unable to record the event.\r\n{1}", ex.GetType(), ex.Message);
#endif
GC.KeepAlive(ex);
}
}
