### Author Topic: Code location sensitivity of timings  (Read 35414 times)

#### nidud

• Member
• Posts: 2242
##### Code location sensitivity of timings
« on: July 12, 2014, 09:15:44 PM »
This subject is from the old forum

When code is executed it is cached more like the file cache system so code/files are reused to improve performance. This is a problem when using clock timings on file access/read/copy, and also when similar algorithms of code are compared.

I don’t know exactly how this cache system works but it could be illustrated like this:
Code: [Select]
`SSE16 macro x.datainfo_&x&  db "memcpy SSE 16",0.codetest_&x& proc uses esi edi dst, src, count mov edi,dst mov esi,src mov ecx,count and ecx,-16 jz tail     @@: sub ecx,16 movdqu  xmm0,[esi+ecx] movdqu  [edi+ecx],xmm0 jnz @B mov ecx,count movdqu  xmm0,[esi+ecx-16] movdqu  [edi+ecx-16],xmm0  toend: mov eax,dst ret   tail: mov ecx,count rep stosb jmp toend db 99 dup(90h)test_&x& endpsize_&x& equ \$ - test_&x& endmSSE16 0SSE16 1SSE16 2SSE16 3SSE16 4SSE16 5`
which gives this (random) result:
Code: [Select]
`AMD Athlon(tm) II X2 245 Processor (SSE3)--------------------------------------------------- 1232712 cycles - 2048..4096  (164) A memcpy SSE 16877928  cycles - 2048..4096  (164) A memcpy SSE 161232112 cycles - 2048..4096  (164) A memcpy SSE 16878896  cycles - 2048..4096  (164) A memcpy SSE 161233148 cycles - 2048..4096  (164) A memcpy SSE 16879296  cycles - 2048..4096  (164) A memcpy SSE 161233667 cycles - 2048..4096  (164) U memcpy SSE 161016403 cycles - 2048..4096  (164) U memcpy SSE 161234898 cycles - 2048..4096  (164) U memcpy SSE 161016440 cycles - 2048..4096  (164) U memcpy SSE 161231145 cycles - 2048..4096  (164) U memcpy SSE 161019004 cycles - 2048..4096  (164) U memcpy SSE 16`
However, the result repeat itself (on the same CPU/OS), so the pattern is more consistent than random. The pattern could also be manipulated by changing the size of the proc or insert random sized code above it, so what to do?

Disable the cache during the test would be nice, if you know how, which I don't, so the simplest solution seems to be overflowing the system with garbage between tests and not have any code above the first one.

The actual size and scope of the cache may differ from various OS/CPU’s but from the result at least 512 byte. Newer systems may also be larger and more selective.

I wrote a new test-bed where a 4096 byte buffer was added to each proc to try flushing the code cache between them:
Code: [Select]
` jmp toend db 99 dup(90h)test_&x& endpsize_&x& equ \$ - test_&x&fill_&x& db PROCSIZE - size_&x& dup(0) endm`
The result now is slow and more equal so it seems to have an effect
Code: [Select]
`1229362 cycles - 2048..4096  (164) A memcpy SSE 161234968 cycles - 2048..4096  (164) A memcpy SSE 161231486 cycles - 2048..4096  (164) A memcpy SSE 161229533 cycles - 2048..4096  (164) A memcpy SSE 161235589 cycles - 2048..4096  (164) A memcpy SSE 161229830 cycles - 2048..4096  (164) A memcpy SSE 161234907 cycles - 2048..4096  (164) U memcpy SSE 161232686 cycles - 2048..4096  (164) U memcpy SSE 161231493 cycles - 2048..4096  (164) U memcpy SSE 161235533 cycles - 2048..4096  (164) U memcpy SSE 161231223 cycles - 2048..4096  (164) U memcpy SSE 161231564 cycles - 2048..4096  (164) U memcpy SSE 16`
Intel seems more selective with regards to what ends up in the cache and don't seems to fall,  at least to the same extent, for the dup(0) trap.
Code: [Select]
`Intel(R) Core(TM) i3-2367M CPU @ 1.40GHz (SSE4)------------------------------------------------------1137020 cycles - 2048..4096  (164) A memcpy SSE 161143048 cycles - 2048..4096  (164) A memcpy SSE 161155096 cycles - 2048..4096  (164) A memcpy SSE 16910107  cycles - 2048..4096  (164) A memcpy SSE 16924623  cycles - 2048..4096  (164) A memcpy SSE 16865810  cycles - 2048..4096  (164) A memcpy SSE 16980038  cycles - 2048..4096  (164) U memcpy SSE 16925320  cycles - 2048..4096  (164) U memcpy SSE 161021239 cycles - 2048..4096  (164) U memcpy SSE 16881953  cycles - 2048..4096  (164) U memcpy SSE 16965462  cycles - 2048..4096  (164) U memcpy SSE 16850145  cycles - 2048..4096  (164) U memcpy SSE 16...978347  cycles - 2048..4096  (164) A memcpy SSE 16892772  cycles - 2048..4096  (164) A memcpy SSE 16927040  cycles - 2048..4096  (164) A memcpy SSE 16917530  cycles - 2048..4096  (164) A memcpy SSE 16913893  cycles - 2048..4096  (164) A memcpy SSE 16947837  cycles - 2048..4096  (164) A memcpy SSE 16932098  cycles - 2048..4096  (164) U memcpy SSE 16925095  cycles - 2048..4096  (164) U memcpy SSE 16914343  cycles - 2048..4096  (164) U memcpy SSE 16924735  cycles - 2048..4096  (164) U memcpy SSE 16920416  cycles - 2048..4096  (164) U memcpy SSE 16922230  cycles - 2048..4096  (164) U memcpy SSE 16`
The test works well for the AMD in this case, but it should be possible to write a StuffCache proc of some size with "strange" upcode to fill up the cache with some unrelated code. Calling this proc before each test may then clear (or replace) the cache content.

