Join 34,000+ subscribers and receive articles from our
blog about software quality, testing, QA and security.

StopWatch function


#1

I want to be able to start a named “StopWatch” and subsequently log splits to the named stopwatch.

Pseudo-Code:

SiAuto.Main.CreateStopWatch( “MyStopWatch” );

SiAuto.Main.LogStopWatchSplit( “MyStopWatch”, “At the begining of X” );

SiAuto.Main.LogStopWatchSplit( “MyStopWatch”, “At the ending of X” );

SiAuto.Main.LogStopWatchSplit( “MyStopWatch”, “At the begining of Y” );

SiAuto.Main.LogStopWatchSplit( “MyStopWatch”, “At the ending of Y” );

SiAuto.Main.EndStopWatch( “MyStopWatch”);

each split logs the name, the message and the duration in millisecs since the stopwatch started. Ideally it could log the duration since the last split as well.

Create and End would log the absolute time and the duration.

How can I accomplish something like this with the existing API.

Thanks so much
Jim


#2

Hello Jim,

this feature is currently not included in the libraries. However, there is actually a feature in the Console which comes close to what you are asking for. There’s the Details toolbox (shown by default on the left of the Console) which can display the time span between two selected log entries (see the Time Span row).

If you want to include this information directly in the log message via the library, you would need to extend the Session class with the required methods. I usually suggest using class helpers/extension methods for adding new methods. But since you need to store the timer information somewhere, it’s probably a better idea to add a derived Session class (with a field to manage the timer information). I can prepare a small example on how to do this on Monday.

By the way, as an unrelated side note, there’s the high-resolution time stamp feature in the libraries which provide a much higher resolution (micro-seconds) which might come in handy in your situation. High-res time stamps can be enabled with:

Hope that helps!


#3

Here’s the promised example:

[quote]class CustomSession : Session
{
private IDictionary<string, Stopwatch> m_Timers;
private object m_TimersLock;

public CustomSession(SmartInspect parent, string name): base(parent, name)
{ 
	m_TimersLock = new object();
}

public void StartTimer(string name)
{
	lock (m_TimersLock)
	{
		if (m_Timers == null)
		{
			m_Timers = new Dictionary<string, Stopwatch>();
		}

		Stopwatch stopwatch = Stopwatch.StartNew();
		m_Timers[name] = stopwatch;
	}

	LogMessage("Timer started: {0}", name);
}

private bool TryGetTimer(string name, out long elapsed)
{
	elapsed = 0;

	if (m_Timers == null)
	{
		return false;
	}

	Stopwatch stopwatch;
	if (!m_Timers.TryGetValue(name, out stopwatch))
	{
		return false;
	}

	elapsed = stopwatch.ElapsedMilliseconds;
	return true;
}

public void LogTimer(string name, string title)
{
	long elapsed;

	lock (m_TimersLock)
	{
		if (!TryGetTimer(name, out elapsed))
		{
			return;
		}
	}

	LogMessage("Timer {0}: {1} ({2})", name, title, elapsed);
}

public void StopTimer(string name)
{
	long elapsed;

	lock (m_TimersLock)
	{
		if (!TryGetTimer(name, out elapsed))
		{
			return;
		}

		m_Timers[name] = null;
	}

	LogMessage("Timer stopped: {0} ({1})", name, elapsed);
}

}

class Program
{
static void Main()
{
SiAuto.Si.Enabled = true;
CustomSession session = new CustomSession(SiAuto.Si, “Timer”);
for (int i = 0; i < 100; i++)
{
session.StartTimer(“Test”);
Thread.Sleep(100);
session.LogTimer(“Test”, “First message”);
Thread.Sleep(100);
session.LogTimer(“Test”, “Second message”);
Thread.Sleep(100);
session.StopTimer(“Test”);
}
}
}[/quote]

It basically works as you suggested. There are methods for starting/stopping a named timer and for sending log messages including the elapsed time since start. Feel free to use and modify it as needed. Let me know if you have any questions.