I have been using stopwatch in one of my DevExpress based application. I have created a FlaUI based test case that initiates the keyboard, enters a value and then moves to the next column. Now, there are like 20+ columns in a row in the DevExpress grid I am using. While I try to run that test case 5 times to come to a baseline timing, I am seeing too much different results.
I am pasting an extract of my current code here:
public bool CreateNewGdistVoyageForPerformanceTesting(IEnumerable<GdistBenchVoyageParameters> gdistparameters,
string gridAutomationId)
{
var watch = System.Diagnostics.Stopwatch
.StartNew(); //This line of code is being used to monitor the time taken by each Keyboard operation
long TotalTimeConsumed = 0;
int MaxAllowedTime = 0;
int HasTimeExceeded = 0;
bool TimeHasNotExceeded = true;
watch.Start();
_logger.Info("Creating a new GDIST Voyage");
TabItem ParentControl = VoyageEditorTabControl.SelectedTabItem;
var CurrentSelectedTab = VoyageEditorTabControl.SelectedTabItemIndex;
var ParentGrid = VoyageEditorTabControl.TabItems[CurrentSelectedTab]
.FindFirstDescendant(cf => cf.ByAutomationId(gridAutomationId)).AsGrid();
_controlAction.Highlight(ParentGrid);
var Pattern = ParentGrid.Patterns.Grid;
var RowCount = Pattern.Pattern.RowCount;
var ColumnCount = Pattern.Pattern.ColumnCount;
_logger.Info("======================================================================================");
if (ParentGrid.AutomationId.Equals("ParentGridControl"))
{
_logger.Info($"Performance Testing on GDIST's View Main Grid :{gridAutomationId}");
_logger.Info($"Current Grid Row count is: {RowCount}");
_logger.Info("Creating a new voyage for GDIST Bench");
}
else
{
_logger.Info($"Performance Testing on GDIST's Similar Voyages Panel Grid: {gridAutomationId}");
_logger.Info($"Current Grid Row count is: {RowCount}");
_logger.Info("Editing an existing voyage for GDIST Bench's Similar Voyages Panel");
}
for (int i = 0; i < ColumnCount; i++)
{
var cell = ParentGrid.Patterns.Grid.Pattern.GetItem(ParentGrid.RowCount - 1, i);
if (cell == null)
{
_logger.Warning("No Columns found with matching Automation Ids");
break;
}
if (cell.AutomationId.Equals("Vessel"))
{
MaxAllowedTime = 1500;
gdistparameters.ToList().ForEach(voyageDetailsField =>
{
if (voyageDetailsField.VesselId != null)
{
_logger.Info("Adding Data in Vessel ID ");
cell.Focus();
cell.Click();
_logger.Info($"Entered value is:{voyageDetailsField.VesselId}");
watch.Stop(); // trying this to ensure the watch dummy run to remove JIT noise
if (!watch.IsRunning)
{
watch.Restart(); //starting the watch
}
Keyboard.Type(voyageDetailsField.VesselId.Trim());
watch.Stop();
Keyboard.Press(VirtualKeyShort.TAB);
// _controlAction.WaitFor(new TimeSpan(0, 0, 2));
Wait.UntilInputIsProcessed();
_logger.Info($"Execution Time: {watch.ElapsedMilliseconds} ms");
if (watch.ElapsedMilliseconds > MaxAllowedTime)
{
HasTimeExceeded++;
_logger.Warning($"The data entry time has exceeded beyond the fixed value by {watch.ElapsedMilliseconds - MaxAllowedTime} ms");
}
TotalTimeConsumed = TotalTimeConsumed + watch.ElapsedMilliseconds;
}
});
TotalTimeConsumed = TotalTimeConsumed + watch.ElapsedMilliseconds;
}
if (cell.AutomationId.Equals("LoadDate")) //Load Date
{
MaxAllowedTime = 500;
gdistparameters.ToList().ForEach(voyageDetailsField =>
{
// _logger.Info("Adding data into the Load Date field");
if (voyageDetailsField.LoadDate != null)
{
_logger.Info("Adding Data in Load Date ");
cell.Focus();
cell.Click();
_logger.Info($"Entered value is:{voyageDetailsField.LoadDate}");
watch.Stop(); // trying this to ensure the watch dummy run to remove JIT noise
if (!watch.IsRunning)
{
watch.Restart(); //starting the watch
}
Keyboard.Type(voyageDetailsField.LoadDate.Trim());
watch.Stop();
Keyboard.Press(VirtualKeyShort.TAB);
// _controlAction.WaitFor(new TimeSpan(0, 0, 2));
Wait.UntilInputIsProcessed();
_logger.Info($"Execution Time: {watch.ElapsedMilliseconds} ms");
if (watch.ElapsedMilliseconds > MaxAllowedTime)
{
HasTimeExceeded++;
_logger.Warning(
$"The data entry time has exceeded beyond the fixed value by {watch.ElapsedMilliseconds - MaxAllowedTime} ms");
}
TotalTimeConsumed = TotalTimeConsumed + watch.ElapsedMilliseconds;
}
});
TotalTimeConsumed = TotalTimeConsumed + watch.ElapsedMilliseconds;
}
The timings that I have been observing via the logger functionality is below.
I have run this on multiple PCs, multiple environments but the results are very different. The 5th run is actually taking a lot in every single case.
Note also that all the data that is being entered in populated when the application loads so network latency shouldn't be a problem here.
Moreover, I read that StopWatch comes with a lot of JIT noise, and yes, I had experienced it every time it was running for the first time, so I have already given it a false start in my code.
This test is a performance test and requires benchmarking. We can decide on the benchmarking with such big difference in the numbers.
