[.net] [MDX] Timing & StopWatch

Started by
8 comments, last by MickDuprez 17 years, 8 months ago
I'm using the stopwatch object to perform my timing between frames in my render loop. I'm getting some really strange timings for my frame delta. If I run in windowed mode with 6000 sprites, I get roughly 20-22 milliseconds per frame. If I run in full screen with the same parameters I get roughly 33 milliseconds which drops my FPS to 30 FPS. This is odd, considering I only have my presentation interval set to one for full screen mode, this should effectively limit it to the refresh rate (60 Hz) and yield the same results (I could be wrong, I just assumed this from random observations). I also turned off the vsync, and it went to 23-25 milliseconds in fullscreen (strange that it would drop like that). Still, I'm missing like 5-8 FPS in fullscreen mode (yes, I know it's a small number, but shouldn't fullscreen be as fast or faster than windowed mode?). Perhaps it's my timing code, but I don't know for sure. So can someone look at this code and see if I messed up somewhere?

/// <summary>
/// Object to handle timing operations.
/// </summary>
public class Timer : NamedObject 
{
	#region Variables.
	private Stopwatch _timer;			// Actual timer object.
	private long _milliseconds;			// Milliseconds.
	private long _ticks;				// Clock ticks.
	private TimeSpan _span;				// Time span.
	#endregion

	#region Properties.
	/// <summary>
	/// Property to get the number of milliseconds elapsed since the timer was started.
	/// </summary>
	public long Milliseconds
	{
		get
		{
			GetTime();
			return _milliseconds;
		}
	}

	/// <summary>
	/// Property to get the number of microseconds elapsed since the timer was started.
	/// </summary>
	public long Microseconds
	{
		get
		{
			return Milliseconds * 1000;
		}
	}

	/// <summary>
	/// Property to return the number of ticks since the timer was started.
	/// </summary>
	public long Ticks
	{
		get
		{
			GetTime();
			return _ticks;
		}
	}

	/// <summary>
	/// Property to return the time elapsed since the timer was started.
	/// </summary>
	public TimeSpan Elapsed
	{
		get
		{
			GetTime();
			return _span;
		}
	}
	#endregion

	#region Methods.
	/// <summary>
	/// Function to start the timing process.
	/// </summary>
	private void GetTime()
	{
		// Stop the timer and get the timings.
		_timer.Stop();
		_milliseconds  += _timer.ElapsedMilliseconds;
		_ticks += _timer.ElapsedTicks;
		_span += _timer.Elapsed;
		// Reset and start over.
		_timer.Reset();
		_timer.Start();
	}

	/// <summary>
	/// Function to reset the timer.
	/// </summary>
	public void Reset()
	{
		_timer.Stop();
		_timer.Reset();
		_milliseconds = 0;
		_ticks = 0;
		_span = TimeSpan.MinValue;
	}

	/// <summary>
	/// Function to convert the desired frames per second to milliseconds.
	/// </summary>
	/// <param name="FPS">Desired frames per second.</param>
	/// <returns>Frames per second in milliseconds.</returns>
	public static double FPSToMilliseconds(double FPS)
	{
		if (FPS > 0)
			return (1000/(FPS + 3));
		else
			return 0;
	}

	/// <summary>
	/// Function to convert the desired frames per second to microseconds.
	/// </summary>
	/// <param name="FPS">Desired frames per second.</param>
	/// <returns>Frames per second in microseconds.</returns>
	public static double FPSToMicroseconds(double FPS)
	{
		if (FPS > 0)
			return (1000000/(FPS + 3));
		else
			return 0;
	}
	#endregion

	#region Constructors/Destructors.
	/// <summary>
	/// Constructor.
	/// </summary>
	/// <param name="timerName">Name of this timer.</param>
	internal Timer(string timerName) : base(timerName)
	{
		_timer = Stopwatch.StartNew();
		Reset();
	}
	#endregion
}

All this basically does is make the stop watch act as though it were a continuously running timer. The actual calculations for timing are performed in this class:

/// <summary>
/// Object for timing data like FPS, # of frames, etc...
/// </summary>
public class TimingData
{
	#region Variables.
	private double _lastFrameTime;		// Last frame time.
	private double _currentFrameTime;	// Current frame time.
	private double _frameDrawTime;		// Time to draw a frame in milliseconds.
	private double _lastFPSFrameTime;	// Last FPS.
	private double _averageFPS;			// Average FPS.
	private double _highestFPS;			// Highest FPS.
	private double _lowestFPS;			// Lowest FPS.
	private double _currentFPS;			// Current FPS.
	private long _frameCount;			// Frame count.
	private Timer _timer;				// FPS timer.
	#endregion

