Logger for performance testing

Article
10/11/2015

About the Logger

Logging is an integral part of performance testing. The following method of logging performance testing, (done) using coded UI test or selenium test using Visual Studio will help in getting better insights into

The response time for a transaction
The response time for a complete scenario
Finding out average response time
90th % response time.

Though there are multiple ways of logging such as text file based logging, logging in test context, this method provides easier mode of analysis of the results. Using the queries given in section 6, a user can get a holistic view of the response times for scenario/transaction; and import the results into excel and create graphical modals for better analysis. The other main advantage; is use of sql queries for analysis, compared to reading text file based logging.

[Note]: There are different ways of invoking timers in and logging results, this is one such method that makes use of DateTime difference to calculate and log results into SQL. For simpler ways of invoking timers and noting the results, please refer "https://blogs.msdn.microsoft.com/geoffgr/updated-adding-timers-to-coded-ui-tests-running-in-load-tests/"

How to do it:

1. Create 2 tables [DataLog] and [ExceptionLog]

2. Create the coded UI project that does coded UI based clicks

3. Include the logger code [.cs file]

4. Include the connection strings in web.config

5. Add the code for logging before and after every transaction and scenario.

6. Collect the data using the SQL queries given.

Step1

Create database Logging

Table creation

USE [Logging]

/****** Object: Table [dbo].[DataLog] Script Date: 4/9/2015 4:39:31 AM ******/

SET ANSI_NULLS ON

SET QUOTED_IDENTIFIER ON

CREATE TABLE [dbo].[DataLog](

[Id] [int] IDENTITY(1,1) NOT NULL,

[MachineName] [nvarchar](100) NULL,

[UserId] [nvarchar](100) NULL,

[ScenarioName] [nvarchar](100) NULL,

[ScenarioResponseTime] [nvarchar](30) NULL,

[TransactionName] [nvarchar](100) NULL,

[TransactionResponseTime] [nvarchar](30) NULL,

[StartDateTime] [datetime] NULL,

[EndDateTime] [datetime] NULL,

[Misc] [nvarchar](100) NULL,

PRIMARY KEY CLUSTERED

( [Id] ASC

)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]

) ON [PRIMARY]

USE [Logging]

/****** Object: Table [dbo].[ExceptionLog] Script Date: 4/9/2015 4:39:50 AM ******/

SET ANSI_NULLS ON

SET QUOTED_IDENTIFIER ON

CREATE TABLE [dbo].[ExceptionLog](

[ExceptionId] [int] IDENTITY(1,1) NOT NULL,

[MachineName] [nvarchar](100) NULL,

[UserId] [nvarchar](100) NULL,

[ScenarioName] [nvarchar](100) NULL,

[Exception] [nvarchar](4000) NULL,

[ExceptionTime] [datetime] NULL,

PRIMARY KEY CLUSTERED

(

[ExceptionId] ASC

)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]

) ON [PRIMARY]

Step2

Create your coded UI based project

Step3

Copy paste this code into a cs file

using System;

using System.Collections.Generic;

using System.Configuration;

using System.Data;

using System.Data.SqlClient;

using System.Linq;

using System.Text;

using System.Threading.Tasks;

namespace Logger

