Speed testing algos

[LordAdef]

Hi there, I usually post in my own thread in the Campus, where I´m making this game. But since this is related to timing algos, I thought this should be the right place.

The thing is, I realized I don´t know how to properly time my code to accurately tell if I´m optimizing it right.
There is always some system interference or some fluctuation. I´m sure there must be a way to accurately measure your code.

In the case below, there are 2 algos which I put in the same proggy. The "old" copies values byte per byte, while the 2nd invokes the memcopy to copy dword chunks first, and the remaing goes byte per byte.

I didn´t optmized it so far, and wanted to call for help before I begin. All I did is change the copy behaviour as described above. 

The old one uses this macro called mUNROLL:

mUNROLL MACRO
         PUSH ecx
         mov ecx, tChar
         xor eax, eax
          @@:
            mov [edi], cl
              cmp eax, ebx
         jz @F          
             add edi, 1
         add eax, 1
         jmp @B
         @@:
         POP ecx
      endm

The "new" uses the mUNROLLdword:

mUNROLLdword MACRO
      PUSH edx
      mov eax, ebx                        ; MOD here
      mov ecx, 4
      cdq
      div ecx                              ; result in eax, sobra in edx; MOD

      sub ebx, edx                        ; only dwords here, we do edx afterwards   
      .IF tChar == 64
         mov eax, offset Ln1
      .ELSEIF tChar == 32
         mov eax,  offset Ln2
      .ENDIF
      invoke MemCopy, eax, edi, ebx      ; copying dword sizes
      add edi, ebx                        ; add a line lenght for edi index
      mov bl, [eax]                        ; this is either @ or space
      xor ecx, ecx
   @@:
      cmp ecx, edx
      jz @F
      mov [edi], bl
      add edi, 1
      add ecx, 1          
      jmp @B
   @@:         
      POP edx
      endm

I´m calling both algos from here:

.code
start:
   ;old algo. Copies byte by byte
   printf ("\nNew Algo: ")
   ;NanoTimer()
   invoke pDecompress, offset NewFile
   ;Print Str$("%i us ", NanoTimer(us))
      
   ;New algo. Copies dwords, then the remaining byte by byte. Uses "memcopy"
   printf ("\nOld Algo: ")
   ;NanoTimer()
   invoke pDecompress2, offset NewFile
   ;Print Str$("%i us ", NanoTimer(us))

I tested multiplying the calls by 4 each, 8 and 16. I also inverted the invoking order, which appeared to change things too.

1 call
old   174   197   192   154   268   227   211   212   157   169   162   219   =2
new   192   161!   157!   153x   187!   173!   158!   200!   165   141!   158!   157!   =9

1 call (New 1st)
new   178   212   186   183   170x   153   196   168   169   193   192   =4
old   140!   250   162!   172!   171x   192   253   147!   162!   135!   202   =6

4 calls:
old   515   616   512   588   740   480   518   503   543   532   =4
new   499!   556!   535   558!   735!   678   481!   551   511!   557   =6

8 calls:
old   995   923   937   1096   1083   914   999   886   934   905   973   =3
new   904!   900!   1100   906!   961!   931   902!   902!   1107   894!   917!   =8

16 calls:
old   1799   1783   2352   1907   3213   1845x   1688   1727x   1844   1732   1717   =4
new   1702!   1730!   1763!   1896!   2843!   1849x   1800   1722x   2030   1826   1756   =5

16 calls (New first):   
new   1913   1784   1969   2162   1837   1900   1728   2630   2165   1729   1763   =0
old   1732!   1658!   1778!   1902!   1733!   1688!   1615!   2029!   1638!   1669!   1649!   =11

If you look at my last test for 16 calls, my New algo looses in every take.

[jj2007]

Use a 1000 calls, as shown below:

      printf ("\nNew Algo: ")
      NanoTimer()
      push 999
      .Repeat
            invoke pDecompress, offset NewFile
            dec stack
      .Until Sign?
      pop edx
      Print Str$("%i ms ", NanoTimer(ms))
           
      ;New algo. Copies dwords, then the remaining byte by byte. Uses "memcopy"
      printf ("\tOld Algo: ")
      NanoTimer()
      push 999
      .Repeat
            invoke pDecompress2, offset NewFile
            dec stack
      .Until Sign?
      pop edx
      Print Str$("%i ms ", NanoTimer(ms))
      endm