	#region Properties.
	/// <summary>
	/// Property to return the amount of time to draw a frame in milliseconds.
	/// </summary>
	public double FrameDrawTime
	{
		get
		{
			return _frameDrawTime;
		}
	}

	/// <summary>
	/// Property to return the average Frames Per Second.
	/// </summary>
	public double AverageFPS
	{
		get
		{
			return _averageFPS;
		}
	}

	/// <summary>
	/// Property to return the highest Frames Per Second.
	/// </summary>
	public double HighestFPS
	{
		get
		{
			return _highestFPS;
		}
	}

	/// <summary>
	/// Property to return the lowest Frames Per Second.
	/// </summary>
	public double LowestFPS
	{
		get
		{
			return _lowestFPS;
		}
	}

	/// <summary>
	/// Property to return the current Frames Per Second.
	/// </summary>
	public double CurrentFPS
	{
		get
		{
			return _currentFPS;
		}
	}

	/// <summary>
	/// Property to return the current number of frames drawn.
	/// </summary>
	public long FrameCount
	{
		get
		{
			return _frameCount;
		}
	}
	#endregion

	#region Methods.
	/// <summary>
	/// Function to calculate the frames per second.
	/// </summary>
	private void GetFPS()
	{
		_frameCount++;

		if ((_currentFrameTime - _lastFPSFrameTime) >= 1000)
		{
			_currentFPS = ((double)_frameCount / (_currentFrameTime - _lastFPSFrameTime)) * 1000.0;

			if (_averageFPS == 0.0)
				_averageFPS = _currentFPS;
			else
			{
				_averageFPS = (_averageFPS + _currentFPS) / 2.0;

				if (_currentFPS > _highestFPS)
					_highestFPS = _currentFPS;

				if ((_currentFPS < _lowestFPS) || (_lowestFPS == 0))
					_lowestFPS = _currentFPS;
			}

			_lastFPSFrameTime = _currentFrameTime;
			_frameCount = 0;
		}
	}

	/// <summary>
	/// Function to reset the timing data.
	/// </summary>
	public void Reset()
	{
		_timer.Reset();
		_lastFPSFrameTime = 0.0;
		_averageFPS = 0.0; 
		_highestFPS = 0.0;
		_lowestFPS = 0.0;
		_currentFPS = 0.0;
		_frameCount = 0;
		_lastFrameTime = 0.0;
		_currentFrameTime = 0.0;
		_frameDrawTime = 0.0;
	}

	/// <summary>
	/// Function to end timing routine.
	/// </summary>
	public void Refresh()
	{
		_lastFrameTime = _currentFrameTime;
		_currentFrameTime = _timer.Milliseconds;
		_frameDrawTime = _currentFrameTime - _lastFrameTime;
		GetFPS();
	}
	#endregion

	#region Constructor.
	/// <summary>
	/// Constructor.
	/// </summary>
	internal TimingData()
	{
		_timer = Gorgon.Timers.SystemTimer("@Gorgon_Timer");
		Reset();			
	}
	#endregion
}

Where _timer is an instance of the aforementioned Timer class.
Advertisement
I just ripped this from an old project of mine, but it uses the high precision timer (assuming it exists). If you wanted maximum compatibility you'd want to test for existence of it first, and also test for multiple processors as the timer behaves differently in that case.

using System.Runtime.InteropServices;   /// <summary>   /// High performance API timer    /// (may not be supported on older machines)   /// </summary>   public class Timey {      [DllImport("Kernel32.dll")]      private static extern bool QueryPerformanceCounter(out long lpPerformanceCount);      [DllImport("Kernel32.dll")]      private static extern bool QueryPerformanceFrequency(out long lpFrequency);      private long start = 0;      private long time = 0;      private long freq;      /// <summary>      /// Initializes the timer      /// </summary>      public Timey()  {         QueryPerformanceFrequency(out freq);         QueryPerformanceCounter(out start);      }      /// <summary>      /// Resets the timer      /// </summary>      public void Reset()  {         QueryPerformanceCounter(out start);      }      /// <summary>      /// Duration since the creation of the timer or since      /// the last reset in seconds      /// </summary>      public double Duration  {         get  {            QueryPerformanceCounter(out time);            return (double) (time - start) / (double) freq;         }      }      /// <summary>      /// Current tick count      /// </summary>      public double Ticks {         get {            QueryPerformanceCounter(out time);            return (double) time / (double) freq;         }      }   }
Depending on the native resolution of your monitor, it could be slower to full-screen as it would have to convert your (say) 800×600 image into a 1024×768 pixel array. This is most likely true for flat-panel monitors.

