AGS script global performance

Started by Monsieur OUXX, Sun 13/01/2008 02:32:54

Previous topic - Next topic

Monsieur OUXX

Haha, I bet I scared you with this title : "AGS script peformance". I bet that you are convinced that I am going to complain that it is too slow and that it suXxZ. Not at all!

Here are some tests that I performed with a tool described below to give a quantitative comparison of several coding solutions using the AGS script. It will allow script users to know how CPU-consuming is one thing compared to another.

IMPORTANT NOTE

These tests are only for scripts that need a very high performance;
Pay attention to the results interpretation below:
- Only if you are making a script that requires the execution of a huge and complex code that will only be used as the lowest layer of something much more simple and user-friendly.
- Only if you are going to have it perform a lot of calculation.
- Only if speed is a critical factor.

NEVER FORGET that a CLEAN CODE is much more important than a fast code. Always use function calls to avoid redundant code, always use as many local functions as necessary, always use the appropriate data type.


RESULTS

Using AGS 2.72 :
Code: ags

          --------------------------------------------------------------------------
         |    local variable   |   global variable   |  member of a global object |
-----------------------------------------------------------------------------------
int      |         58          |         57          |             56             |
-----------------------------------------------------------------------------------
String   |        282          |        253          |            252             |
-----------------------------------------------------------------------------------

         ---------------------------------------------
         |    inside loop      |   outside loop      |
------------------------------------------------------
int      |         82          |         76          |
------------------------------------------------------
String   |        263          |        252          |
------------------------------------------------------

                 ------------------------------------------------------------------------------------------------------
                 | int | String (litteral, length 0) | String (litteral, length 100) |  String (variable, length 100) |  
-----------------------------------------------------------------------------------------------------------------------
affectation time | 74  |              254            |            303                |             172                |
-----------------------------------------------------------------------------------------------------------------------

         ----------------------- 
         |      write time     |
--------------------------------
int      |         76          |
--------------------------------
float    |         76          |
--------------------------------
bool     |         76          |
--------------------------------


         ----------------------- 
         |        time         |
--------------------------------
if..then |         84          |
--------------------------------
if..else |         76          |
--------------------------------


         ----------------------- 
         |        time         |
--------------------------------
0 param  |         93          |
--------------------------------
1 param  |        107          |
--------------------------------
2 param  |        117          |
--------------------------------
3 param  |        128          |
--------------------------------
4 param  |        139          |
--------------------------------

         ----------------------- 
         |        time         |
--------------------------------
inline   |         61          |
--------------------------------
with func|         117         |
--------------------------------



RESULTS INTERPRETATION

Here is what can be said from the results above :

RESULTS THAT HAVE NO IMPACT
- internal structure of the script doesn't make it slower to access a global variable than a local variable.
- using objects is as fast as using primitive-types variables.
- ints, floats and bool have the same read/write speed. Other tests should be performed on calculation using floats vs. ints

RESULTS THAT CAN HELP GAINING SPEED
- Strings are 2 to 3 times slower than ints.
- Strings are almost 2 times faster when using variables than litterals.

- declaring a variable inside a loop is up to 10% slower than declaring it once at the beginning of the function
- putting instructions in the "then" rather than in the "else" makes the code 10% slower. It's wether because a condition is eaiser to invalidate than to validate, or because AGS virtual machine performs a "goto" to handle the THEN (vs. no jump for the ELSE)

- the more parameters you put, the slower is the function. See results above to see how much slower it is.
- using a function instead of a simple instruction is +100% slower.


 

Monsieur OUXX

Here is the code for the tests :

Code: ags

// Main script for module 'PerformanceCommands'

DateTime *chronoStartTime;
int nbLoopsTest = 100000000;


//////////////////////////////////////////////////////////////////////



void resetChrono() {
	AGSH_Console.DebugMsg("Starting chronometer");
  chronoStartTime = DateTime.Now;
}