Code Select Expand

New Algo: 129 ms        Old Algo: 132 ms
New Algo: 123 ms        Old Algo: 128 ms
New Algo: 126 ms        Old Algo: 123 ms
New Algo: 127 ms        Old Algo: 118 ms
New Algo: 117 ms        Old Algo: 128 ms
New Algo: 129 ms        Old Algo: 138 ms
New Algo: 123 ms        Old Algo: 124 ms
New Algo: 123 ms        Old Algo: 122 ms
New Algo: 123 ms        Old Algo: 124 ms
New Algo: 120 ms        Old Algo: 122 ms

Results in the 100 ms range are much more reliable than something in the us range.
The timer example in the templates is optimised for such problems btw.

[LordAdef]

Nice JJ!

dec "stack" is new to me by the way. MB?

[jj2007]

dec "stack" is new to me by the way. MB?

Yes, it's just an equate: stack equ dword ptr [esp]

Code Select Expand

      push 999
      .Repeat
            invoke pDecompress, offset NewFile
            dec stack   ; same as dec dword ptr [esp]
      .Until Sign?
      pop edx

It will cost an extra cycle in that loop, but that hardly matters, and it's a very simple way to get a counter without using a register. And no risk to end up by accident with an endless loop - I avoid .Until Zero? wherever possible ;)

[mineiro]

hello sir LordAdef;
I took some time to understand your code, sound to me that you're thinking so hard, you can do this procedure on a more easy way.

To better readable masm have 'struct' keyword, acts like opaque structures.

Code Select Expand

header_file struct
output_size dd ?
line_count dd ?
line_lenght dd ?
header_file ends

so, on your code you can use do something like:

Code Select Expand


mov   esi, pstring ;pointer to file
assume esi:ptr header_file
m2m tSum,[esi].output_size
m2m tLine,[esi].line_count
m2m tLineLen,[esi].line_lenght
assume esi:nothing
; add esi,sizeof header_file ;displacement header file
; sub szstring,sizeof header_file ;szstring==szstring-header_file

On your code you have used "mov ecx, DWORD Ptr [esi+8]" to get line_lenght . On line "mov edx, 12 ;counter" you can write "mov edx,sizeof header_file".

You can use some tricks on your code, but you should think on binary base instead of decimal base.

Code Select Expand


mSWITCHChars MACRO
xor tChar,01100000b
; .IF tChar == "@" ;64 ;1000000b
; mov tChar, " " ;32 ;_100000b
; .ELSEIF tChar == " " ;32
; mov tChar, "@" ;64
; .ENDIF
endm


Other trick is when you're working with multiples of number 2, so, 2,4,8,16,32,64,... . If you write this numbers with binary base you can feel an idea.
        1  1
      10  2
    100  4
  1000  8
10000  16
The number one is walking to left side and inserting zeros at right side, and this is multiplication. So, if you like to multiply something by 4 per example you need only shift the number left by 2, if you like to multiply by 8 you shl number by 3.
So, if walking to left is multiply, walking to right should be divide. So, if you like to divide something by 4 per example you need only shift the number right by 2, if you like to divide by 8 you shr number by 3. This way you get quotient.
But by dividing (shift right) we lost remainder, so, to you get the remainder you can use a mask on original number.

Code Select Expand

mov eax, ebx  ;ebx holds a number to be divided by 4
mov edx,ebx
shr eax,2 ;quotient, divide by 4
and edx,3 ;remainder, 3 means mask, 00000011b


You're working with sign numbers, so, if you get a negative value you can transform it to positive value by using "neg" instruction.

Code Select Expand