#### dedndave

• Member
• Posts: 8829
• Still using Abacus 2.0
##### Re: Code location sensitivity of timings
« Reply #1 on: July 12, 2014, 10:06:49 PM »
i suppose you could use VirtualProtect to allow writes in the .CODE section
then, copy the code under test into a common code address space before executing it

http://msdn.microsoft.com/en-us/library/windows/desktop/aa366898%28v=vs.85%29.aspx

to help speed testing up a little....
you could use different counter_begin loop count values for the short and long tests
i try to select a loop count that yields about 0.5 seconds per pass

#### dedndave

• Member
• Posts: 8829
• Still using Abacus 2.0
##### Re: Code location sensitivity of timings
« Reply #2 on: July 12, 2014, 10:11:45 PM »
prescott w/htt - xp sp3
unaligned
Code: [Select]
`Intel(R) Pentium(R) 4 CPU 3.00GHz (SSE3)------------------------------------------------------4925905 cycles - 2048..4096  (164) A memcpy SSE 164933332 cycles - 2048..4096  (164) A memcpy SSE 164953203 cycles - 2048..4096  (164) A memcpy SSE 164963909 cycles - 2048..4096  (164) A memcpy SSE 164923198 cycles - 2048..4096  (164) A memcpy SSE 164941277 cycles - 2048..4096  (164) A memcpy SSE 1611502669        cycles - 2048..4096  (164) U memcpy SSE 1611487135        cycles - 2048..4096  (164) U memcpy SSE 1611564951        cycles - 2048..4096  (164) U memcpy SSE 1611570118        cycles - 2048..4096  (164) U memcpy SSE 1611497558        cycles - 2048..4096  (164) U memcpy SSE 1611526087        cycles - 2048..4096  (164) U memcpy SSE 16`
aligned
Code: [Select]
`Intel(R) Pentium(R) 4 CPU 3.00GHz (SSE3)------------------------------------------------------4935114 cycles - 2048..4096  (164) A memcpy SSE 164934727 cycles - 2048..4096  (164) A memcpy SSE 164942523 cycles - 2048..4096  (164) A memcpy SSE 164924574 cycles - 2048..4096  (164) A memcpy SSE 164924658 cycles - 2048..4096  (164) A memcpy SSE 164937763 cycles - 2048..4096  (164) A memcpy SSE 1611490869        cycles - 2048..4096  (164) U memcpy SSE 1611481780        cycles - 2048..4096  (164) U memcpy SSE 1611616596        cycles - 2048..4096  (164) U memcpy SSE 1611530420        cycles - 2048..4096  (164) U memcpy SSE 1611488318        cycles - 2048..4096  (164) U memcpy SSE 1611504392        cycles - 2048..4096  (164) U memcpy SSE 16`

#### nidud

• Member
• Posts: 2242
##### Re: Code location sensitivity of timings
« Reply #3 on: July 12, 2014, 11:04:51 PM »
Your CPU seems to be free of this problem so that makes the test result more reliable. My CPU are a bit moody.

copy the code under test into a common code address space before executing it

brilliant: a location problem solved by relocation  :lol:

I used the data segment for the code and that seems to work just fine
Code: [Select]
`.dataproc_x  db PAGESIZE dup(?)... lea edi,proc_x lea esi,test_&x& mov ecx,size_&x& rep movsb invoke  Sleep, 200 counter_begin 1000, HIGH_PRIORITY_CLASS mov edi,l1 .repeat push edi push offset source push a2 lea eax,proc_x call eax; invoke  test_&x&,a2,addr source,edi`

#### dedndave

• Member
• Posts: 8829
• Still using Abacus 2.0
##### Re: Code location sensitivity of timings
« Reply #4 on: July 12, 2014, 11:21:46 PM »
hmmm - that seems wrong
i thought you had to be in a code section to assemble instructions
guess i've never tried it - lol

but - there is nothing to prevent you from putting a proc in the code section and copying it to another address
so long as you allow writes into the affected pages with VirtualProtect and PAGE_EXECUTE_READWRITE

http://msdn.microsoft.com/en-us/library/windows/desktop/aa366786%28v=vs.85%29.aspx

#### nidud

• Member
• Posts: 2242
##### Re: Code location sensitivity of timings
« Reply #5 on: July 13, 2014, 02:28:37 AM »
I don't think it's a problem using the data segment
Code: [Select]
`.datadb "I'm in the _DATA segment ;-)",13,10,0hello_dave proc invoke crt_printf,\$ - 31 rethello_dave endp.codestart: call hello_dave`
I tried the strlen test and it worked fine
that is, this work:
Code: [Select]
`test_0  proc uses edi string:dword invoke  crt_strlen,string rettest_0  endp`but this failed:
Code: [Select]
`test_5 proc string:dword void len(string) rettest_5  endp`suspect putting it in the code segment will be the same though

#### dedndave

• Member
• Posts: 8829
• Still using Abacus 2.0
##### Re: Code location sensitivity of timings
« Reply #6 on: July 13, 2014, 03:03:15 AM »
but - most win32 CALL's are near relative
so, you'd have to translate the target addresses

but - for testing algorithm code that doesn't make any calls, like loops, etc,
the branch addresses are relative, but the target moves with the code   :P

if you wanted to use calls or invokes in movable code,
you could store the branch address and use CALL DWORD PTR lpfnFunction
or MOV EAX,Function and CALL EAX

#### nidud