{

public class Logger

{

private static SqlConnection con = null;

public List<DataLog> DataLogCollection = new List<DataLog>();

DateTime sc_startdateTime = new DateTime();

DateTime sc_enddateTime = new DateTime();

DateTime tr_startdateTime = new DateTime();

DateTime tr_enddateTime = new DateTime();

public Logger(string _ScenarioName="undefined")

{

ScenarioName = _ScenarioName;

}

//Singleton object

public static SqlConnection GetDataContext()

{

if (con == null)

{

string loggerConnectionString = ConfigurationManager.AppSettings.Get("LoggerConnectionString");

con = new SqlConnection();

con.ConnectionString = loggerConnectionString;

con.Open();

return con;

}

else

{

return con;

}

public void ScenarioStart()

{

sc_startdateTime = DateTime.Now;

}

public void ScenarioEnd()

{

DataLog dataLog = new DataLog();

var dataContext = GetDataContext();

sc_enddateTime = DateTime.Now;

var ScenarioResponseTime = sc_enddateTime.Subtract(sc_startdateTime);

dataLog.MachineName = Environment.MachineName;

dataLog.UserName = System.DirectoryServices.AccountManagement.UserPrincipal.Current.DisplayName;

dataLog.ScenarioName = ScenarioName;

dataLog.ScenarioResponseTime = ScenarioResponseTime.ToString();

dataLog.TransactionName = null;

dataLog.TransactionResponseTime = null;

dataLog.StartDateTime = sc_startdateTime;

dataLog.EndDateTime = sc_enddateTime;

DataLogCollection.Add(dataLog);

StringBuilder sqlcommmand = new StringBuilder();

string tableName = ConfigurationManager.AppSettings.Get("TableName");

foreach (DataLog dataLogvalue in DataLogCollection)

{

sqlcommmand.Append("Insert into " + tableName.ToString() + " values('"+dataLogvalue.MachineName+"','"+dataLogvalue.UserName+"','"+dataLogvalue.ScenarioName+"','"+dataLogvalue.ScenarioResponseTime+"','"+dataLogvalue.TransactionName+"','"+dataLogvalue.TransactionResponseTime+"','"+dataLogvalue.StartDateTime+"','"+dataLogvalue.EndDateTime+"','');\r\n");

}

SqlCommand myCommand = new SqlCommand(sqlcommmand.ToString(), con);

myCommand.ExecuteNonQuery();

}

public void TransactionStart(string TransactionName)

{

tr_startdateTime = DateTime.Now;

}

public void TransactionEnd(string TransactionName)

{

DataLog dataLog = new DataLog();

var dataContext = GetDataContext();

tr_enddateTime = DateTime.Now;

var TransactionResponseTime = tr_enddateTime.Subtract(tr_startdateTime);

dataLog.MachineName = Environment.MachineName;

dataLog.UserName = System.DirectoryServices.AccountManagement.UserPrincipal.Current.DisplayName;

dataLog.ScenarioName = ScenarioName;

dataLog.ScenarioResponseTime = null;

dataLog.TransactionName = TransactionName;

dataLog.TransactionResponseTime = TransactionResponseTime.ToString();

dataLog.StartDateTime = tr_startdateTime;

dataLog.EndDateTime = tr_enddateTime;

DataLogCollection.Add(dataLog);

}

public void LogException(string ScenarioName, string exception)

{

ExceptionLog exceptionLog = new ExceptionLog();

var dataContext = GetDataContext();

exceptionLog.MachineName = Environment.MachineName;

exceptionLog.UserName = System.DirectoryServices.AccountManagement.UserPrincipal.Current.DisplayName;

exceptionLog.ScenarioName = ScenarioName;

exceptionLog.Exception = exception;

exceptionLog.ExceptionTime = DateTime.Now;

string tableName = ConfigurationManager.AppSettings.Get("ExceptionLogTable");

string sqlcommand = "insert into " + tableName + " values ('" + exceptionLog.MachineName + "','" + exceptionLog.UserName + "','" + exceptionLog.ScenarioName + "','" + exceptionLog.Exception.Replace("\"", string.Empty).Replace("'", string.Empty) +"','" + exceptionLog.ExceptionTime + "')";

SqlCommand myCommand = new SqlCommand(sqlcommand, con);

myCommand.ExecuteNonQuery();

}

public void WriteToDB()

{

var dataContext = GetDataContext();

StringBuilder sqlcommmand = new StringBuilder();

string tableName = ConfigurationManager.AppSettings.Get("TableName");

foreach (DataLog dataLogvalue in DataLogCollection)

{

sqlcommmand.Append("Insert into " + tableName.ToString() + " values('" + dataLogvalue.MachineName + "','" + dataLogvalue.UserName + "','" + dataLogvalue.ScenarioName + "','" + dataLogvalue.ScenarioResponseTime + "','" + dataLogvalue.TransactionName + "','" + dataLogvalue.TransactionResponseTime + "','" + dataLogvalue.StartDateTime + "','" + dataLogvalue.EndDateTime + "','');\r\n");

}

SqlCommand myCommand = new SqlCommand(sqlcommmand.ToString(), dataContext);

myCommand.ExecuteNonQuery();

DataLogCollection = new List<DataLog>();

}

public string ScenarioName { get; set; }

}

public class DataLog

{

public string MachineName { get; set; }

public string UserName { get; set; }

public string ScenarioName { get; set; }

public string ScenarioResponseTime { get; set; }

public string TransactionName { get; set; }

public string TransactionResponseTime { get; set; }

public DateTime StartDateTime { get; set; }

public DateTime EndDateTime { get; set; }

}

public class ExceptionLog

{

public string MachineName { get; set; }

public string UserName { get; set; }

public string ScenarioName { get; set; }

public string Exception { get; set; }

public DateTime ExceptionTime { get; set; }

}

Step4

Add the following code in App settings

In case you have integrated security please change the first line of the connection string