.IF tChar == "@" ;64; .if tChar == "@@@@"
; mov eax, offset Ln1
.while eax != 0
mov dword ptr [edi],"@@@@"
add edi,4 ;lea edi,[edi+4]
dec eax
.endw
.while edx != 0
mov byte ptr [edi],"@"
inc edi
dec edx
.endw
.ELSE;IF tChar == " " ;32
; mov eax,  offset Ln2
.while eax != 0
mov dword ptr [edi],"    "
add edi,4 ;lea edi,[edi+4]
dec eax
.endw
.while edx != 0
mov byte ptr [edi]," "
inc edi
dec edx
.endw

.ENDIF


[LordAdef]

Master of the Golden Lands of Minas Gerais, Mr. Mineiro!!

Thanks my friend.
I´m having a lot of fun only dealing with asm without having to deal with Windows....

I´m prototyping these algos and making them to work first. Then, I´ll be tweaking and fiddling with it so to optimize it for speed.

I was having issues to time my algos, that´s why I wrote this thread. Without timing it properly I could not possibly judge anything. JJ has given me the timing tip above and now it´s fun time.

"NEG" => I have forgot about this one!!!! Thanks, I was wasting some valuable cycles there

SHR/SHL I´ve read somewhere these are kind of slower instructions. I guess there must be a cost relation and my extra code is in fact slower. I´ll check them

Please, keep it coming!
Cheers
Alex

[jj2007]

Hi Alex,

You should isolate the file load times from your algos. See the bookmarks in the attachment for an example.

In your case, it doesn't matter a lot because the algos have a lot of work to do, but for fast short algos it makes a big difference if you are just working on a buffer, or if the buffer needs to be filled from disk before the short work starts.

(in conditional assembly, ife means "if equal" or "if zero" - see free esi)

[LordAdef]

Dear JJ,

I´ll check this out now!
I must thank you, you can´t imagine how useful your timing snippet above is being right now! I was missing that.

I´ve already started to fiddle with the algo:
- mUNROLLdword  macro was slower so I got back mUNROLL and am optimizing it. 
- NEG was clearly faster than my maths
- SHR/SHL made a negative effect on the code, slower
- Working on optimizing  reg usage, with good results

So far:

New Algo: 103 ms       Old Algo: 97 ms
New Algo: 102 ms       Old Algo: 96 ms
New Algo: 102 ms       Old Algo: 97 ms
New Algo: 105 ms       Old Algo: 97 ms
New Algo: 108 ms       Old Algo: 100 ms
New Algo: 109 ms       Old Algo: 101 ms

after using "NEG"
   .mUNROLLdword was slower, using mUNROLL
   .SHR/SHL was slower

New Algo: 98 ms        Old Algo: 103 ms
New Algo: 98 ms        Old Algo: 102 ms
New Algo: 100 ms       Old Algo: 103 ms
New Algo: 98 ms        Old Algo: 102 ms
New Algo: 99 ms        Old Algo: 100 ms
New Algo: 99 ms        Old Algo: 101 ms

after optm tChar for ecx mUNROLL2

New Algo: 96 ms        Old Algo: 99 ms
New Algo: 94 ms        Old Algo: 104 ms
New Algo: 99 ms        Old Algo: 97 ms   x
New Algo: 92 ms        Old Algo: 98 ms
New Algo: 94 ms        Old Algo: 97 ms
New Algo: 92 ms        Old Algo: 100 ms
New Algo: 96 ms        Old Algo: 97 ms

[mineiro]

hello sir LordAdef;
I agree with you, some persons use 'lea' instead of 'shl'.
Check this link
http://www.agner.org/optimize/

[jj2007]

some persons use 'lea' instead of 'shl'

Let's time it

Code Select Expand

Intel(R) Core(TM) i5-2450M CPU @ 2.50GHz (SSE4)
10      cycles for 100 * shl eax, 1
25      cycles for 100 * lea eax, [2*eax]
10      cycles for 100 * shl eax, 3
17      cycles for 100 * lea eax, [8*eax]
18      cycles for 100 * lea eax, [8*eax+100]
148     cycles for 100 * imul eax, eax, 8

11      cycles for 100 * shl eax, 1
26      cycles for 100 * lea eax, [2*eax]
11      cycles for 100 * shl eax, 3
16      cycles for 100 * lea eax, [8*eax]
17      cycles for 100 * lea eax, [8*eax+100]
147     cycles for 100 * imul eax, eax, 8