• Member
• Posts: 2242
##### Re: Code location sensitivity of timings
« Reply #7 on: July 13, 2014, 04:10:22 AM »
well, here is a cute one
Code: [Select]
`ifdef MASMBASIC include \masm32\MasmBasic\MasmBasic.incelse include \masm32\include\masm32rt.incendif.686.xmminclude \masm32\macros\timers.asmPAGESIZE equ 4096.data?align 16proc_x  db PAGESIZE*4 dup(?)error dd ?.dataimmed equ 1mem dd ?mem16 dw ?,?mem8 db ?,?,?,?info_0  db "prolog",0.codetest_0  proclocal char[1]:byte rettest_0  endpsize_0  equ \$ - test_0UPCODE macro x,asm:VARARG.datainfo_&x&  db "&asm&",0.codetest_&x& proclocal char[1]:byte repeat 1000 asm endm@@: rettest_&x&  endpsize_&x&  equ \$ - test_&x& endmUPCODE 1,mov eax,immedUPCODE 2,mov eax,memUPCODE 3,mov ax,mem16UPCODE 4,mov al,mem8UPCODE 5,movzx eax,mem16UPCODE 6,movsx eax,mem8UPCODE 7,push eaxUPCODE 8,pop eaxUPCODE 9,push memUPCODE A,pop memUPCODE B,lea eax,memUPCODE C,lea eax,[eax+1]UPCODE D,add eax,immedUPCODE E,sub eax,immedUPCODE F,add eax,memUPCODE G,sub eax,memUPCODE H,@@: jmp @FUPCODE I,@@: jz @FUPCODE J,@@: jnz @FUPCODE K,test eax,eaxUPCODE L,test eax,memUPCODE M,cmp eax,eaxUPCODE N,cmp eax,memprocs equ <for x,<0,1,2,3,4,5,6,7,8,9,A,B,C,D,E,F,G,H,I,J,K,L,M,N>>;***********************************************************************************************; get the cycle count for each algotest_algo macro x,l1 push esi push edi push ebx lea edi,proc_x lea esi,test_&x& mov ecx,size_&x& rep movsb invoke  Sleep, 200 counter_begin 100, HIGH_PRIORITY_CLASS mov edi,l1 lea ebx,proc_x .repeat call ebx dec edi .until  !edi counter_end printf("%d\tcycles - %d (%4d)  %s\n",eax,l1,size_&x&,addr info_&x&) pop ebx pop edi pop esi endmvalidate_x macro x ; test if the algo actually works.. invoke test_&x& ; and spin-up the CPU.. endm;***********************************************************************************************main proc procs     validate_x x     cmp error,0     jne toend endm procs     test_algo x,32 endmtoend: retmain endp;***********************************************************************************************ShowCpu proc ; mode:DWORDCOMMENT @ Usage:  push 0, call ShowCpu  ; simple, no printing, just returns SSE level  push 1, call ShowCpu  ; prints the brand string and returns SSE level@  pushad  sub esp, 80 ; create a buffer for the brand string  mov edi, esp ; point edi to it  xor ebp, ebp  .Repeat lea eax, [ebp+80000002h] db 0Fh, 0A2h ; cpuid 80000002h-80000004h stosd mov eax, ebx stosd mov eax, ecx stosd mov eax, edx stosd inc ebp  .Until ebp>=3  push 1  pop eax  db 0Fh, 0A2h ; cpuid 1  xor ebx, ebx ; CpuSSE  xor esi, esi ; add zero plus the carry flag  bt edx, 25 ; edx bit 25, SSE1  adc ebx, esi  bt edx, 26 ; edx bit 26, SSE2  adc ebx, esi  bt ecx, esi ; ecx bit 0, SSE3  adc ebx, esi  bt ecx, 9 ; ecx bit 9, SSE4  adc ebx, esi  dec dword ptr [esp+4+32+80] ; dec mode in stack  .if Zero? mov edi, esp ; restore pointer to brand string .Repeat .Break .if byte ptr [edi]!=32 ; mode was 1, so show a string but skip leading blanks inc edi .Until 0 .if byte ptr [edi]<32 print chr\$("pre-P4") .else print edi ; CpuBrand .endif .if ebx print chr\$(32, 40, "SSE") ; info on SSE level, 40=( print str\$(ebx), 41, 13, 10 ; 41=) .endif  .endif  add esp, 80 ; discard brand buffer (after printing!)  mov [esp+32-4], ebx ; move ebx into eax stack position - returns eax to main for further use  ifdef MbBufferInit call MbBufferInit  endif  popad  ret 4ShowCpu endpstart: print " ", 13, 10 push 1 call ShowCpu ; print brand string and SSE level print "------------------------------------------------------", 13, 10 call main inkey chr\$("--- ok ---", 13) exit end start`
result:
Code: [Select]
`AMD Athlon(tm) II X2 245 Processor (SSE3)--------------------------------------------266     cycles - 32 (  10)  prolog10916   cycles - 32 (5010)  mov eax,immed16301   cycles - 32 (5010)  mov eax,mem32171   cycles - 32 (6010)  mov ax,mem1632164   cycles - 32 (5010)  mov al,mem816316   cycles - 32 (7010)  movzx eax,mem1616317   cycles - 32 (7010)  movsx eax,mem824145   cycles - 32 (1010)  push eax16353   cycles - 32 (1010)  pop eax36611   cycles - 32 (6010)  push mem36377   cycles - 32 (6010)  pop mem10900   cycles - 32 (6010)  lea eax,mem32152   cycles - 32 (3010)  lea eax,[eax+1]32146   cycles - 32 (3010)  add eax,immed32150   cycles - 32 (3010)  sub eax,immed32170   cycles - 32 (6010)  add eax,mem32171   cycles - 32 (6010)  sub eax,mem345857  cycles - 32 (2010)  @@: jmp @F10844   cycles - 32 (2010)  @@: jz @F346143  cycles - 32 (2010)  @@: jnz @F10839   cycles - 32 (2010)  test eax,eax16311   cycles - 32 (6010)  test eax,mem10839   cycles - 32 (2010)  cmp eax,eax16311   cycles - 32 (6010)  cmp eax,mem`

