time a procedure takes in microseconds ? not milli

Blitz3D Forums/Blitz3D Beginners Area/time a procedure takes in microseconds ? not milli

RemiD

(Posted 2016) [#1]

hello,

from what i have found online :
1 second = 1 000 milliseconds = 1 000 000 microseconds
so 1 millisecond = 1 000 microseconds

and as i understand it, with Blitz3d, we can only get the current milliseconds value since the computer started.

but sometimes, the time in milliseconds is not precise enough to get an idea of the time a procedure takes.
so an ugly workaround that i use is to run the procedure 1000 times so that it gives me an idea of the time it takes in microseconds (or a float value in milliseconds taking into account microseconds) :

Graphics3D(640,480,32,2)

SeedRnd(MilliSecs())

Global TexelsCount%
Dim Texel_Texture(63000)
Dim Texel_PX%(63000)
Dim Texel_PY%(63000)
Dim Texel_ColorR%(63000)
Dim Texel_ColorG%(63000)
Dim Texel_ColorB%(63000)

For n% = 1 To 63000 Step 1
 TexelsCount = TexelsCount + 1
 TI% = TexelsCount
 Texel_Texture(TI) = 0
 Texel_PX(TI) = Rand(0,1024-1) : Texel_PY(TI) = Rand(0,1024-1)
 Texel_ColorR(TI) = Rand(000,255) : Texel_ColorG(TI) = Rand(000,255) : Texel_ColorB(TI) = Rand(000,255)
Next

ColorR% = Rand(000,255) : ColorG% = Rand(000,255) : ColorB% = Rand(000,255)
StartMs% = MilliSecs()
For l% = 1 To 1000 Step 1
For TI% = 1 To TexelsCount Step 1
 If( Texel_ColorR(TI) = ColorR And Texel_ColorG(TI) = ColorG And Texel_ColorB(TI) = ColorB )
  ;
 EndIf
Next
Next
TimeMs% = MilliSecs() - StartMs
ClsColor(000,000,000) : Cls()
Locate(0,0)
Color(255,255,255)
Print("TimeMs = "+Float(TimeMs)/1000)

WaitKey()

End()

(be sure to run the code with debug mode desactivated...)
is there any other (more precise) way to get the microseconds value since the computer started ?

_PJ_	(Posted 2016) [#2]

Many years ago I posted a function timing routine on these boards that provides sufficient repetition and accounts for the time delay in the processing of the actual timing itself.

I'll see if I can find the post...

skidracer

(Posted 2016) [#3]

searching blitz3d queryperformancecounter led me here

oh sorry, it's blitzmax code...

_PJ_	(Posted 2016) [#4]

Well I couldn't find the topic opr posts I mentioned. You might have better luck searching, but all I can say it was at least 3 years ago and maybe as many as 6 - I cannot even recall if this was in Code Archives, B3D or Blitz 3D Beginners...

___

Anyway the crux of the issue are a number of points:

1) As you have identified a number of iterations are required to ascertain a more accurate mean approximation of the duration for a given function. Theoretically, the more iterations, the more accurate result...

2) Each iteration, however incurs a modicum of time that is required for the testing routine to call the function and process the timing as well as keyboard input etc. polling and, if relevant, the compiler/debugger. This will always be included in the total duration recorded. It is therefore necessary to account for this addition and subtract it from the final result.

3) Other factors are also going to severely impact the result. Depending on CPU, this may be multithreading operations from other processes or the OS, the ability to cache repeated code (actually making your function timing faster) and so on.

4)Odd/Even "jump-labels" can even affect timing.

There are a number of other areas under-the-hood in which the duration of one part of the code may actually be affected significantly (i.e. over 50%) by the presence of certain other aspects.

For example, consider the change in the size of the EMPTY (which ought to be fairly static and NOT dependant on any other code-related changes) duration when different variable types are processed in the TEST:

EnableDirectInput False
Delay 500; This just gives Blitz time to pop up its initial window on the screen.
Local Iter

Const TRIALS=8
Const ITERATIONS=1000;Large number for accuracy. Also converts To "盜"

Global EMPTY[TRIALS]
Global TEST[TRIALS]
Global EMPTYTOTAL
Global EMPTYMEAN#
Global TESTTOTAL
Global TESTMEAN#
Global TIMESTAMP