10      cycles for 100 * shl eax, 1
25      cycles for 100 * lea eax, [2*eax]
10      cycles for 100 * shl eax, 3
18      cycles for 100 * lea eax, [8*eax]
18      cycles for 100 * lea eax, [8*eax+100]
149     cycles for 100 * imul eax, eax, 8

11      cycles for 100 * shl eax, 1
25      cycles for 100 * lea eax, [2*eax]
10      cycles for 100 * shl eax, 3
16      cycles for 100 * lea eax, [8*eax]
18      cycles for 100 * lea eax, [8*eax+100]
148     cycles for 100 * imul eax, eax, 8

2       bytes for shl eax, 1
7       bytes for lea eax, [2*eax]
3       bytes for shl eax, 3
7       bytes for lea eax, [8*eax]
7       bytes for lea eax, [8*eax+100]
3       bytes for imul eax, eax, 8

[mineiro]

these are results on my pc:

Code Select Expand

Intel(R) Pentium(R) Dual  CPU  E2160  @ 1.80GHz (SSE4)

12      cycles for 100 * shl eax, 1
1       cycles for 100 * lea eax, [2*eax]
12      cycles for 100 * shl eax, 3
1       cycles for 100 * lea eax, [8*eax]
0       cycles for 100 * lea eax, [8*eax+100]
180     cycles for 100 * imul eax, eax, 8

87      cycles for 100 * shl eax, 1
1       cycles for 100 * lea eax, [2*eax]
12      cycles for 100 * shl eax, 3
1       cycles for 100 * lea eax, [8*eax]
0       cycles for 100 * lea eax, [8*eax+100]
181     cycles for 100 * imul eax, eax, 8

12      cycles for 100 * shl eax, 1
1       cycles for 100 * lea eax, [2*eax]
12      cycles for 100 * shl eax, 3
1       cycles for 100 * lea eax, [8*eax]
0       cycles for 100 * lea eax, [8*eax+100]
181     cycles for 100 * imul eax, eax, 8

12      cycles for 100 * shl eax, 1
1       cycles for 100 * lea eax, [2*eax]
12      cycles for 100 * shl eax, 3
1       cycles for 100 * lea eax, [8*eax]
0       cycles for 100 * lea eax, [8*eax+100]
180     cycles for 100 * imul eax, eax, 8

2       bytes for shl eax, 1
7       bytes for lea eax, [2*eax]
3       bytes for shl eax, 3
7       bytes for lea eax, [8*eax]
7       bytes for lea eax, [8*eax+100]
3       bytes for imul eax, eax, 8


--- o

[jj2007]

0 cycles for 100 * lea is very strange ::)

[LordAdef]

these results are frustrating sometimes.....

sadly I left my pc already. I post my results later today

[TWell]

Code Select Expand

AMD E1-6010 APU with AMD Radeon R2 Graphics     (SSE4)

0       cycles for 100 * shl eax, 1
3       cycles for 100 * lea eax, [2*eax]
0       cycles for 100 * shl eax, 3
3       cycles for 100 * lea eax, [8*eax]
2       cycles for 100 * lea eax, [8*eax+100]
173     cycles for 100 * imul eax, eax, 8

1       cycles for 100 * shl eax, 1
4       cycles for 100 * lea eax, [2*eax]
0       cycles for 100 * shl eax, 3
3       cycles for 100 * lea eax, [8*eax]
2       cycles for 100 * lea eax, [8*eax+100]
174     cycles for 100 * imul eax, eax, 8

0       cycles for 100 * shl eax, 1
3       cycles for 100 * lea eax, [2*eax]
0       cycles for 100 * shl eax, 3
4       cycles for 100 * lea eax, [8*eax]
2       cycles for 100 * lea eax, [8*eax+100]
173     cycles for 100 * imul eax, eax, 8