   <add key="LoggerConnectionString" value="Data Source=<<servername>>;Initial Catalog=&quot;<<DBName>>&quot;;User ID=<<UserID>>;Password=<<Password>>"/>  
  <add key="TableName" value="DataLog"/>
  <add key="ExceptionLogTable" value="ExceptionLog"/>
    <add key="TimeforExecutionmin" value="5"/>

 </appSettings>

Step5

Adding the logging code to collect results in SQL

Logger.Logger obj = new Logger.Logger(" <<Scenario Name>> ")

var connection = Logger.Logger.GetDataContext();

//This is the higher level

obj.ScenarioStart()

<<Ur code>>

obj.TransactionStart("Transaction Name");

<<Ur code>>

obj.TransactionEnd("Transaction Name");

obj.TransactionStart("Transaction Name");

<<Ur code>>

obj.TransactionEnd("Transaction Name");

obj.SenarioEnd()

Step 6

Collecting Results

Query1

This gives you

Scenario Name, Avg Response Time, Total Time, Number of times Scenario Executed, Min response time, Max response time

Transaction Name, Avg Response Time, Total Time, Number of times Scenario Executed, Min response time, Max response time

declare @scnName varchar(max) = '%Scenario Name%'

declare @starttime datetime = '2015-06-24 04:16:33.743'

declare @endtime datetime = '2015-06-24 09:19:33.743'

select ScenarioName, TransactionName,

DATEDIFF(S, '00:00:00.000', cast(cast(avg(cast(CAST(LEFT(ScenarioResponseTime, 12) as datetime) as float)) as datetime) as time)) ScenarioAvgTime,

DATEDIFF(S, '00:00:00.000', cast(cast(sum(cast(CAST(LEFT(ScenarioResponseTime, 12) as datetime) as float)) as datetime) as time)) ScenarioTotalTime,

COUNT(distinct(ScenarioName)) CountofScenarios,

MIN(DATEDIFF(S, '00:00:00.000', ScenarioResponseTime)) MinScenarioResponseTime,

MAX(DATEDIFF(S, '00:00:00.000', ScenarioResponseTime)) MaxScenarioResponseTime,

DATEDIFF(S, '00:00:00.000', cast(cast(avg(cast(CAST(LEFT(TransactionResponseTime, 12) as datetime) as float)) as datetime) as time)) TransactionAvgTimeInSec,

DATEDIFF(S, '00:00:00.000', cast(cast(sum(cast(CAST(LEFT(TransactionResponseTime, 12) as datetime) as float)) as datetime) as time)) TransactionTotalTimeInSec,

COUNT(TransactionName) CountofTransactions,

MIN(DATEDIFF(S, '00:00:00.000', TransactionResponseTime)) MinTransactionResponseTime,

MAX(DATEDIFF(S, '00:00:00.000', TransactionResponseTime)) MaxTransactionResponseTime

from [Logging].[dbo].[DataLog] where StartDateTime between @starttime and @endtime

and scenarioname like @scnName group by ScenarioName, TransactionName;

Query2 - gives 90th percentile of the response time

SELECT DISTINCT ScenarioName, TransactionName AS ScName

,DATEDIFF(S, '00:00:00.000',CONVERT(VARCHAR,DATEADD(ms, (

PERCENTILE_CONT(0.9) WITHIN GROUP (ORDER BY DATEDIFF(MS, '00:00:00.000', TransactionResponseTime) )

OVER (PARTITION BY TransactionName)),0),114)) as '90thpercentile'

FROM dbo.DataLog where StartDateTime between @starttime and @endtime

and scenarioname like @scnName;

Query3 - for specific transaction

SELECT TransactionName, count(distinct(StartDateTime)) CountOfStart , count(distinct(EndDateTime)) CountOfEnd FROM [Logging].[dbo].[DataLog]

where ScenarioName like @scnName and TransactionName like '%<<TransactionName>>%'

and StartDateTime between @starttime and @endtime

group by ScenarioName, TransactionName

Share via

Logger for performance testing

Additional resources