Also, dumb question, but is your window smaller than the size of your full-screen render?
I had the same issues a while ago and made a thread about it. The thing is, I couldn't use stopwatch because I'm targeting .NET 1.1, so I had to look elsewhere. Nagromo came up with an awesome solution, which uses the QueryPerformanceCounter, and if it's not available on the target machine, it uses Environment.TickCount as an alternative.

It's an excellent solution and has worked very nicely.
Rob Loach [Website] [Projects] [Contact]
Quote:Original post by Bob Janova
Depending on the native resolution of your monitor, it could be slower to full-screen as it would have to convert your (say) 800×600 image into a 1024×768 pixel array. This is most likely true for flat-panel monitors.

Also, dumb question, but is your window smaller than the size of your full-screen render?


It's possible, and that'd explain the slight decrease in speed when I have the vsync off. But I'm not sure that it explains the frame rate cutting in half with the vsync on.

My client area of the window is the same size as my fullscreen resolution.

I've implemented the QueryPerformance counter stuff in place of the stopwatch code:

/// <summary>/// Object to handle timing operations./// </summary>public class Timer 	: NamedObject {	#region Variables.	private long _startTime;			// Starting timer time.	private bool _useHighResolution;	// Flag to indicate that we're using a high resolution timer.	private long _frequency;			// Frequency of the timer.	private double _milliseconds;		// Milliseconds.	private long _ticks;				// Clock ticks.	private long _lastTicks;			// Last tick count.	private long _startingTick;			// Starting clock tick.	private long _adjustStartTick;		// Adjustment starting tick.	#endregion	#region Properties.	/// <summary>	/// Property to get the number of milliseconds elapsed since the timer was started.	/// </summary>	public double Milliseconds	{		get		{			GetTime();			return _milliseconds;		}	}	/// <summary>	/// Property to get the number of microseconds elapsed since the timer was started.	/// </summary>	public double Microseconds	{		get		{			return Milliseconds * 1000;		}	}	/// <summary>	/// Property to return the number of ticks since the timer was started.	/// </summary>	public long Ticks	{		get		{			GetTime();			return _ticks;		}	}	/// <summary>	/// Property to set or return whether to use the high resolution timer or not.	/// </summary>	public bool HighResolutionTimer	{		get		{			return _useHighResolution;		}		set		{			_useHighResolution = value;			Reset();		}	}	#endregion	#region Methods.	/// <summary>	/// Function to start the timing process.	/// </summary>	private void GetTime()	{		long currentTime = 0;		// Current time.		if (_useHighResolution)		{			Win32API.QueryPerformanceCounter(ref currentTime);			_ticks = currentTime - _startTime;			_milliseconds = ((double)_ticks/(double)_frequency) * 1000;			// The QueryPerformance counter drifts on some motherboards.			// See Microsoft KB: Q274323 for the explanation.			ulong check = (ulong)Environment.TickCount - (ulong)_adjustStartTick;	// Get tick count.			long msDrift = (long)(check - _milliseconds);							// Get any millisecond drifts.			// If we're out by 100 milliseconds either way, then adjust the time.			if ((msDrift < -100) || (msDrift > 100))			{				// Get adjustment amount.				long adjust = Math.Min(msDrift * _frequency / 1000, _ticks - _lastTicks);				_startingTick += adjust;				_ticks -= adjust;				// Recalcuate the timing.				_milliseconds = ((double)_ticks / (double)_frequency) * 1000;			}			_lastTicks = _ticks;		}		else		{			currentTime = Win32API.timeGetTime();			_milliseconds = currentTime - _startTime;			_ticks = Environment.TickCount - _startingTick;		}	}	/// <summary>	/// Function to reset the timer.	/// </summary>	public void Reset()	{		_milliseconds = 0;		_ticks = 0;		_lastTicks = 0;		_adjustStartTick = _startingTick = Environment.TickCount;		// Determine which type of timer to use.		if (_useHighResolution)		{			// If this fails, then drop to the lower precision timer.			if (!Win32API.QueryPerformanceCounter(ref _startTime))			{				_startTime = Win32API.timeGetTime();				_useHighResolution = false;			}		}		else		{			_startTime = Win32API.timeGetTime();			_useHighResolution = false;		}	}	/// <summary>	/// Function to convert the desired frames per second to milliseconds.	/// </summary>	/// <param name="FPS">Desired frames per second.</param>	/// <returns>Frames per second in milliseconds.</returns>	public static double FPSToMilliseconds(double FPS)	{		if (FPS > 0)			return (1000/(FPS + 3));		else			return 0;	}	/// <summary>	/// Function to convert the desired frames per second to microseconds.	/// </summary>	/// <param name="FPS">Desired frames per second.</param>	/// <returns>Frames per second in microseconds.</returns>	public static double FPSToMicroseconds(double FPS)	{		if (FPS > 0)			return (1000000/(FPS + 3));		else			return 0;	}	#endregion	#region Constructors/Destructors.	/// <summary>	/// Constructor.	/// </summary>	/// <param name="timerName">Name of this timer.</param>	internal Timer(string timerName) 		: base(timerName)	{		_startTime = 0;		_frequency = 0;		_useHighResolution = false;		_adjustStartTick = _startingTick = Environment.TickCount;		_lastTicks = 0;		if (Win32API.QueryPerformanceFrequency(ref _frequency))		{			if (Win32API.QueryPerformanceCounter(ref _startTime))				_useHighResolution = true;		}		// Fall back on the low resolution timer if no high resolution one can be found.		if (!_useHighResolution)			_startTime = Win32API.timeGetTime();					}	#endregion}