#### nidud

• Member
• Posts: 2242
##### Re: Code location sensitivity of timings
« Reply #8 on: July 14, 2014, 09:39:03 PM »
Instruction Timing

I parsed instructions from the Intel 8086 Family Architecture and tried to calibrate the clock cycle calculation to 1000 for one instruction, and use this as a base to compare different CPU's.

Code: [Select]
` mov cloop,1calibrate: mov eax,cloop mov count,eax counter_begin TMCOUNT, HIGH_PRIORITY_CLASS     l2: lea eax,proc_x call eax ; Instruction MOV EAX,1 dec count jnz l2 mov eax,cloop mov count,eax counter_end cmp eax,1000 jae @F add cloop,1 jmp calibrate`
Code: [Select]
`Instruction Clock Cycle Calculation1. AMD Athlon(tm) II X2 245 Processor2. Intel(R) Core(TM) i3-2367M CPU @ 1.40GHzInstr.  Operands      Size  CPU1  CPU2------------------------------------------------------proc        [0]   0.1   0.1AAA        [1]  14.1  10.3AAD        [2]  14.0   4.5AAM        [2]  36.5  54.8AAS        [1]  14.1  10.3ADC reg,reg        [2]   2.7   5.5ADC mem,reg        [6]  19.1  20.0ADC reg,mem        [6]   2.8   5.5ADC reg,imm        [3]   2.8   5.4ADC mem,imm        [7]  18.2  20.5ADC acc,imm        [3]   2.8   5.5ADD reg,reg        [2]   2.7   2.5ADD mem,reg        [6]  19.1  16.1ADD reg,mem        [6]   2.8   2.7ADD reg,imm        [3]   2.8   2.6ADD mem,imm        [7]  18.2  16.4ADD acc,imm        [3]   2.8   2.7AND reg,reg        [2]   2.7   2.5AND mem,reg        [6]  19.1  17.8AND reg,mem        [6]   2.8   2.8AND reg,imm        [3]   2.8   2.6AND mem,imm        [7]  18.2  16.5AND acc,imm        [3]   2.8   2.5BSF reg,reg        [3]  11.2   6.9BSF reg,mem        [7]   8.5   6.9BSR reg,reg        [3]  11.2   6.9BSR reg,mem        [7]   8.5   7.2BSWAP reg        [2]   2.7   2.8BT reg,imm        [4]   1.0   1.6BT mem,imm        [8]   1.6   1.6BT reg,reg        [3]   1.1   1.5BT mem,reg        [7]   5.7  14.4BTC reg,imm        [4]   5.5   2.5BTC mem,imm        [8]  19.4  16.7BTC reg,reg        [3]   5.5   2.6BTC mem,reg        [7]  14.0  17.4BTR reg,imm        [4]   5.5   2.6BTR mem,imm        [8]  19.4  16.5BTR reg,reg        [3]   5.5   2.5BTR mem,reg        [7]  22.1  17.4BTS reg,imm        [4]   5.5   2.7BTS mem,imm        [8]  19.4  16.6BTS reg,reg        [3]   5.5   2.9BTS mem,reg        [7]  22.1  17.5CALL        [5]  51.8  12.0CBW        [2]   2.7   2.6CDQ        [1]   2.8   2.9CLC        [1]   1.1   0.9CLD        [1]   2.8  11.5CMC        [1]   2.8   2.6CMP reg,reg        [2]   1.0   1.1CMP mem,reg        [6]   1.6   1.5CMP reg,mem        [6]   1.6   1.8CMP reg,imm        [3]   1.1   1.1CMP mem,imm        [7]   1.5   2.9CMP acc,imm        [3]   1.1   1.1CMP r16,imm        [4]   1.0   1.0CMP m16,imm        [8]   1.6   2.9CMP r16,r16        [3]   1.1   1.1CMP m16,r16        [7]   1.5   1.5CMPSB        [1]   8.5  11.4CMPSW        [2]   8.6  11.4CMPSD        [1]   8.5  11.4CMPXCHG reg,acc        [3]   5.7  14.4CMPXCHG mem,acc        [7]  20.5  20.7CWD        [2]   2.7   3.0CWDE        [1]   2.8   2.9DAA        [1]  16.8  11.9DAS        [1]  19.7  11.9DEC reg        [1]   2.8   2.5DEC r16        [2]   2.7   2.6DEC r08        [2]   2.7   2.5DEC mem        [6]  19.1  16.5DIV reg        [2]  50.6  52.6DIV r08        [2]  45.0  49.3DIV r16        [3]  50.5  55.7DIV mem        [6]  53.3  52.4DIV m08        [6]  44.9  49.0DIV m16        [7]  53.3  55.5ENTER        [4]  33.8  22.7IDIV reg        [2]  61.8  53.3IDIV r08        [2]  47.7  52.3IDIV r16        [3]  61.7  55.9IDIV mem        [6]  61.7  52.5IDIV m08        [6]  53.4  49.3IDIV m16        [7]  61.8  56.0IMUL reg        [2]   8.4  12.0IMUL r08        [2]   8.4   6.9IMUL r16        [3]   8.4  11.7IMUL mem        [6]   8.4  12.3IMUL m08        [6]   8.4   6.9IMUL m16        [7]   8.4  11.9IMUL reg,acc        [3]   8.4   8.1IMUL reg,acc,imm    [3]   2.9   2.8INC reg        [1]   2.8   2.6INC r16        [2]   2.7   2.6INC r08        [2]   2.7   2.5INC mem        [6]  20.0  16.4JCXZ        [3]   2.0   3.4JECXZ        [2]   2.1   7.0JMP        [2]  30.5   8.1JNZ        [2]  30.1  10.7JZ        [2]   1.0   8.0LAHF        [1]   5.7   2.9LEA acc,mem        [6]   1.0   1.4LEA reg,mem        [6]   1.0   1.4LEA acc,[acc]      [2]   2.7   2.5LEA reg,[reg]      [2]   2.7   2.5LEA acc,[acc+imm]  [3]   2.8   2.5LEA reg,[reg+imm]  [3]   2.8   2.5LEAVE*        [5]  36.6  25.6LODSB        [1]   5.7   3.5LODSW        [2]   5.7   3.5LODSD        [1]   5.7   2.9LOOP        [2]  36.8  16.5LOOPZ        [2]   8.5  19.0LOOPNZ        [2]  41.0  24.5MOV acc,imm        [5]   1.1   1.0MOV reg,imm        [5]   1.1   1.1MOV reg,mem        [6]   1.5   1.5MOV r16,m16        [7]   2.8   2.6MOVSB        [1]   8.5  11.6MOVSW        [2]   8.5  11.5MOVSD        [1]   8.5  11.4MOVSX acc,al        [3]   2.8   2.5MOVSX acc,m16        [7]   1.5   1.5MOVSX reg,cl        [3]   2.8   2.6MOVSX reg,m16        [7]   1.5   1.7MOVZX acc,al        [3]   2.8   2.5MOVZX acc,m16        [7]   1.5   1.5MOVZX reg,cl        [3]   2.8   2.5MOVZX reg,m16        [7]   1.5   1.8MUL reg        [2]   8.4  12.0MUL r16        [3]   8.4  11.5MUL r08        [2]   8.4   6.8MUL mem        [6]   8.4  12.3NEG acc        [2]   2.7   2.6NEG reg        [2]   2.7   2.5NEG mem        [6]  19.1  16.2NOP        [1]   1.0   0.9NOT reg        [2]   2.7   2.8NOT mem        [6]  19.1  16.5OR reg,reg        [2]   2.7   2.5OR mem,reg        [6]  19.1  16.1OR reg,mem        [6]   2.8   2.6OR reg,imm        [3]   2.8   2.6OR mem,imm        [7]  18.3  16.4OR acc,imm        [3]   2.8   2.5PUSH acc        [1]   2.2   2.9PUSH reg        [1]   2.2   2.9PUSH mem        [6]   3.3   2.9PUSHAD        [1]  16.9  22.8PUSHFD        [1]   8.5   3.0POP acc        [1]   1.6   1.6POP reg        [1]   1.6   1.5POP mem        [6]   3.3   3.1POPAD*        [2]  32.3  45.2POPFD*        [2]  38.9  64.7RCL acc,1        [2]   2.7   5.7RCL mem,1        [6]  19.1  21.8RCL reg,cl        [2]  11.3  17.0RCL mem,cl        [6]  20.5  28.2RCL reg,16        [3]   8.5  17.0RCL mem,16        [7]  23.3  28.2RCR acc,1        [2]   2.7   5.8RCR mem,1        [6]  19.2  21.9RCR reg,cl        [2]   8.5  14.2RCR mem,cl        [6]  21.5  25.7RCR reg,16        [3]   8.5  14.2RCR mem,16        [7]  21.6  25.9ROL acc,1        [2]   2.7   3.0ROL mem,1        [6]  19.1  17.9ROL reg,cl        [2]   2.7   5.6ROL mem,cl        [6]  19.1  16.5ROL reg,16        [3]   2.8   2.9ROL mem,16        [7]  18.2  18.2ROR acc,1        [2]   2.7   2.9ROR mem,1        [6]  19.1  18.1ROR reg,cl        [2]   2.7   5.5ROR mem,cl        [6]  19.1  16.6ROR reg,16        [3]   2.8   2.9ROR mem,16        [7]  18.2  18.5SAHF        [1]   1.1   4.7SAR acc,1        [2]   2.7   2.5SAR mem,1        [6]  19.1  16.4SAR reg,cl        [2]   2.7   5.5SAR mem,cl        [6]  19.1  16.6SAR reg,16        [3]   2.8   2.6SAR mem,16        [7]  18.2  16.5SBB reg,reg        [2]   2.7   5.5SBB mem,reg        [6]  19.1  19.7SBB reg,mem        [6]   2.8   5.4SBB reg,imm        [3]   2.8   5.4SBB acc,imm        [3]   2.8   5.7SCASB        [1]   7.1   3.5SCASW        [2]   6.7   3.5SCASD        [1]   7.1   3.5SETNB al        [3]   2.8   2.5SETNB m08        [7]   2.8   3.5SETB al        [3]   2.8   2.6SETB m08        [7]   2.8   2.9SETBE al        [3]   2.8   3.1SETBE m08        [7]   2.8   2.9SETZ al        [3]   2.8   2.9SETZ m08        [7]   2.8   2.9SETNZ al        [3]   2.8   2.6SETNZ m08        [7]   2.8   2.9SETL al        [3]   2.8   2.6SETL m08        [7]   2.8   2.9SETNL al        [3]   2.8   2.6SETNL m08        [7]   2.8   2.9SETLE al        [3]   2.8   2.8SETLE m08        [7]   2.8   2.9SETG al        [3]   2.8   2.5SETG m08        [7]   2.8   2.9SETS al        [3]   2.8   2.6SETS m08        [7]   2.8   2.9SETNS al        [3]   2.8   2.6SETNS m08        [7]   2.8   2.9SETC al        [3]   2.8   2.8SETC m08        [7]   2.8   2.9SETNC al        [3]   2.8   2.5SETNC m08        [7]   2.8   2.9SETO al        [3]   2.8   2.6SETO m08        [7]   2.8   2.9SETNO al        [3]   2.8   2.5SETNO m08        [7]   2.8   2.9SETP al        [3]   2.8   2.7SETP m08        [7]   2.8   2.9SETPE al        [3]   2.8   2.6SETPE m08        [7]   2.8   2.9SETNP al        [3]   2.8   2.8SETNP m08        [7]   2.8   2.9SETPO al        [3]   2.8   2.5SETPO m08        [7]   2.8   2.9SHL acc,1        [2]   2.7   2.6SHL mem,1        [6]  19.1  16.6SHL reg,cl        [2]   2.7   5.6SHL mem,cl        [6]  19.1  16.7SHL reg,16        [3]   2.8   2.6SHL mem,16        [7]  18.2  16.5SHR acc,1        [2]   2.7   2.6SHR mem,1        [6]  19.1  16.4SHR reg,cl        [2]   2.7   5.5SHR mem,cl        [6]  19.1  16.6SHR reg,16        [3]   2.8   2.5SHR mem,16        [7]  18.2  16.4SHLD acc,reg,16     [4]   8.5   2.5SHLD mem,reg,16     [8]  18.3  16.7SHLD acc,reg,cl     [3]   8.5   5.5SHLD mem,reg,cl     [7]  19.4  16.5SHRD acc,reg,16     [4]   8.5   2.5SHRD mem,reg,16     [8]  18.3  19.2SHRD acc,reg,cl     [3]   8.5   6.6SHRD mem,reg,cl     [7]  19.4  19.9SMSW ax        [3]   5.7  28.2SMSW m16        [7]   5.7  25.5STC        [1]   1.1   1.0STD        [1]   5.6  13.0STOSB        [1]   5.7   3.0STOSW        [2]   5.7   3.0STOSD        [1]   5.7   2.9SUB reg,reg        [2]   1.0   1.2SUB mem,reg        [6]  19.1  16.1SUB reg,mem        [6]   2.8   2.6SUB reg,imm        [3]   2.8   2.6SUB acc,imm        [3]   2.8   2.8TEST reg,reg        [2]   1.0   1.0TEST mem,reg        [6]   1.6   1.5TEST reg,mem        [6]   1.6   1.5TEST reg,imm        [6]   1.0   1.1TEST acc,imm        [5]   1.1   1.1XCHG reg,reg        [2]   2.9   5.9XCHG reg,mem        [6]  44.9  64.7XCHG mem,reg        [6]  45.7  64.8XOR reg,reg        [2]   1.1   0.8XOR mem,reg        [6]  19.9  16.0XOR reg,mem        [6]   2.8   2.9XOR reg,imm        [3]   2.8   2.6XOR mem,imm        [7]  18.2  16.2XOR acc,imm        [3]   2.8   2.6* LEAVE = LEAVE - ENTER* POPAD = POPAD - PUSHAD* POPFD = POPFD - PUSHFD`