Local Trial
Local PerIter#
Local M
Local Calculate

;POPULATE EMPTY
For Trial= 1 To TRIALS
	TIMESTAMP=MilliSecs()
	For Iter=1 To ITERATIONS
		M=MilliSecs();Tracks time of call
	Next
	EMPTY[Trial-1]=M-TIMESTAMP
Next

;CALCULATE EMPTY MEAN
For Calculate=1 To TRIALS
	EMPTYTOTAL=EMPTYTOTAL+EMPTY[Calculate-1]
Next
EMPTYMEAN#=Float((Float(EMPTYTOTAL)/Float(TRIALS)))

;POPULATE TEST
For Trial=1 To TRIALS
	TIMESTAMP=MilliSecs()
	For Iter=1 To ITERATIONS
		
;INSERT TEST FUNCTION HERE!
		
	Next
	TEST[Trial-1]=MilliSecs()-TIMESTAMP
Next

;CALCULATE TEST MEAN
For Calculate=1 To TRIALS
	TESTTOTAL=TESTTOTAL+TEST[Calculate-1]
Next
TESTMEAN#=Float((Float(TESTTOTAL)/Float(TRIALS)))

Print "Mean duration for function process:"
Print Str(TESTMEAN)+" - "+Str(EMPTYMEAN)+" = "+Str(TESTMEAN-EMPTYMEAN)+"盜"

Bobysait