Unfortunately, I'm still getting the same speed decrease in full screen. I tried bringing down my sprite count from 6000 by 1000 sprites at a time. The framerate went back to 60 FPS (vsync limited) after I got to 3000 sprites (and 3500 sprites as well). However in windowed mode it went from ~50 FPS (with a delta time of ~19 ms) to 80 FPS (with a delta time of ~12 ms). It's almost like the fullscreen adjusted to nearest multiple of a vsync. I tested this theory of course by doubling everything and bringing the FPS down to 30-40 FPS in windowed mode, and it went to 20 FPS in full screen. This is very confusing. I don't know if it's the timers now, I tried this with both the QueryPerformanceCounter and timeGetTime functions and both returned roughly the same intervals. Could it be something driver related? Monitor related (I have an LCD, 8ms refresh)? Or am I high on mushrooms and just hallucinating?

Again, if I turn vSync off, I get roughly the same speed (minus about 4-8 FPS) (see edit below). You'd think if this were vSync limited that if I got 50 FPS in windowed mode, I should get 50 FPS in fullscreen, but no more than 60 FPS if I'm @ 60 Hz, which I am, but on an LCD it's not supposed to matter (unless I'm not understanding the presentation intervals?)

I dread trying this on my work machine, cause last time I had timing issues like this my work machine couldn't smoothly interpolate the movement of the objects on the screen, thus giving a jerky performance.


Edit:

After running it again, I found that it's running a little faster in full screen than windowed, WITHOUT vsync. Still having the same issues with vsync being enabled though. :(


[Edited by - Tape_Worm on July 22, 2006 9:38:54 PM]
Quote:Original post by Bob Janova
Depending on the native resolution of your monitor, it could be slower to full-screen as it would have to convert your (say) 800×600 image into a 1024×768 pixel array. This is most likely true for flat-panel monitors.

Also, dumb question, but is your window smaller than the size of your full-screen render?


The monitor's upscaling hardware does this for you.
Quote:
<*@*.*> to DIRECTXDEV
More options 8:30 pm (39 minutes ago)
Hi,

If vsync is on and your rendering takes > 1/60 seconds then you will end
up "skipping" refreshes. e.g.

Render-------->|Render-------->|Render-------->|....
.......x.......^.......x.......^........x......^

In the (dodgy) diagram above the "x"'s are the refreshes you are missing
and the "^"'s are the refreshes you are hitting. Thus actual FPS
rendered is only 30. (This is assuming a constant render time).

Not too much you can do other than optimise your rendering code as much
as possible!

HTH,


This seems to explain the situation. Do you all think this could be the issue? Does it make sense?
Just an FYI - the new Stopwatch class in .Net 2.0 uses the high precision/QueryPerfCounter if it exists (Stopwatch has a property that you can check the granularity of the timer which will tell you what it is using). So unless you are targetting .Net 1.1 there really isn't any reason to be doing the interop stuff any more.
ZMan
For those interested and another variation, I did some testing with a simple timer class I knocked up for testing database operations with autocad, I was directed to the QueryPerfCounter and did the following test both while debugging and in release mode, the results were pretty close!.