#### nidud

• Member
• Posts: 2242
##### Re: Code location sensitivity of timings
« Reply #9 on: July 14, 2014, 10:09:22 PM »
here is the source code for the instruction calculation
however, you need ASM and JWLINK to build

#### dedndave

• Member
• Posts: 8829
• Still using Abacus 2.0
##### Re: Code location sensitivity of timings
« Reply #10 on: July 15, 2014, 02:10:35 AM »
hard to test individual instructions
so much relies on the surrounding code

#### nidud

• Member
• Posts: 2242
##### Re: Code location sensitivity of timings
« Reply #11 on: July 15, 2014, 05:46:29 AM »
hard to test individual instructions
it's actually very easy, in fact the easiest ting to test

counter_begin 1000, HIGH_PRIORITY_CLASS
repeat 1000
lea eax,[eax]
endm
counter_end

knowing the approximate time difference between instructions is also useful

mov     eax,[ebx]   ; 1
mov     [ebx],ecx   ; 2
mov     ecx,eax     ; 3 cycles
...
xchg    ecx,[ebx]   ; 50 cycles

this is the old document I have used for this

Agner Fog have a Lists of instruction latencies
Code: [Select]
`MOV     r,r     1   1  1/3 ALUMOV     r,i     1   1  1/3 ALUMOV     r8,m8   1   4  1/2 ALU, AGU...DIV     r8/m8   32  24  23 ALUDIV     r16/m16 47  24  23 ALUDIV     r32/m32 79  40  40 ALUIDIV    r8      41  17  17 ALUIDIV    r16     56  25  25 ALUIDIV    r32     88  41  41 ALUIDIV    m8      42  17  17 ALUIDIV    m16     57  25  25 ALUIDIV    m32     89  41  41 ALU`seems from this the test may not be that far off

