Interesting speed test

[awsdert]

A while ago I had the thought to compare the speed of a branch call (if statement) to the speed of an actual call (ie. do_whatever()) and after finally putting down Dragon Quest Builders 2 for today (cause I don't feel like trying to find a work around for a timer workbench glitch that was fixed at least partially) I decided to try it out, the below is everything involved in the test, any thoughts?

makefile:

DEF?=
OUT?=main.elf
DEF+=-D OUT=${OUT}

rebuild: clean run

run: ${OUT}
	./${OUT}

clean:
	-rm ${OUT}

${OUT}: main.c
	cc ${DEF} -o ${OUT} main.c

main.c:

#include <string.h>
#include <stdio.h>
#include <time.h>

#define _2STR( DATA ) #DATA
#define TOSTR( DATA ) _2STR( DATA ) 
#define OUT_STR TOSTR( OUT )

int call0() { return 0; }
int call1() { return 1; }
typedef int (*call_t)();

int main( int argc, char *argv[]  ) {
	int a = 0, arg_one[2] = { 0, 1 };
	call_t calls[2] = { call0, call1 };
	unsigned long long next, last, call, init = clock();
	if ( strstr( argv[0], OUT_STR ) ) a = 1;
	next = clock();
	a = arg_one[!!(strstr( argv[0], OUT_STR ))];
	call = clock();
	a = calls[!!(strstr( argv[0], OUT_STR ))]();
	last = clock();
	printf( "if = %llu\n[] = %llu\n() = %llu",
		next - init, call - next, last  - call );
	return 0;
}

output:

make run (in directory: /media/lee/ZXUIJI_1TB/github/mc)
cc  -D OUT=main.elf -o main.elf main.c
./main.elf
if = 8
[] = 0
() = 1
Compilation finished successfully.

[awsdert]

Noticed I forgot to test the switch statement so here's that:

#include <string.h>
#include <stdio.h>
#include <time.h>

#define _2STR( DATA ) #DATA
#define TOSTR( DATA ) _2STR( DATA ) 
#define OUT_STR TOSTR( OUT )

int call0() { return 0; }
int call1() { return 1; }
typedef int (*call_t)();

int main( int argc, char *argv[]  ) {
	int a = 0, arg_one[2] = { 0, 1 };
	call_t calls[2] = { call0, call1 };
	unsigned long long next, list, last, call, init = clock();
	if ( strstr( argv[0], OUT_STR ) ) a = 1;
	next = clock();
	switch (!!(strstr( argv[0], OUT_STR ))) {
	case 0: a = 0; break;
	case 1: a = 1; break;
	}
	list = clock();
	a = arg_one[!!(strstr( argv[0], OUT_STR ))];
	call = clock();
	a = calls[!!(strstr( argv[0], OUT_STR ))]();
	last = clock();
	printf( "if = %llu\n{} = %llu\n[] = %llu\n() = %llu",
		next - init, list - next, call - list, last  - call );
	return 0;
}

output:

make run (in directory: /media/lee/ZXUIJI_1TB/github/mc)
cc  -D OUT=main.elf -o main.elf main.c
./main.elf
if = 7
{} = 1
[] = 0
() = 1
Compilation finished successfully.

[flp1969]

The clock() function is imprecise. Here's a precise clock counting for your code (simplified, without the makefile):

/* test.c */
#define _GNU_SOURCE
#include <string.h>   /* _GNU_SOURCE defined just for basename() */
#include <stdio.h>
#include <inttypes.h>
#include "cycles_counting.h"

static int call0( void )
{
  return 0;
}

static int call1( void )
{
  return 1;
}

typedef int ( *call_t )( void );

int main( int argc, char *argv[] )
{
  int a = 0, arg_one[2] = { 0, 1 };
  call_t calls[2] = { call0, call1 };
  counter_T next, list, last, call;
  char *OUT_STR;

  // if there is an argument, use an gibberish string to compare.
  if ( *( argv + 1 ) )
    OUT_STR = "njn4jr4$%#";  // gibberish!
  else
    OUT_STR = basename( *argv );

  next = BEGIN_TSC();
  if ( strstr( *argv, OUT_STR ) )
    a = 1;
  END_TSC( &next );

  list = BEGIN_TSC();
  switch ( !!( strstr( *argv, OUT_STR ) ) )
  {
    case 0:
      a = 0;
      break;

    case 1:
      a = 1;
      break;
  }
  END_TSC( &list );

  call = BEGIN_TSC();
  a = arg_one[!!( strstr( *argv, OUT_STR ) )];
  END_TSC( &call );

  last = BEGIN_TSC();
  a = calls[!!( strstr( *argv, OUT_STR ) )]();
  END_TSC( &last );

  printf( "if = %" PRIu64 "\n{} = %" PRIu64 "\n[] = %" PRIu64 "\n() = %" PRIu64 "\n",
          next, list, call, last );
}

/* cycles_counting.h */
#ifndef CYCLES_COUNTING_H__
#define CYCLES_COUNTING_H__

typedef volatile uint64_t counter_T;

#if defined(__x86_64__)
  inline counter_T BEGIN_TSC( void )
  {
    uint32_t a, d;

    __asm__ __volatile__ (
# ifdef SYNC_MEM
      "mfence\n\t"
# endif
      "xorl %%eax,%%eax\n\t"
      "cpuid\n\t"
      "rdtsc" : "=a" (a), "=d" (d) :: "%rbx", "%rcx"
    );

    return a | ((uint64_t)d << 32);
  }

  inline void END_TSC( counter_T *cptr )
  {
    uint32_t a, d;

    __asm__ __volatile__ (
      "rdtscp" : "=a" (a), "=d" (d) :: "%rcx"
    );

    *cptr = (a | ((uint64_t)d << 32)) - *cptr;;
  }
#elif defined(__i386__)
  inline counter_T BEGIN_TSC( void )
  {
    uint32_t a, d;

    __asm__ __volatile__ (
# ifdef __SSE2__
#   ifdef SYNC_MEM
      "mfence\n\t"
#   endif
# endif
      "xorl %%eax,%%eax\n\t"
      "cpuid\n\t"
      "rdtsc" : "=a" (a), "=d" (d) :: "%ebx", "%ecx"
    );

    return a | ((uint64_t)d << 32);
  }

  inline void END_TSC( counter_T *cptr )
  {
    uint32_t a, d;

    __asm__ __volatile__ (
      "rdtscp" : "=a" (a), "=d" (d) :: "%ecx"
    );

    *cptr = (a | ((uint64_t)d << 32)) - *cptr;
  }
#else
# error i386 or x86-64 only.
#endif

#endif

My results, compiling with optimization:

$ cc -O2 -o test test.c
$ ./test
if = 24
{} = 24
[] = 24
() = 2496
$ ./test gibberish
if = 24
{} = 24
[] = 24
() = 363

These are counting in REAL clock cycles (not considering cache misses, page faults, interrupts, DMA, and other unpredicted effects).

[laserlight]

You're dealing with something that's far more complex than it looks, e.g., in practice, how well one fares versus another can depend on things like what's already in cache/memory, instructions being cached, branch prediction, function inlining, what optimisations a compiler might apply, that kind of thing.

Did you compile at a high optimisation level? Try rearranging the tests and see if your result is still consistent.

[awsdert]

Wow, way more than I expected for just a simple speed test, anyway I'll start by responding to the easier one, this one:

You're dealing with something that's far more complex than it looks, e.g., in practice, how well one fares versus another can depend on things like what's already in cache/memory, instructions being cached, branch prediction, function inlining, what optimisations a compiler might apply, that kind of thing.

Since I'm comparing which pathing is faster let's just stick with in cache as the assumption since the data set is small enough that it will probably be put there, as you can see by the makefile I used default optimizations

Did you compile at a high optimisation level? Try rearranging the tests and see if your result is still consistent.

I just attempted it after moving everything to function calls for simplicity (internal clock values used) I then made a for loop (for 10 times) and pick a random one of these functions to call so that should give valid results, as far as flp's clock code goes I will give it a try after I finished analyzing it to understand it, anyway reason I'm doing this is 'cause I'm still working on making my own compiler under MIT license, specifically I want it to be as portable as possible and support japanese characters as I'm learning japanese also and using it in code will help me remember them. Also later I will attempt my own personal dragon quest builders style project (cause I hate being restricted to just 2-300 max HP despite potential for 999 or even 9999 since there is still space in that 16bit value, although probably 32bit used)

[awsdert]

Alright here's my new test code:

#include <string.h>
#include <stdio.h>
#include <stdlib.h>
#include <inttypes.h>
#include <time.h>
 
#define _2STR( DATA ) #DATA
#define TOSTR( DATA ) _2STR( DATA ) 
#define OUT_STR TOSTR( OUT )
 
int call0() { return 0; }
int call1() { return 1; }
typedef int (*call_t)();

typedef volatile uint64_t counter_t;
#if defined( __x86_64__ ) || defined( __i386__ )
counter_t INIT_TSC( void ) {
	uint32_t a, d;
	__asm__ __volatile__ (
#if (defined(__x86_64__) || defined( __SSE2__ )) & defined( SYNC_MEM )
	"mfence\n\t"
#endif
	"xorl %%eax,%%eax\n\t"
	"cpuid\n\t"
	"rdtsc" : "=a" (a), "=d" (d) ::
#ifdef __x86_64__
		"%rbx", "%rcx"
#else
		"%ebx", "%ecx"
#endif
	);
	return a | ((uint64_t)d << 32);
}
void KILL_TSC( counter_t *cptr )
{
	uint32_t a, d;
	__asm__ __volatile__ (
		"rdtscp" : "=a" (a), "=d" (d) ::
#ifdef _x86_64__
		"%rcx"
#else
		"%ecx"
#endif
	);
	*cptr = (a | ((uint64_t)d << 32)) - *cptr;;
}
#else
#define INIT_TSC() time(NULL)
#define KILL_TSC(P) *(P) = time(NULL)
#endif

typedef struct main_ctx {
	time_t timed;
	char *arg0;
	_Bool name_included;
	const char *name;
	counter_t init;
	counter_t stop;
	counter_t tick;
} main_ctx_t;

void print_timed( main_ctx_t *ctx ) {
	KILL_TSC(&ctx->stop);
	ctx->tick = clock();
#define VAL(N) N " = %020" PRIu64
	(void)printf("Timed Action for '%s':"
		VAL("init") VAL(", stop") VAL(", diff") VAL(", tick") "\n",
		ctx->name, ctx->init, ctx->stop, ctx->stop - ctx->init, ctx->tick
	);
#undef VAL
}

int try_query( main_ctx_t *ctx ) {
	int a;
	counter_t init = INIT_TSC();
	if ( ctx->name_included ) a = 1; else a = 0;
	ctx->name = "if";
	print_timed(ctx);
	return a;
}
int try_switch( main_ctx_t *ctx ) {
	int a;
	counter_t init = INIT_TSC();
	switch ( ctx->name_included ) {
	case 0: a = 0; break;
	case 1: a = 1; break;
	}
	ctx->name = "{}";
	print_timed(ctx);
	return a;
}
int try_array( main_ctx_t *ctx ) {
	int a;
	int array[2] = { 0, 1 };
	counter_t init = INIT_TSC();
	a = array[ctx->name_included];
	ctx->name = "[]";
	print_timed(ctx);
	return a;
}
int try_calls( main_ctx_t *ctx ) {
	int a;
	call_t calls[2] = { call0, call1 };
	counter_t init = INIT_TSC();
	a = calls[ctx->name_included]();
	ctx->name = "()";
	print_timed(ctx);
	return a;
}
typedef int (*try_test_t)( main_ctx_t *ctx );

int main( int argc, char *argv[]  ) {
		main_ctx_t ctx = {0};
    int a = 0, j;
    try_test_t tests[4] =
			{ try_query, try_switch, try_array, try_calls };
		ctx.timed = time(&ctx.timed);
    ctx.name_included =  !!(strstr( argv[0], OUT_STR ));
    try_query( &ctx );
    try_switch( &ctx );
    try_array( &ctx );
    try_calls( &ctx );
    for ( a = 0; a < 10; ++a ) {
			j = 4;
			j = rand_r(&j);
			if ( j >= 4 ) j = 3;
			if ( j < 0 ) j = 0;
			tests[j]( &ctx );
		}
    return 0;
}

and the results:

make run (in directory: /media/lee/ZXUIJI_1TB/github/mc)
cc  -D OUT=main.elf -o main.elf main.c
./main.elf
Timed Action for 'if':init = 00000000000000000000, stop = 00000024923091304583, diff = 00000024923091304583, tick = 00000000000000000374
Timed Action for '{}':init = 00000000000000000000, stop = 00000000000000221523, diff = 00000000000000221523, tick = 00000000000000000432
Timed Action for '[]':init = 00000000000000000000, stop = 00000024923091310198, diff = 00000024923091310198, tick = 00000000000000000434
Timed Action for '()':init = 00000000000000000000, stop = 00000000000000225565, diff = 00000000000000225565, tick = 00000000000000000435
Timed Action for '()':init = 00000000000000000000, stop = 00000024923091314421, diff = 00000024923091314421, tick = 00000000000000000436
Timed Action for '()':init = 00000000000000000000, stop = 00000000000000229362, diff = 00000000000000229362, tick = 00000000000000000437
Timed Action for '()':init = 00000000000000000000, stop = 00000024923091317998, diff = 00000024923091317998, tick = 00000000000000000438
Timed Action for '()':init = 00000000000000000000, stop = 00000000000000233019, diff = 00000000000000233019, tick = 00000000000000000439
Timed Action for '()':init = 00000000000000000000, stop = 00000024923091321502, diff = 00000024923091321502, tick = 00000000000000000440
Timed Action for '()':init = 00000000000000000000, stop = 00000000000000236566, diff = 00000000000000236566, tick = 00000000000000000441
Timed Action for '()':init = 00000000000000000000, stop = 00000024923091325009, diff = 00000024923091325009, tick = 00000000000000000442
Timed Action for '()':init = 00000000000000000000, stop = 00000000000000240170, diff = 00000000000000240170, tick = 00000000000000000443
Timed Action for '()':init = 00000000000000000000, stop = 00000024923091328506, diff = 00000024923091328506, tick = 00000000000000000444
Timed Action for '()':init = 00000000000000000000, stop = 00000000000000243772, diff = 00000000000000243772, tick = 00000000000000000445
Compilation finished successfully.

I don't think I fully understand that mfence opcode though (didn't bother looking at cpuid and rdtsc/p, rdtsc/p looks pretty straight forward and I'm guessing cpuid is to ensure reading from cpu values)

[flp1969]

I don't think I fully understand that mfence opcode though (didn't bother looking at cpuid and rdtsc/p, rdtsc/p looks pretty straight forward and I'm guessing cpuid is to ensure reading from cpu values)

CPUID is there to garantee the processor is serialized (all pending instructions in execution units will be executed before callind RDTSC). MFENCE (if you use it) is there to garantee that all pre-cached storage will be read/writen to cache...

RDTSC is really straightforward: It reads the TimeStamp Counter. RDTSCP is analogous, but it reads a MSR causing serialization... The difference between this and CPUID? From Intel Instruction Set Manual:

The RDTSCP instruction waits until all previous instructions have been executed before reading the counter.
However, subsequent instructions may begin execution before the read operation is performed

You can use CPUID as in BEGIN_TSC() inline function to serialize before RDTSC if you wish...

BUT... This method is not precise either (is better than use clock()!). As I said before, cache, page faults, interruptions, DMA, etc, affects your code execution...

[awsdert]

ah so that's what various docs meant by serialization, as far as those examples of outside factors I guess that would certainly be true for real world code but for this test scenario I can't see them as being likely to get involved since I have 12GB RAM and a quadcore AMD64 CPU, with that combination combined with the smallness of the test app it is not a concern, I will consider them once I start using the functions to test other more serious stuff (such as define read/writes or expression handling). Also thanks for clearing up my understanding of cpuid and mfence

Edit 1: After correcting some faults in my code I noticed (like using local init variable instead of ctx->init) and adding a cpuid instruction before the rdtscp instruction as was suggested I re-ran the test and got some easier to read results, calling a function still turned out to be faster than using the if statement so I think from now on I will design my code around that concept instead

make run (in directory: /media/lee/ZXUIJI_1TB/github/mc)
cc  -D OUT=main.elf -o main.elf main.c
./main.elf
Timed Action for 'if':init = 00000005663080468322, stop = 00000005663080468852, diff = 00000000000000000530, tick = 00000000000000000795
Timed Action for '{}':init = 00000005663080900284, stop = 00000005663080900841, diff = 00000000000000000557, tick = 00000000000000000909
Timed Action for '[]':init = 00000005663080912185, stop = 00000005663080912683, diff = 00000000000000000498, tick = 00000000000000000911
Timed Action for '()':init = 00000005663080921469, stop = 00000005663080921992, diff = 00000000000000000523, tick = 00000000000000000914
Timed Action for '()':init = 00000005663080931107, stop = 00000005663080931592, diff = 00000000000000000485, tick = 00000000000000000917
Timed Action for '()':init = 00000005663080939768, stop = 00000005663080940253, diff = 00000000000000000485, tick = 00000000000000000919
Timed Action for '()':init = 00000005663080947959, stop = 00000005663080948444, diff = 00000000000000000485, tick = 00000000000000000921
Timed Action for '()':init = 00000005663080956129, stop = 00000005663080956614, diff = 00000000000000000485, tick = 00000000000000000924
Timed Action for '()':init = 00000005663080964265, stop = 00000005663080964750, diff = 00000000000000000485, tick = 00000000000000000926
Timed Action for '()':init = 00000005663080972409, stop = 00000005663080972894, diff = 00000000000000000485, tick = 00000000000000000928
Timed Action for '()':init = 00000005663080981168, stop = 00000005663080981653, diff = 00000000000000000485, tick = 00000000000000000930
Timed Action for '()':init = 00000005663080989384, stop = 00000005663080989869, diff = 00000000000000000485, tick = 00000000000000000933
Timed Action for '()':init = 00000005663080997783, stop = 00000005663080998268, diff = 00000000000000000485, tick = 00000000000000000935
Timed Action for '()':init = 00000005663081006020, stop = 00000005663081006505, diff = 00000000000000000485, tick = 00000000000000000937
Compilation finished successfully.

Edit 2: Finally fixed my lack of actual random output in that loop of mine with the help of this macro:

// https://www.geeksforgeeks.org/generating-random-number-range-c/
#define BETWEEN( MIN, MAX ) ((rand() % ((MAX) - (MIN) + 1)) + (MIN))

Output:

make run (in directory: /media/lee/ZXUIJI_1TB/github/mc)
cc  -D OUT=main.elf -o main.elf main.c
./main.elf
Timed Action for 'if':init = 00000010074041966702, stop = 00000010074041967059, diff = 00000000000000000357, tick = 00000000000000000625
Timed Action for '{}':init = 00000010074042272021, stop = 00000010074042272391, diff = 00000000000000000370, tick = 00000000000000000705
Timed Action for '[]':init = 00000010074042280559, stop = 00000010074042280917, diff = 00000000000000000358, tick = 00000000000000000707
Timed Action for '()':init = 00000010074042286732, stop = 00000010074042287085, diff = 00000000000000000353, tick = 00000000000000000709
Timed Action for '()':init = 00000010074042294216, stop = 00000010074042294564, diff = 00000000000000000348, tick = 00000000000000000711
Timed Action for '[]':init = 00000010074042300333, stop = 00000010074042300742, diff = 00000000000000000409, tick = 00000000000000000712
Timed Action for '{}':init = 00000010074042306685, stop = 00000010074042307092, diff = 00000000000000000407, tick = 00000000000000000714
Timed Action for '()':init = 00000010074042312691, stop = 00000010074042313039, diff = 00000000000000000348, tick = 00000000000000000716
Timed Action for '{}':init = 00000010074042318608, stop = 00000010074042319015, diff = 00000000000000000407, tick = 00000000000000000717
Timed Action for '()':init = 00000010074042324551, stop = 00000010074042324899, diff = 00000000000000000348, tick = 00000000000000000719
Timed Action for '[]':init = 00000010074042330631, stop = 00000010074042331039, diff = 00000000000000000408, tick = 00000000000000000721
Timed Action for 'if':init = 00000010074042336775, stop = 00000010074042337121, diff = 00000000000000000346, tick = 00000000000000000722
Timed Action for '{}':init = 00000010074042342676, stop = 00000010074042343084, diff = 00000000000000000408, tick = 00000000000000000724
Timed Action for '{}':init = 00000010074042348442, stop = 00000010074042348849, diff = 00000000000000000407, tick = 00000000000000000726
Compilation finished successfully.

[awsdert]

I forgot to test the conditionals

var = exp ? true : false;

so here's the results including that now:

make run (in directory: /media/lee/ZXUIJI_1TB/github/mc)
cc  -D OUT=main.elf -o main.elf main.c
./main.elf
Timed Action for '?:':init = 00000012663240650676, stop = 00000012663240651032, diff = 00000000000000000356, tick = 00000000000000000516
Timed Action for 'if':init = 00000012663240859253, stop = 00000012663240859515, diff = 00000000000000000262, tick = 00000000000000000570
Timed Action for '{}':init = 00000012663240865213, stop = 00000012663240865453, diff = 00000000000000000240, tick = 00000000000000000572
Timed Action for '[]':init = 00000012663240869677, stop = 00000012663240869918, diff = 00000000000000000241, tick = 00000000000000000573
Timed Action for '()':init = 00000012663240873490, stop = 00000012663240873751, diff = 00000000000000000261, tick = 00000000000000000574
Timed Action for '[]':init = 00000012663240879076, stop = 00000012663240879309, diff = 00000000000000000233, tick = 00000000000000000575
Timed Action for 'if':init = 00000012663240882887, stop = 00000012663240883163, diff = 00000000000000000276, tick = 00000000000000000576
Timed Action for '{}':init = 00000012663240886832, stop = 00000012663240887066, diff = 00000000000000000234, tick = 00000000000000000577
Timed Action for '?:':init = 00000012663240890837, stop = 00000012663240891069, diff = 00000000000000000232, tick = 00000000000000000579
Timed Action for '[]':init = 00000012663240894736, stop = 00000012663240894965, diff = 00000000000000000229, tick = 00000000000000000580
Timed Action for '?:':init = 00000012663240898913, stop = 00000012663240899144, diff = 00000000000000000231, tick = 00000000000000000581
Timed Action for 'if':init = 00000012663240903092, stop = 00000012663240903327, diff = 00000000000000000235, tick = 00000000000000000582
Timed Action for '{}':init = 00000012663240907093, stop = 00000012663240907367, diff = 00000000000000000274, tick = 00000000000000000583
Timed Action for '()':init = 00000012663240911000, stop = 00000012663240911232, diff = 00000000000000000232, tick = 00000000000000000584
Timed Action for 'if':init = 00000012663240915010, stop = 00000012663240915287, diff = 00000000000000000277, tick = 00000000000000000585
Compilation finished successfully.

I actually tested it to see if I could use it instead of storing a pointer to the functions I want to call, seems to be on relatively equal footing there aside from the first call

[awsdert]

Seems complex code likes the if syntax better than conditional syntax when it comes to speed as noted via this thread
Manually reading an integer literal

[Hodor]

Seems complex code likes the if syntax better than conditional syntax when it comes to speed as noted via this thread
Manually reading an integer literal

Stop trying to out think the compiler. Write code that's clear to read (for humans) and not what you think might be faster given a particular compiler (or what a given compiler A produces faster code for... compiler B might do the exact opposite). Geez.