The NeL framework provides a number of tools for timing and profiling NeL-based applications and games. The most commonly used tool is the hierarchical timer which allows you to see overall execution of code as well as atomic breakdowns of scopes or sections of code within the hierarchy. There are many ways to use this and customize it to your specific needs. NeL also provides a much simpler tool called a stop watch, which meters the execution time between two points in code execution. Both of these options will be covered in this section.

CTime contains only static methods to get the time, in second since Unix epoch, in millisecond or using processor ticks. Check time_nl.h or Doxygen for more information.

Only works on Unices. Allows accurate timing measures for both cpu and process (at least at OS timing accuracy). Check cpu_time_stat.h or Doxygen for more information.

NeL provides a handful of very useful timer tools for troubleshooting and profiling the performance of NeL-based applications. The most commonly used tool is the hierarchical timer. The hierarchical timer is comprised largely if the CHTimer class and a handful of utility macros: H_AUTO, H_AUTO_USE, H_AUTO_DECL, H_BEFORE and H_AFTER. The hierarchical timer gives you the ability to gather time statistics for an entire function or a block of code and provides some methods for managing the data the timer collects as well as reporting this data someplace useful (typically the log.)

In most scenarios you will use H_AUTO, H_BEFORE and H_AFTER so we'll describe how to use these macros first. H_AUTO is the most often used macro in this toolkit. One thing you'll also notice in the code is that the macros have a block of text. This block of text identifies the "scope" that we're benchmarking. This will be explained in more depth later on. Here is an example of these three macros in use:

void CFoo::usingHAuto()
{
	H_AUTO( SAMPLE_usingHAuto );
	CFooBar::getSingleton().calculateSomething();
}

void CFoo::usingHBeforeAfter()
{
 	// We'll do some unimportant code here.
	int i;
	i++;
	// Now we'll specify the important part of code to benchmark.

	H_BEFORE( SAMPLE_usingtHBeforeAfter );
	CFooBar::getSingleton().calculateSomething();
	H_AFTER( SAMPLE_usingHBeforeAfter );
}

So you can see that in the method 'usingHAuto' we simply used the H_AUTO macro. This creates an instance of the timer object within the scope of the method and when the method exits and the object is destroyed it will report back to the CHTimer class. This over simplifies the process but is essential enough to describe how to use the methods for timing and benchmarking. In the method 'usingHBeforeAfter' you can see that rather than relying on scope to determine the timing interval we specify the block of code we want to benchmark. This is handy if you have a specific block of code that is plaguing you and you don't want the other activities in that method or tree of methods to contaminate your timing benchmarks.

H_BEFORE/AFTER obviously have an application that H_AUTO cannot provide - benchmarking a specific block of code regardless of scope. But there's one large benefit that H_AUTO has over its before/after counterpart - you never have to remember to provide the H_AFTER macro. Take this scenario for example:

// HUGE MESS
void CFoo::exampleOne()
{
 	// We'll do some unimportant code here.
	int i;
	i++;
	// Now we'll specify the important part of code to benchmark.

	H_BEFORE(SAMPLE_usingtHBeforeAfter);
	CFooBar::getSingleton().calculateSomething();
	if(foo == 1)
		return;
	H_AFTER(SAMPLE_usingHBeforeAfter);
}

// Correct way to do this
void CFoo::exampleOne()
{
 	// We'll do some unimportant code here.
	int i;
	i++;
	// Now we'll specify the important part of code to benchmark.

	H_BEFORE(SAMPLE_usingtHBeforeAfter);
	CFooBar::getSingleton().calculateSomething();
	if(foo == 1) {
 		H_AFTER(SAMPLE_usingHBeforeAfter);
		return;
	}
	H_AFTER(SAMPLE_usingHBeforeAfter);
}

You can see in the above example that you need to make sure to call H_AFTER before every single exit point in your method or else you could (and will) end up with a huge mess in your benchmarking.

Finally there's the H_AUTO_DECL and H_AUTO_USE macros. These very important macros are used when you want to lump multiple blocks of calls together without having to rely on the strategic placement of H_AUTO calls whenever these blocks of code are called. Here's a quick example of how these blocks of code can be lumped together:

H_AUTO_DECL(SAMPLE_allCFooCalls);

void CFoo::buildSomething()
{
	H_AUTO_USE(SAMPLE_allCFooCalls);
	CFooBar::getSingleton().calculateSomething();
}

void CFoo::calculateSomething()
{
	H_AUTO_USE(SAMPLE_allCFooCalls);
	CFooBar::getSingleton().calculateSomething();
}

These macros alone will not produce the benchmarking and timing results you require. Ultimately you will need to start using the CHTimer class. This powerful class provides you a variety of useful methods to manage this process. First you will need to know how to start, stop, reset and display the benchmarking and timing statistics. Use the following code as an example:

NLMISC::CHTimer::startBench();
// Now lets do some stuff.
CFoo::buildSomething();
CFoo::calculateSomething();
Scene->render();
// Now we're done, lets finish up the benchmarking.
NLMISC::CHTimer::stopBench();
// Finally output the results to the InfoLog
NLMISC::CHTimer::displaySummary();

That is the essentials of using the hierarchical timer classes. Please refer to the API documentation for some more information on the CHTimer class. There are several methods on that class to display the benchmarking and timing data in meaningful ways. It is also important to note that these macros perform no logic when NeL is compiled in RELEASE mode.