Quote
so much relies on the surrounding code
that's true, hence the problem with the test
location, alignment, and the issue of caches

#### nidud

• Member
• Posts: 2242
##### Re: Code location sensitivity of timings
« Reply #12 on: July 16, 2014, 08:15:11 AM »
I created a new testbed where the code location problem is fixed by having a fixed location for the function (as Dave pointed out). And (as Dave pointed out) the cache problem could be solved by not linking in the functions to test. This is solved by using the –bin switch in JWASM to create a binary of the function.

#### nidud

• Member
• Posts: 2242
##### Re: Code location sensitivity of timings
« Reply #13 on: July 20, 2014, 11:43:43 PM »
It turns out the data section also have an impact on the result. The code is executed in the data? section so I now (again  :P) use the method suggested by Dave and load the functions in the code section.

In addition to this I flush the code buffer for each new function loaded using FlushInstructionCache.

readit proc uses ebx esi edi fname
invoke GetCurrentProcess

I tested some string functions using the strlen approach.

Code: [Select]
`strcpy  proc uses edi esi dst, src mov edi,dst mov esi,src mov eax,[esi] ; test the first 4 byte for zero.. lea ecx,[eax-01010101H] not eax and ecx,eax and ecx,80808080h jnz tailif 1 ; ; at this point there is at least 4 byte in src ; mov ecx,esi ; align pointer to 4 and ecx,3 mov eax,[esi] ; copy the first 4 bytes mov [edi],eax add edi,ecx ; set new offset (+0..3) add esi,ecx mov eax,[esi] ; test new offset 0..3 lea ecx,[eax-01010101H] not eax and ecx,eax and ecx,80808080h jnz @1endif align 4 ; align main loop@@: mov eax,[esi] ; copy aligned DWORD's mov [edi],eax add edi,4 add esi,4 mov eax,[esi] lea ecx,[eax-01010101H] not eax and ecx,eax and ecx,80808080h jz @B ; ; we now have at least 4 byte in the buffer ;@1: bsf ecx,ecx shr ecx,3 mov eax,[esi+ecx-3] ; copy 1..4 byte with overlap mov [edi+ecx-3],eax align 4toend:  mov eax,dst ret align 4tail: mov eax,[esi] ; for strings < 4 byte.. mov [edi],al ; 1893/1505/1602 - 3 test al,al jz toend mov [edi],ax test ah,ah jz toend shr eax,16 mov [edi+2],al test al,al jz toend mov [edi+2],ax jmp toendstrcpy  endp `here is the SSE version using the same approach
Code: [Select]
`SSE_strcpy  proc uses esi edi dst, src mov edi,dst mov esi,src ; ; test the first 16 byte for zero.. ; xorps xmm1,xmm1 ; clear xmm1 for compare movdqu  xmm0,[esi] ; get 16 byte from source pcmpeqb xmm0,xmm1 ; compare bytes pmovmskb ecx,xmm0 ; get result test ecx,ecx jnz tailif 0 mov ecx,esi ; align pointer to 16 and ecx,15 movdqu  xmm0,[esi] ; copy 16 byte movdqu  [edi],xmm0 ; add edi,ecx ; set new offset add esi,ecx pcmpeqb xmm0,xmm1 ; compare bytes pmovmskb ecx,xmm0 ; get result test ecx,ecx jnz @Zendif ; ; main loop ; align 4@@: movdqu  xmm0,[esi] ; copy movdqu  [edi],xmm0 ; add esi,16 add edi,16 pcmpeqb xmm0,xmm1 ; test for zero pmovmskb ecx,xmm0 ; test ecx,ecx jz @B@Z: bsf ecx,ecx movdqu  xmm0,[esi+ecx-16+1] movdqu  [edi+ecx-16+1],xmm0 align 4toend: mov eax,dst ret align 4 ; for strings < 16 byte..tail:if 0 bsf ecx,ecx mov [edi],ch jz toend align 4@@: mov al,[esi] mov [edi],al inc edi inc esi dec ecx jnz @B mov [edi],cl jmp toendendifif 0 bsf ecx,ecx inc ecx@@: mov al,[esi+ecx-1] mov [edi+ecx-1],al dec ecx jnz @B jmp toendendifif 0 ; 4387 - small.. bsf ecx,ecx inc ecx rep movsb jmp toendendifif 1 ; 1709 - large.. repeat  3 mov eax,[esi] mov [edi],al test al,al jz toend mov [edi],ax test ah,ah jz toend shr eax,16 mov [edi+2],al test al,al jz toend mov [edi+2],ax test ah,ah jz toend add esi,4 add edi,4 endm mov eax,[esi] mov [edi],al test al,al jz toend mov [edi],ax test ah,ah jz toend shr eax,16 mov [edi+2],al test al,al jz toend mov [edi+2],ax jmp toendendifSSE_strcpy endp`
The first run is aligned strings, second unaligned, and the last a small for the tail.

