Logger for Performance testing

This post has been republished via RSS; it originally appeared at: TestingSpot Blog articles.

First published on MSDN on May 31, 2017

Authored by Gunjan Jain


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
1. The response time for a transaction
2. The response time for a complete scenario
3. Finding out average response time
4. 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]
GO
/****** Object:  Table [dbo].[DataLog]    Script Date: 5/31/2017 4:39:31 AM ******/
SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO
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]
GO

USE [Logging]
GO
/****** Object:  Table [dbo].[ExceptionLog]    Script Date: 5/31/2017 4:39:50 AM ******/
SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO
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]
GO


Step2 | Create a Coded UI project
Please refer this to know how to create a coded UI 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 DataLogCollection = new List();
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();
}
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.

<appSettings>

<add key="LoggerConnectionString" value="Data Source=<<servername>>;Initial Catalog=<<DBName>>;UserID=<<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(“<>“)
var connection = Logger.Logger.GetDataContext();
//This is the higher level
obj.ScenarioStart()
<>
obj.TransactionStart(“Transaction Name“);
<>
obj.TransactionEnd(“Transaction Name“);

obj.TransactionStart(“Transaction Name“);
<>
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 : This 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

Leave a Reply

Your email address will not be published. Required fields are marked *

*

This site uses Akismet to reduce spam. Learn how your comment data is processed.