using System;using System.ComponentModel;using System.Runtime.InteropServices;namespace TimerTests{	/// <summary>	/// Summary description for Class1.	/// </summary>	class Class1	{		/// <summary>		/// The main entry point for the application.		/// </summary>		[STAThread]		static void Main(string[] args)		{			//			// TODO: Add code to start application here			//			TestTimers();		}		public static void TestTimers()		{			FunctionTimer timer = new FunctionTimer();			QueryPerfCounter qpc = new QueryPerfCounter();			//jit the timers:			qpc.Start();			timer.Start();			qpc.Stop();			timer.Stop();			Console.WriteLine("Started Timer:");			// Time the overall test duration:			DateTime dtStartTime = DateTime.Now;			int i = 0;			int j = 1;			int k = 2;			int iterations = 5;			for(int a = 0; a < iterations; a++)			{				System.Threading.Thread.Sleep(1000);			}			qpc.Stop();			timer.Stop();						double result = qpc.Duration(iterations);			// Show the average time per iteration results			Console.WriteLine("Iterations: {0}", iterations);			Console.WriteLine("Average time per iteration: ");			Console.WriteLine(result/1000000000 + " seconds");			Console.WriteLine(result/1000000 + " milliseconds");			Console.WriteLine(result + " nanoseconds");			// Show the overall test duration results			DateTime dtEndTime = DateTime.Now;			Double duration = ((TimeSpan)(dtEndTime-dtStartTime)).TotalMilliseconds;			Console.WriteLine();			Console.WriteLine("Duration of test run: ");			Console.WriteLine(duration/1000 + " seconds");			Console.WriteLine(duration + " milliseconds");			Console.WriteLine("QPC's Timer result: {0}",(result/1000000000)*iterations + " seconds");			Console.WriteLine("MickD's FunctionTimer result: {0}",timer.ElapsedTime);				Console.ReadLine();		}		public class QueryPerfCounter		{			[DllImport("KERNEL32")]			private static extern bool QueryPerformanceCounter(				out long lpPerformanceCount);			[DllImport("Kernel32.dll")]			private static extern bool QueryPerformanceFrequency(out long lpFrequency);			private long start;			private long stop;			private long frequency;			Decimal multiplier = new Decimal(1.0e9);			public QueryPerfCounter()			{				if (QueryPerformanceFrequency(out frequency) == false)				{					// Frequency not supported					throw new Win32Exception();				}			}			public void Start()			{				QueryPerformanceCounter(out start);			}			public void Stop()			{				QueryPerformanceCounter(out stop);			}			public double Duration(int iterations)			{				return ((((double)(stop - start)* (double) multiplier) / (double) frequency)/iterations);			}		}		/// <summary>		/// //Class to time the execution of functions for testing and comparisons		/// </summary>		public class FunctionTimer		{			public FunctionTimer()			{				//				// TODO: Add constructor logic here				//			}			private double _startTicks;			private double _endTicks;			private double _totalTime;			public void Start()			{				_startTicks = Convert.ToDouble(DateTime.Now.Ticks);			}			public void Stop()			{				_endTicks = Convert.ToDouble(DateTime.Now.Ticks);				_totalTime = (_endTicks - _startTicks)/10000000;			}			public string ElapsedTime			{				get				{					return "Total Elapsed Time = " + _totalTime.ToString() + " seconds\n";				}			}		}	}}


The results -

Without debugging:
Quote:
Started Timer:
Iterations: 5
Average time per iteration:
0.998617924903864 seconds
998.617924903864 milliseconds
998617924.903864 nanoseconds

Duration of test run:
5 seconds
5000 milliseconds
QPC's Timer result: 4.99308962451932 seconds
MickD's FunctionTimer result: Total Elapsed Time = 5 seconds


While debugging:
Quote:
Started Timer:
Iterations: 5
Average time per iteration:
0.994149200526882 seconds
994.149200526883 milliseconds
994149200.526883 nanoseconds

Duration of test run:
5 seconds
5000 milliseconds
QPC's Timer result: 4.97074600263441 seconds
MickD's FunctionTimer result: Total Elapsed Time = 5.015616 seconds

This topic is closed to new replies.

Advertisement