AMD Athlon(tm) II X2 245 Processor (SSE3)
STRCHR-----------------------------------
597240  cycles - 10 (  0) 0: crt_strcpy
1462096 cycles - 10 ( 37) 1: x
544466  cycles - 10 (151) 2: x
168543  cycles - 10 (251) 3: SSE2

616369  cycles - 10 (  0) 0: crt_strcpy
2062799 cycles - 10 ( 37) 1: x
561664  cycles - 10 (151) 2: x
236658  cycles - 10 (251) 3: SSE2

1850    cycles - 99 (  0) 0: crt_strcpy
5161    cycles - 99 ( 37) 1: x
1603    cycles - 99 (151) 2: x
1993    cycles - 99 (251) 3: SSE2

here is a version of strchr that use a DWORD as argument
the char needs to be populated from ‘c’ to ‘cccc’
Code: [Select]
`strchr proc uses ebx string, char mov eax,string mov ebx,char not ebx align 4lup: mov edx,[eax] lea ecx,[edx-01010101H] not edx and ecx,edx and ecx,80808080h jnz tail add eax,4 sub edx,ebx lea ecx,[edx-01010101H] not edx and ecx,edx and ecx,80808080h jz lup bsf ecx,ecx shr ecx,3 lea eax,[ecx+eax-4] align 4toend:  ret align 4tail: movzx ebx,byte ptr char cmp [eax],bx je toend inc eax cmp [eax],bx je toend inc eax cmp [eax],bx je toend inc eax cmp [eax],bx je toend xor eax,eax jmp toendstrchr endp `
timeings for strchr:
82497   cycles - (  0) 0: crt_strchr
91200   cycles - ( 29) 1: x
53679   cycles - (119) 2: 'c'
51788   cycles - (107) 3: 'cccc'