Allows to accurately measure performance of routines, and displays results hierarchically. It's the best way to know what is slow in your program. It's really easy to use and give you good measures.

• Create a function to activate/deactivate the bench.

void switchBench()
{
    static bool benching = false;
    benching = !benching;
    if(benching)
    {
        nlinfo("Start of benchmark");
        CHTimer::startBench();
    }
    else
    {
        nlinfo("End of benchmark");
        CHTimer::endBench();
        CHTimer::display(InfoLog, CHTimer::TotalTime, true, true);
        CHTimer::displayHierarchicalByExecutionPathSorted(InfoLog, CHTimer::TotalTime, true, 64, 3);
    }
}

• Then add H_BEFORE and H_AFTER around each code block you want to bench.

H_BEFORE( nameofbenchinlist );
// ... your code to bench ...
H_AFTER( nameofbenchinlist );

• If you use H_AUTO, it'll bench the current scope.

void func()
{
  H_AUTO( func ); // it'll bench the func() scope
  // ...some code...
  if(i<j)
  {
    H_AUTO( func_less ); // it'll bench the if() scope
    // ...some code...
  }
  // ...some code...
}

The stop watch class is used for performance measurement and statistics. It allows you to measure the time elapsed with controls like start, stop, pause, and resume. It gives you more flexibility to measure specific metrics at the loss of the automation and reporting abilities of the hierarchal timer. It's very handy for troubleshooting where the hierarchal timer is useful for profiling and overall performance monitoring. The stop watch controls are fairly basic, see this example for a common scenario:

void foo()
{
	// create the stop watch.
	NLMISC::CStopWatch stopWatch;
	// start the timer.
	stopWatch.start();
	// ... process some code here.
	// stop the timer.
	stopWatch.stop();
	// and output the results.
	nlinfo("Time Elapsed in Milliseconds: %d", stopWatch.getDuration());
}

The stop watch system also gives you a handful of other methods to control how you accumulate time. Above we saw the use of start and stop and how to use the getDuration method to display the amount of time that elapsed between the start and stop call. Here we'll see how you can pause execution to skip a bit of code and resume accumulating time later. Also we'll see how you can artificially add time to the stop watch using the addTime method which can be useful if you're skipping a block of logic and want to assume that it took a predetermined amount of time. Finally you can start and stop a stop watch several times and output the average time that elapsed over each of the calls.

void foo()
{
	// create the stop watch.
	NLMISC::CStopWatch stopWatch;
	
	// start the timer.
	stopWatch.start();
	
	// ... process some code here.
	
	// pause the timer..
	stopWatch.pause();
	
	// ... process some code that shouldn't affect your dynamically.
	// add the time we want to assume the above code took.
	stopWatch.addTime( /* time here is in ticks... */ 1500 );
	
	// resume the timer.
	stopWatch.resume();
	
	// ... process some code here.
	
	// stop the timer.
	stopWatch.stop();
	
	// start the timer.
	stopWatch.start();
	// ... process the same code here.
	// stop the timer.
	stopWatch.stop();
	
	// and output the results.
	nlinfo("Time Elapsed in Milliseconds: %d", stopWatch.getDuration());
	nlinfo("Average Time of Both start/stop calls in Milliseconds: %d", stopWatch.getAverageDuration());
}

In the above examples we saw two ways to display the stopwatch timing information: getDuration and getAverageDuration. The method getDuration will only provide you with time information in milliseconds for the period after the last call to stop. That means if you call start and stop several times - you will only see the last, most recent call to stop. The other handy display method, getAverageDuration, display the average elapsed time for all calls to start and stop.

Stopwatch class used for performance measurements and statistics. It allows you to measure the time elapsed with controls like ''start'', ''stop'', ''pause'', and ''resume''.
Check stop_watch.h or Doxygen for more information.

• Simple Stop Watch usage is straight forward:

void foo()
{
    // create the stop watch.
    NLMISC::CStopWatch stopWatch;
    // start the timer.
    stopWatch.start();
    // ... process some code here.
    // stop the timer.
    stopWatch.stop();
    // and output the results.
    nlinfo("Time Elapsed in Milliseconds: %d", stopWatch.getDuration());
}

• Some slightly more advanced options are:

void foo()
{
    // create the stop watch.
    NLMISC::CStopWatch stopWatch;

    // start the timer.
    stopWatch.start();

    // ... process some code here.

    // pause the timer..
    stopWatch.pause();

    // ... process some code that shouldn't affect your dynamically.
    // add the time we want to assume the above code took.
    stopWatch.addTime( /* time here is in ticks... */ 1500 );

    // resume the timer.
    stopWatch.resume();

    // ... process some code here.

    // stop the timer.
    stopWatch.stop();

    // start the timer.
    stopWatch.start();
    // ... process the same code here.
    // stop the timer.
    stopWatch.stop();

    // and output the results.
    nlinfo("Time Elapsed in Milliseconds: %d", stopWatch.getDuration());
    nlinfo("Average Time of Both start/stop calls in Milliseconds: %d", stopWatch.getAverageDuration());
}

• https://web.archive.org/web/20100511090441/http://www.opennel.org/confluence/display/~mattr/MtrNelManualNotes
• https://web.archive.org/web/20080905203307/http://www.opennel.org/confluence/display/NEL/NeLTime