(Posted 2016) [#5]

I'm pretty sure I've add this on an old c++ library I made for blitz3d
It was on google.code, I didn't port it to github so it may be lost, but, I probably have a backup.

[edit]
Ok, I got it
* http://mdt.bigbang.free.fr/bbAddon/v0.4/v0.4.rar (latest stable version)
* http://mdt.bigbang.free.fr/bbAddon/v0.41/v0.41.rar (latest version - some stuff may be broken ... I don't remember)

it contains a lots of addons for blitz3d but it's pretty old now (I'm not even sure it will work with latest versions of blitz3d.
All the sources are available in the archive.

The library also contains :
- linked list
- some maths functions
- scripted class
- a tokenizer
- an event queue manager (like blitzmax')
- a counter sdk (which contains time in microseconds -> require a high definition cpu -> probably available on all 5-10 years old cpu)

(la liste des fonctions disponibles dans le fichier decls)

.lib "bbAddon.dll"

; ------------ Maths ------------
RadToDeg#(Angle#):"_RadToDeg@4"
DegToRad#(Angle#):"_DegToRad@4"
Min#(a#,b#):"_Min@8"
Max#(a#,b#):"_Max@8"
LinearInterp#(a#,b#,rate#):"_LinearInterp@12"
CosInterp#(a#,b#,rate#):"_CosInterp@12"
CubicInterp#(a#,b#,c#,d#,rate#):"_CubicInterp@20"


; ------------ Vector2 ------------
Vector2%(x#,y#):"_NewVector2@8"
DeleteVector2%(v):"_DeleteVector2@4"

SetVector2(v, x#,y#):"_SetVector2@12"
SetVector2X(v, x#):"_SetVector2X@8"
SetVector2Y(v, y#):"_SetVector2Y@8"

Vector2Equal%(v1,v2):"_Vector2Equal@8"

Vector2x#(v):"_Vector2X@4"
Vector2y#(v):"_Vector2Y@4"
Vector2Angle#(v1,v2):"_Vector2Angle@8"
Vector2Mag#(v):"_Vector2Mag@4"
Vector2SquareMag#(v):"_Vector2SquareMag@4"
Vector2Dot#(v1,v2):"_Vector2Dot@8"
Vector2Cross#(v1,v2):"_Vector2Cross@8"

MagVector2#(v):"_MagVector2@4"


; ------------ Events ------------

EmitEvent(Id%,X%,Y%,Data$,Source%):"_EmitEvent@20"
PollEvent%():"_PollEvent@0"
EventID%():"_EventID@0"
EventX%():"_EventX@0"
EventY%():"_EventY@0"
EventSource%():"_EventSource@0"
EventData$():"_EventData@0"

EventEnableStack(Enable%):"_EventEnableStack@4"
EventStackEnabled%():"_EventStackEnabled@0"
SetEventStackSize(size%):"_SetEventStackSize@4"
EventStackSize%():"_EventStackSize@0"
CountEvents%():"_CountEvents@0"


; ------------ Counter ------------

HDTSupport%():"_HDTSupport@0"

Millisecondes%():"_Millisecondes@0"
SystemCounter%():"_SystemCounter@0"
ResetClock ():"_ResetClock@0"
MicroSecs%():"_MicroSecs@0"
ComputerTime%():"_ComputerTime@0"
ElapsedTime%():"_ElapsedTime@0"
PITClock#():"_PITClock@0"
AppMicroCoef#():"_AppMicroCoef@0"

CreateCounter%():"_CreateCounter@0"
ResetCounter( counter ):"_ResetCounter@4"
CounterTime %( counter ):"_CounterTime@4"
CounterElasped%( counter ):"_CounterElasped@4"
CounterFree( counter ) :"_CounterFree@4"
CounterStartedAt%( counter ):"_CounterStartedAt@4"


; ------------ Linked-List ------------

DebugCountLinks%():"_DebugCountLinks@0"
NewList%():"_NewList@0"
AddLast%(List,value$):"_ListAddLast@8"
AddFirst%(List,value$):"_ListAddFirst@8"
InsertBefore%(Link,before):"_ListInsertBefore@8"
InsertAfter%(Link,after):"_ListInsertAfter@8"
DeleteList(List):"_DeleteList@4"
DeleteLink(Link):"_DeleteLink@4"
ListContains%(List,Value$):"_ListContains@8"
ListIsEmpty%(List):"_ListIsEmpty@4"
ListFirst%(list):"_FirstLink@4"
ListLast%(list):"_LastLink@4"
AfterLink%(link):"_AfterLink@4"
BeforeLink%(link):"_BeforeLink@4"
LinkValue$(link):"_LinkValue@4"
SetLinkValue(Link,value$):"_SetLinkValue@8"

LinkCompare%(l1,l2):"_LinkCompare@8"
StrCompare%(a$,b$):"_StrCompare@8"
SwapLinks%(link1,link2):"_SwapLinks@8"
SortList%(List,Sens):"_SortList@8"


; ------------ Tokenizer ------------

Tokenize%(chaine$,Delimiters$, Symbols$):"_cTokenize@12"


; ------------ SSE float4 -----------

Float4Create%():"_Float4Create@0"
Float4Free(float4%):"_Float4Free@4"
Float4Set(float4%,a#,b#,c#,d#):"_Float4Set@20"
Float4Get#(float4%,index%):"_Float4Get@8"
Float4Add(float4_0%,float4_1%):"_Float4Add@8"
Float4Sub(float4_0%,float4_1%):"_Float4Sub@8"
Float4Mul(float4_0%,float4_1%):"_Float4Mul@8"
Float4Div(float4_0%,float4_1%):"_Float4Div@8"
Float4Min(float4_0%,float4_1%):"_Float4Min@8"
Float4Max(float4_0%,float4_1%):"_Float4Max@8"
Float4Sqrt(float4%):"_Float4Sqrt@4"

RemiD

(Posted 2016) [#6]

@Bobysait>>thanks i will try your function MicroSecs()

xlsior

(Posted 2016) [#7]

Quick and dirty alternative: call your function a thousand times in a row, and measure how many millisecs passed. Divide by 1,000 to see how many microseconds each iteration took.

RemiD

(Posted 2016) [#8]

call your function a thousand times in a row, and measure how many millisecs passed. Divide by 1,000 to see how many microseconds each iteration took.

apparently you read the first post ;)

so an ugly workaround that i use is to run the procedure 1000 times so that it gives me an idea of the time it takes in microseconds

Panno

(Posted 2016) [#9]

microseconds and windows? this will not work because win is not realtime.

gtx

_PJ_	(Posted 2016) [#10]

The accuracy will go right out the window with around 200盜 at best.
Although I will concede that milliseconds timing is somewhat ineffective nowadays with a vast majority of processes taking <500盜 and therefore any attempts to identify a deltatime of this will show 0 at the millisecond resoluition (due to rounding).
Ideally current spec would probably require 0.1ms as the target fidelity resolution.

RemiD

(Posted 2016) [#11]

after some tests, it seems better to run the procedure 100times and then to divide the result by 100 (to have a millisecond value with 0.01 precision) because if you try to measure the mstime it takes of a complex procedure like renderworld, this seems to disturb the result in a weird way (takes more time)...