82932   cycles - (  0) 0: crt_strchr
91066   cycles - ( 29) 1: x
59540   cycles - (119) 2: 'c'
54366   cycles - (107) 3: 'cccc'

43756   cycles - (  0) 0: crt_strchr
32192   cycles - ( 29) 1: x
17620   cycles - (119) 2: 'c'
16582   cycles - (107) 3: 'cccc'

timeings for strrchr:
329384  cycles - 10 (  0) 0: crt_strrchr
330506  cycles - 10 ( 40) 1: strrchr
330109  cycles - 10 ( 40) 2: x
109653  cycles - 10 ( 66) 3: x
95977   cycles - 10 ( 72) 4: aligned
123257  cycles - 10 (112) 5: SSE

328457  cycles - 10 (  0) 0: crt_strrchr
328311  cycles - 10 ( 40) 1: strrchr
329352  cycles - 10 ( 40) 2: x
119861  cycles - 10 ( 66) 3: x
102823  cycles - 10 ( 72) 4: aligned
123251  cycles - 10 (112) 5: SSE

27515   cycles - 500 (  0) 0: crt_strrchr
26019   cycles - 500 ( 40) 1: strrchr
26019   cycles - 500 ( 40) 2: x
12508   cycles - 500 ( 66) 3: x
11510   cycles - 500 ( 72) 4: aligned
12007   cycles - 500 (112) 5: SSE

the last run is just a single "c" repeated 500 times

this is a new approach to strstr
Code: [Select]
`strstr  proc uses edx ebx dst, src mov eax,src mov ebx,[eax] mov bh,bl mov eax,ebx shl ebx,16 mov bx,ax mov eax,dst not ebx align 4lup: mov edx,[eax] lea ecx,[edx-01010101H] not edx and ecx,edx and ecx,80808080h jnz tail add eax,4 sub edx,ebx lea ecx,[edx-01010101H] not edx and ecx,edx and ecx,80808080h jz lup bsf ecx,ecx shr ecx,3 lea eax,[ecx+eax-4] xor ecx,ecx mov edx,src mov dst,eax inc eax inc edx align 4lup2: xor cl,[edx] jz found sub cl,[eax] jnz lup inc eax inc edx jmp lup2 align 4found:  mov eax,dst align 4toend:  ret align 4tail: shr ecx,8 jz @F not ebx cmp [eax],bl je @3 shr ecx,8 jz @F inc eax cmp [eax],bl je @3 shr ecx,8 jz @F inc eax cmp [eax],bl je @3@@: xor eax,eax jmp toend@3: xor ecx,ecx mov edx,src mov dst,eax inc eax inc edx align 4lup3: xor cl,[edx] jz found sub cl,[eax] jnz toend inc eax inc edx jmp lup3strstr  endp `
time for strstr (the above is 5)
537610  cycles -  10 (  0) 0: crt_strstr
918998  cycles -  10 (  0) 1: InString(1,dst,src) - 1 + dst
553673  cycles -  10 ( 46) 2: strstr
586127  cycles -  10 ( 57) 3: x
309336  cycles -  10 (148) 4: x
207128  cycles -  10 (176) 5: x

533403  cycles -  10 (  0) 0: crt_strstr
938340  cycles -  10 (  0) 1: InString(1,dst,src) - 1 + dst
554530  cycles -  10 ( 46) 2: strstr
584338  cycles -  10 ( 57) 3: x
322246  cycles -  10 (148) 4: x
215947  cycles -  10 (176) 5: x

14019   cycles - 500 (  0) 0: crt_strstr
27515   cycles - 500 (  0) 1: InString(1,dst,src) - 1 + dst
13264   cycles - 500 ( 46) 2: strstr
14518   cycles - 500 ( 57) 3: x
14518   cycles - 500 (148) 4: x
20519   cycles - 500 (176) 5: x

#### dedndave

• Member
• Posts: 8829
• Still using Abacus 2.0
##### Re: Code location sensitivity of timings
« Reply #14 on: July 21, 2014, 04:40:44 AM »
those tests run way too fast to get reliable readings

for best results:
1) bind to a single core
2) wait about 750 mS before performing any tests - this allows the system to settle
3) adjust individual loop counts so that each test pass takes about 0.5 seconds

Code: [Select]
`Intel(R) Pentium(R) 4 CPU 3.00GHz (SSE3)STRCHR-------------------------------------------170724  cycles - (  0) 0: crt_strchr172046  cycles - ( 29) 1: x70540   cycles - (119) 2: 'c'62934   cycles - (107) 3: 'cccc'170343  cycles - (  0) 0: crt_strchr167063  cycles - ( 29) 1: x89640   cycles - (119) 2: 'c'82154   cycles - (107) 3: 'cccc'240068  cycles - (  0) 0: crt_strchr87783   cycles - ( 29) 1: x25549   cycles - (119) 2: 'c'23995   cycles - (107) 3: 'cccc'--- ok ---H:\nidudString\string\strchr => strchrIntel(R) Pentium(R) 4 CPU 3.00GHz (SSE3)STRCHR-------------------------------------------209073  cycles - (  0) 0: crt_strchr221060  cycles - ( 29) 1: x80107   cycles - (119) 2: 'c'83854   cycles - (107) 3: 'cccc'198648  cycles - (  0) 0: crt_strchr211263  cycles - ( 29) 1: x106992  cycles - (119) 2: 'c'96168   cycles - (107) 3: 'cccc'253182  cycles - (  0) 0: crt_strchr84552   cycles - ( 29) 1: x26531   cycles - (119) 2: 'c'36056   cycles - (107) 3: 'cccc'`
they're all over the place   :P