0       cycles for 100 * shl eax, 1
5       cycles for 100 * lea eax, [2*eax]
0       cycles for 100 * shl eax, 3
2       cycles for 100 * lea eax, [8*eax]
2       cycles for 100 * lea eax, [8*eax+100]
172     cycles for 100 * imul eax, eax, 8

2       bytes for shl eax, 1
7       bytes for lea eax, [2*eax]
3       bytes for shl eax, 3
7       bytes for lea eax, [8*eax]
7       bytes for lea eax, [8*eax+100]
3       bytes for imul eax, eax, 8


--- ok ---

[mineiro]

I tested on linux, I will just reboot and post results on windows.
I'll be back and edit this message.

Code Select Expand

Intel(R) Pentium(R) Dual  CPU  E2160  @ 1.80GHz (SSE4)

12      cycles for 100 * shl eax, 1
1       cycles for 100 * lea eax, [2*eax]
12      cycles for 100 * shl eax, 3
1       cycles for 100 * lea eax, [8*eax]
0       cycles for 100 * lea eax, [8*eax+100]
180     cycles for 100 * imul eax, eax, 8

12      cycles for 100 * shl eax, 1
1       cycles for 100 * lea eax, [2*eax]
12      cycles for 100 * shl eax, 3
1       cycles for 100 * lea eax, [8*eax]
0       cycles for 100 * lea eax, [8*eax+100]
180     cycles for 100 * imul eax, eax, 8

12      cycles for 100 * shl eax, 1
1       cycles for 100 * lea eax, [2*eax]
12      cycles for 100 * shl eax, 3
2       cycles for 100 * lea eax, [8*eax]
0       cycles for 100 * lea eax, [8*eax+100]
180     cycles for 100 * imul eax, eax, 8

12      cycles for 100 * shl eax, 1
1       cycles for 100 * lea eax, [2*eax]
12      cycles for 100 * shl eax, 3
1       cycles for 100 * lea eax, [8*eax]
0       cycles for 100 * lea eax, [8*eax+100]
180     cycles for 100 * imul eax, eax, 8

2       bytes for shl eax, 1
7       bytes for lea eax, [2*eax]
3       bytes for shl eax, 3
7       bytes for lea eax, [8*eax]
7       bytes for lea eax, [8*eax+100]
3       bytes for imul eax, eax, 8


--- ok ---

Same results on linux or windows.

---edited---
Other results

Code Select Expand

     Clock   Core cyc   Instruct       Uops  BrMispred
;-------------------------------------------------------
TestA call shl eax,1
      4131       4126       9000      11000          0
      4131       4126       9000      11000          0
         9          5          9         11          0
1000*shl eax,1
       990        996       1000       1000          0
100000*shl eax,1
    101151     101151     100000     106249          0
;-------------------------------------------------------
TestB call lea eax,[eax*2]
      7695       5126       9000      11000          0
      7686       5126       9000      11000          0
         9          5          9         11          0
1000*lea eax,[eax*2]
       999        995       1000       1000          0
100000*
    105813     105811     100000     112499          0
;-------------------------------------------------------
TestC call shl eax,3
      4248       4253       9000      11000          0
      6381       4253       9000      11000          0
         9          6          9         11          0
1000*shl eax,3
       999        999       1000       1000          0
100000*
    152973     101982     100000     109375          0
;-------------------------------------------------------
TestD call lea eax,[eax*8]
      5256       5252       9000      11000          0
      5256       5252       9000      11000          0
         9          6          9         11          0
1000*lea eax,[eax*8]
       999        996       1000       1000          0
100000*
    307638     307648     100000     125198          0
;-------------------------------------------------------
TestE call lea eax,[eax*8+100]
      5130       5126       9000      11000          0
      7686       5126       9000      11000          0
         0          5          9         11          0
1000*lea eax,[eax*8+100]
       999        996       1000       1000          0
100000*
    322011     214676     100000     125189          0
;-------------------------------------------------------
TestF call imul eax,eax,8
      4257       4253       9000      11000          0
      6372       4253       9000      11000          0
         9          6          9         11          0
1000*imul eax,eax,8
      2997       2995       1000       1000          0
100000*
    450054     300036     100000     109375          0
;--------------------------------------------------------