//////////////////////////////////////////////////////////////////////



int getChrono() {
  DateTime *chronoStopTime = DateTime.Now;
	int result = chronoStopTime.RawTime - chronoStartTime.RawTime;
	Wait(1); //so that the output is not only flushed in log but also on screen
	return result;
}


//////////////////////////////////////////////////////////////////////



int globalVariable_int;
String globalVariable_String;
struct TestObject {
  int objectVariable_int;
  String objectVariable_String;
};
TestObject testObject;


//////////////////////////////////////////////////////////////////////


void noloopcheck testGlobalVariables_int() {


	AGSH_Console.DebugMsg("TESTS ON GLOBAL/LOCAL VARIABLES (int)");


	int result=0;
	
	int localVariable;
	
	//loop that uses a local variable
	resetChrono();
	localVariable = 0;
	while (localVariable < nbLoopsTest) {
			localVariable++;
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for local variable access = %ds (%d iterations loop)", result, nbLoopsTest));

	//loop that uses global variable
	resetChrono();
	globalVariable_int = 0;
	while (globalVariable_int < nbLoopsTest) {
			globalVariable_int++;
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for global variable access = %ds (%d iterations loop)", result, nbLoopsTest));

	//loop that uses a member of a global object
	resetChrono();
	testObject.objectVariable_int = 0;
	while (testObject.objectVariable_int < nbLoopsTest) {
			testObject.objectVariable_int++;
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for global variable access = %ds (%d iterations loop)", result, nbLoopsTest));

}



//////////////////////////////////////////////////////////////////////



void noloopcheck testGlobalVariables_String() {


	AGSH_Console.DebugMsg("TESTS ON GLOBAL/LOCAL VARIABLES (String)");

	int result=0;

	
	String localVariable;
	
	//loop that uses a local variable
	resetChrono();
	int counter = 0;
	while (counter < nbLoopsTest) {
	  localVariable="";
		counter++;
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for local variable access = %ds (%d iterations loop)", result, nbLoopsTest));

	//loop that uses global variable
	resetChrono();
	counter = 0;
	while (counter < nbLoopsTest) {
	  globalVariable_String="";
		counter++;
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for global variable access = %ds (%d iterations loop)", result, nbLoopsTest));

	//loop that uses a member of a global object
	resetChrono();
	counter = 0;
	while (counter < nbLoopsTest) {
	  testObject.objectVariable_String="";
		counter++;
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for global variable access = %ds (%d iterations loop)", result, nbLoopsTest));

}


//////////////////////////////////////////////////////////////////////



void noloopcheck testDeclarations_int() {

	AGSH_Console.DebugMsg("TESTS ON DECLARATIONS INSIDE OR OUTSIDE LOOPS (int)");

	int result=0;
	
	int counter;
	//loop that uses a local variable with declaration inside the loop
	resetChrono();
	counter = 0;
	while (counter < nbLoopsTest) {
			int localVariable=counter;
			counter++;
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for local variable with declaration in loop = %ds (%d iterations loop)", result, nbLoopsTest));

	//loop that uses global variable with one unique declaration
	resetChrono();
	counter = 0;
	int localVariable2;
	while (counter < nbLoopsTest) {
			localVariable2=counter;
			counter++;
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for unique variable declaration = %ds (%d iterations loop)", result, nbLoopsTest));
	
}


//////////////////////////////////////////////////////////////////////



void noloopcheck testDeclarations_String() {

	AGSH_Console.DebugMsg("TESTS ON DECLARATIONS INSIDE OR OUTSIDE LOOPS (String)");

	int result=0;
	
	int counter;
	//loop that uses a local variable with declaration inside the loop
	resetChrono();
	counter = 0;
	while (counter < nbLoopsTest) {
			String localVariable="";
			counter++;
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for local variable with declaration in loop = %ds (%d iterations loop)", result, nbLoopsTest));

	//loop that uses global variable with one unique declaration
	resetChrono();
	counter = 0;
	String localVariable2;
	while (counter < nbLoopsTest) {
			localVariable2="";
			counter++;
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for unique variable declaration = %ds (%d iterations loop)", result, nbLoopsTest));
	
}



//////////////////////////////////////////////////////////////////////



void noloopcheck testStringsCopy() {
	
	AGSH_Console.DebugMsg("TESTS ON String");

	int result=0;
	int counter;
	//loop that declares ints (reference)
	resetChrono();
	counter = 0;
	int localVariableInt;
	while (counter < nbLoopsTest) {
			localVariableInt=666;//arbitrary value
			counter++;
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for a loop that declares ints = %ds (%d iterations loop)", result, nbLoopsTest));


	//loop that copies a litteral String of length 0
	resetChrono();
	counter = 0;
	String localVariableString;
	while (counter < nbLoopsTest) {
			localVariableString="";
			counter++;
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for a loop that copies a litteral String of length 0 = %ds (%d iterations loop)", result, nbLoopsTest));


	//loop that copies a litteral String of length 100
	resetChrono();
	counter = 0;
	while (counter < nbLoopsTest) {
			localVariableString="0123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789";
			counter++;
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for a loop that copies a litteral String of length 100 = %ds (%d iterations loop)", result, nbLoopsTest));


	//loop that copies a variable String of length 100
	resetChrono();
	counter = 0;
	String localVariableString2;
	localVariableString="0123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789";
	while (counter < nbLoopsTest) {
	  localVariableString2 = localVariableString;
		counter++;
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for a loop that copies a variable String of length 100 = %ds (%d iterations loop)", result, nbLoopsTest));
 
}



//////////////////////////////////////////////////////////////////////



void noloopcheck testReadWrite() {

	AGSH_Console.DebugMsg("READ/WRITE TESTS FOR int,float,bool");
  
	int result=0;
	int counter;

	// int /////////////////
	
	resetChrono();
	counter = 0;
	int localVariable_int;
	while (counter < nbLoopsTest) {
			localVariable_int=666;//arbitrary value
			counter++;
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for a loop that writes ints = %ds (%d iterations loop)", result, nbLoopsTest));

	// float /////////////////

	resetChrono();
	counter = 0;
	float localVariable_float;
	while (counter < nbLoopsTest) {
			localVariable_float=666.0;//arbitrary value
			counter++;
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for a loop that writes floats = %ds (%d iterations loop)", result, nbLoopsTest));

	// bool /////////////////

	resetChrono();
	counter = 0;
	int localVariable_bool;
	while (counter < nbLoopsTest) {
			localVariable_bool=true;//arbitrary value
			counter++;
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for a loop that writes bools = %ds (%d iterations loop)", result, nbLoopsTest));
  
}

//////////////////////////////////////////////////////////////////////



void noloopcheck testConditions() {

	AGSH_Console.DebugMsg("TESTS FOR CONDITIONS (if/goto)");
  
	int result=0;
	int result2=0;
	int counter;
	bool condition;

	resetChrono();
	counter = 0;
	condition = true;
	while (counter < nbLoopsTest) {
	  if(condition) {
			counter++;
		} else {
		  //nothing
		}
	}
	result = getChrono();
	
	resetChrono();
	counter = 0;
	condition = false;
	while (counter < nbLoopsTest) {
	  if(condition) {
	    //nothing
		} else {
			counter++;
		}
	}
	result2 = getChrono();

	AGSH_Console.DebugMsg(String.Format("Result for a loop that tests a condition : THEN=%ds, ELSE=%ds (%d iterations loop)", result,result2,nbLoopsTest));
}

//////////////////////////////////////////////////////////////////////

void function0parameter() {
		return;
}
void function1parameter(int p1) {
		return;
}
void function2parameter(int p1, int p2) {
		return;
}
void function3parameter(int p1, int p2, int p3) {
		return;
}
void function4parameter(int p1, int p2, int p3, int p4) {
		return;
}

void noloopcheck testParameters() {

	AGSH_Console.DebugMsg("TESTS FOR FUNCTIONS WITH PARAMETERS");
  
	int result=0;
	int counter;

	// 0 parameters //////////////
	resetChrono();
	counter = 0;
	while (counter < nbLoopsTest) {
	  function0parameter();
		counter++;
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for function with 0 parameters = %ds (%d iterations loop)", result, nbLoopsTest));
	
	// 1 parameters //////////////
	resetChrono();
	counter = 0;
	while (counter < nbLoopsTest) {
	  function1parameter(globalVariable_int);
		counter++;
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for function with 1 parameters = %ds (%d iterations loop)", result, nbLoopsTest));

	// 2 parameters //////////////
	resetChrono();
	counter = 0;
	while (counter < nbLoopsTest) {
	  function2parameter(globalVariable_int,globalVariable_int);
		counter++;
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for function with 2 parameters = %ds (%d iterations loop)", result, nbLoopsTest));

	// 3 parameters //////////////
	resetChrono();
	counter = 0;
	while (counter < nbLoopsTest) {
	  function3parameter(globalVariable_int,globalVariable_int,globalVariable_int);
		counter++;
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for function with 3 parameters = %ds (%d iterations loop)", result, nbLoopsTest));

	// 4 parameters //////////////
	resetChrono();
	counter = 0;
	while (counter < nbLoopsTest) {
	  function4parameter(globalVariable_int,globalVariable_int,globalVariable_int,globalVariable_int);
		counter++;
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for function with 4 parameters = %ds (%d iterations loop)", result, nbLoopsTest));

}

//////////////////////////////////////////////////////////////////////

int simpleFunction(int i) {
	return (i+1);
}

void noloopcheck testFunctionCall() {

	AGSH_Console.DebugMsg("TESTS FOR FUNCTION CALLS");
  
	int result=0;
	int counter;

	resetChrono();
	counter = 0;
	while (counter < nbLoopsTest) {
		counter++;
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for simple operation performed inline = %ds (%d iterations loop)", result, nbLoopsTest));
	
	resetChrono();
	counter = 0;
	while (counter < nbLoopsTest) {
		counter=simpleFunction(counter);
	}
	result = getChrono();
	AGSH_Console.DebugMsg(String.Format("Result for simple operation performed using a function call = %ds (%d iterations loop)", result, nbLoopsTest));

}

//////////////////////////////////////////////////////////////////////


void performTests() {

	displayWelcomeMessage();
  
  testChrono();
  
  testGlobalVariables_int();
  testGlobalVariables_String();

  testDeclarations_int();
  testDeclarations_String();
  
  testStringsCopy();
  testReadWrite();
  
	testConditions();
	testParameters();
	testFunctionCall();
	
  //testPipo();
  
	displayExitMessage();
  
}




 

Monsieur OUXX

Here is the log produed when running the program above :

Code: ags

Console is now defined.
==============================
AGS script performances tester
==============================

About to test chronometer(100 loops)...
Starting chronometer
elapsed time for 100 loops: 2s
TESTS ON GLOBAL/LOCAL VARIABLES (int)
Starting chronometer
Result for local variable access = 58s (100000000 iterations loop)
Starting chronometer
Result for global variable access = 57s (100000000 iterations loop)
Starting chronometer
Result for global variable access = 56s (100000000 iterations loop)
TESTS ON GLOBAL/LOCAL VARIABLES (String)
Starting chronometer
Result for local variable access = 282s (100000000 iterations loop)
Starting chronometer
Result for global variable access = 253s (100000000 iterations loop)
Starting chronometer
Result for global variable access = 252s (100000000 iterations loop)
TESTS ON DECLARATIONS INSIDE OR OUTSIDE LOOPS (int)
Starting chronometer
Result for local variable with declaration in loop = 82s (100000000 iterations loop)
Starting chronometer
Result for unique variable declaration = 76s (100000000 iterations loop)
TESTS ON DECLARATIONS INSIDE OR OUTSIDE LOOPS (String)
Starting chronometer
Result for local variable with declaration in loop = 263s (100000000 iterations loop)
Starting chronometer
Result for unique variable declaration = 252s (100000000 iterations loop)
TESTS ON String
Starting chronometer
Result for a loop that declares ints = 74s (100000000 iterations loop)
Starting chronometer
Result for a loop that copies a litteral String of length 0 = 254s (100000000 iterations loop)
Starting chronometer
Result for a loop that copies a litteral String of length 100 = 303s (100000000 iterations loop)
Starting chronometer
Result for a loop that copies a variable String of length 100 = 172s (100000000 iterations loop)
READ/WRITE TESTS FOR int,float,bool
Starting chronometer
Result for a loop that writes ints = 76s (100000000 iterations loop)
Starting chronometer
Result for a loop that writes floats = 76s (100000000 iterations loop)
Starting chronometer
Result for a loop that writes bools = 76s (100000000 iterations loop)
TESTS FOR CONDITIONS (if/goto)
Starting chronometer
Starting chronometer
Result for a loop that tests a condition : THEN=84s, ELSE=76s (100000000 iterations loop)
TESTS FOR FUNCTIONS WITH PARAMETERS
Starting chronometer
Result for function with 0 parameters = 93s (100000000 iterations loop)
Starting chronometer
Result for function with 1 parameters = 107s (100000000 iterations loop)
Starting chronometer
Result for function with 2 parameters = 117s (100000000 iterations loop)
Starting chronometer
Result for function with 3 parameters = 128s (100000000 iterations loop)
Starting chronometer
Result for function with 4 parameters = 139s (100000000 iterations loop)
TESTS FOR FUNCTION CALLS
Starting chronometer
Result for simple operation performed inline = 61s (100000000 iterations loop)
Starting chronometer
Result for simple operation performed using a function call = 117s (100000000 iterations loop)


==============================
Tests performed. Program will exit in a few seconds...
Please have a look at log.txt

 

Pumaman

Interesting stuff, thanks for posting this!

It's worth noting of course that with things like the number of function parameters, it's likely that the code you actually have inside the function will take a fixed amount of extra time regardless of the number of parameters, therefore the percentage loss of using an extra parameter is much less when you actually have code in the function.

Monsieur OUXX

Quote from: Pumaman on Sun 13/01/2008 15:27:39
It's worth noting of course that with things like the number of function parameters, it's likely that the code you actually have inside the function will take a fixed amount of extra time regardless of the number of parameters, therefore the percentage loss of using an extra parameter is much less when you actually have code in the function.

Absolutely. That's why I made 2 separated tests :

- one that allows to see the proportionality rule between the number of parameters and the time needed to heap/unheap the parameters when function is called (here, the reference is the function with 0 parameters). The more instructions you put in the function, the more this extra-time is "absorbed" in the total time required for the function to execute. Maybe sometimes it could be interesting to group the parameters in an object. I should test if the extra-time comes from the total volume of the parameters or from their number.

- one that compares the extra-time required to execute a very simple function vs. a very simple instruction. Here, the goal is to evaluate the cost of, let's say, an accessor (get/set) in an object (i.e. a function with only one instruction), if you need to call this accessor very often.


-------

I'd really like to test int calculation vs. float calculation. If there is a huge idfference, rewriting the 3D modules with integer-based routines would be a revolution in AGS, just like it was when Doom was released ;) (don't pay attention, I'm dreaming)

 

Monsieur OUXX

#5
I'm digging up this very old thread as I've done some new tests that could benefit to all (as part of the "AGS Kart" development)
Please note that I'm now using AGS 3.2, and the original post was with AGS 2.72.

Here is my test code with results :
Code: ags


function noloopcheck speedTest() {
    int i=0;
    
    // TEST 1 : built-in function call versus stored value access
    /*
    while (i<100000) {
      //float f = Maths.Cos(2.0);     //23 FPS for 100,000 loops
      int f = cos[200];               //25 FPS for 100,000 loops
      i++;
      
    }
    */
    
    
    // TEST 2 : floating division versus binary shifting
    float f;
    int f_;
    
    while (i<100000) {
      f = (1233.54/23344.657)*(65464.78/56556.465);        //19 FPS for 100,000 loops
      //f_ = (132367 >> 10) << (16777216 >> 22);              //19 FPS for 100,000 loops
      i++;
      
    }
    
    // TEST 3 : in-block memory allocation/disposal optimization by AGS' compiler, a.k.a : "Does it help to declare outside of the loop?"
    
    //version 1 : 22 FPS for 100,000 loops
    /*
    while (i<100000) {
      float f1 = 236.25;
      float f2 = 4659.546;
      i++;
      
    }
    */
    
    //version 2: 28 FPS for 100,000 loops
    float f1;
    float f2;
    while (i<100000) {
      f1 = 236.25;
      f2 = 4659.546;
      i++;
      
    }    
    
}



RESULTS:
1. I was stunned to see that using floats to do a division is exactly as fast as using ints to do a binary shift :'(
2. declaring a local variable inside a loop still seems to have an important impact on performance
3. there is still a slight benefit in accessing arrays rather than calling a function, even if it's built-in. That can save a few FPS if you do heavy trigonometric calculations.
 

Kweepa

Quote from: Monsieur OUXX on Fri 11/05/2012 17:46:22
1. I was stunned to see that using floats to do a division is exactly as fast as using ints to do a binary shift :'(
That shouldn't be a surprise. Float division is as fast as integer math on modern CPUs, and there's the large script interpolation overhead drowning out any minor differences.
Good work! :)
Still waiting for Purity of the Surf II

Monsieur OUXX

I ran a new test that shows that the manipulation of dynamic array sby AGS is truly by-reference -- In other words, the size of the array does not impact the speed in any way.
That makes perfect sense but I wanted to be sure.


Test script
Spoiler

Code: ags


int[] Test4_Helper(int array[])
{
   int a2[]= array;
   return a2;
}

void noloopcheck Test4() 
{
    int a[] = new int[1000000];
    int b[] = new int[1];
    
    resetChrono();
    for (int i=0; i<nbLoopsTest; i++) {
        a = Test4_Helper(a);
    }
    int result1 = getChrono();
 
    resetChrono();
    for (int i=0; i<nbLoopsTest; i++) {
        b = Test4_Helper(b);
    }
    int result2 = getChrono();
    
    Console.W("result1=%d, result2=%d", result1,  result2);
    
}


[close]
 

Monsieur OUXX

...and yet another test to see if the number of cells in an array impacts the speed to write to a given cell. it doesn't. Accessing cell #0 of an array with just one cell is as fast as accessing cell #99999 of an array of size 100000.
That also makes perfect sense, but I wanted to make sure there's not bads surprise coming from the underlying memory management and boundaries check

Test script
Spoiler

Code: ags


void noloopcheck Test5()
{
    int a_size=1000000;
    int b_size=1;
    int a[] = new int[a_size];
    int b[] = new int[b_size];
    
    resetChrono();
    for (int i=0; i<nbLoopsTest; i++) {
        a[a_size-1] = 0;
    }
    int result1 = getChrono();
 
    resetChrono();
    for (int i=0; i<nbLoopsTest; i++) {
        b[b_size-1] = 0;
    }
    int result2 = getChrono();
    
    Console.W("result1=%d, result2=%d", result1,  result2); 
}

[close]
 

SMF spam blocked by CleanTalk