title: openssl speed test using cryptodev engine along with hardware accelerator leads to spurious timing results
body: <p>I am trying to get the cryptographic performance tests for my hardware and while doing so I am using openssl speed test commands.</p>
  
  <p>First test I perform is without enabling Hardware Accelerator:</p>
  
  <pre><code>$ openssl speed -evp aes-128-cbc -engine cryptodev
  Doing aes-128-cbc for 3s on 16 size blocks: 4437806 aes-128-cbc's in 3.00s
  Doing aes-128-cbc for 3s on 64 size blocks: 1244528 aes-128-cbc's in 3.00s
  Doing aes-128-cbc for 3s on 256 size blocks: 322780 aes-128-cbc's in 3.00s
  Doing aes-128-cbc for 3s on 1024 size blocks: 81429 aes-128-cbc's in 3.00s
  Doing aes-128-cbc for 3s on 8192 size blocks: 10215 aes-128-cbc's in 3.00s
  
  OpenSSL 1.0.1j 15 Oct 2014
  built on: Thu Jul 23 18:58:46 CDT 2015
  options:bn(64,32) rc4(ptr,char) des(idx,cisc,16,long) aes(partial) idea(int) blowfish(ptr)
  compiler: arm-poky-linux-gnueabi-gcc  -march=armv7-a -mthumb-interwork -mfloat-abi=hard
  -mfpu=neon -mtune=cortex-a9 --sysroot=... -fPIC -DOPENSSL_PIC -DOPENSSL_THREADS
  -D_REENTRANT -DDSO_DLFCN -DHAVE_DLFCN_H -DL_ENDIAN   -DTERMIO  -O2 -pipe -g 
  -feliminate-unused-debug-types -Wall -Wa,--noexecstack -DHAVE_CRYPTODEV -DUSE_CRYPTODEV_DIGESTS
  -DOPENSSL_BN_ASM_MONT -DOPENSSL_BN_ASM_GF2m -DSHA1_ASM -DSHA256_ASM -DSHA512_ASM
  -DAES_ASM -DGHASH_ASM
  
  The 'numbers' are in 1000s of bytes per second processed.
  type             16 bytes     64 bytes    256 bytes   1024 bytes   8192 bytes
  aes-128-cbc      23668.30k    26549.93k    27543.89k    27794.43k    27893.76k
  </code></pre>
  
  <p>Then I enable Hardware Accelerator and get the following results:</p>
  
  <pre><code>$ openssl speed -evp aes-128-cbc -engine cryptodev
  engine "cryptodev" set.
  Doing aes-128-cbc for 3s on 16 size blocks: 39552 aes-128-cbc's in ***0.08s***
  Doing aes-128-cbc for 3s on 64 size blocks: 37060 aes-128-cbc's in ***0.05s***
  Doing aes-128-cbc for 3s on 256 size blocks: 32674 aes-128-cbc's in ***0.07s***
  Doing aes-128-cbc for 3s on 1024 size blocks: 26101 aes-128-cbc's in ***0.06s***
  Doing aes-128-cbc for 3s on 8192 size blocks: 8286 aes-128-cbc's in ***0.02s***
  
  OpenSSL 1.0.1j 15 Oct 2014
  built on: Thu Jul 23 18:58:46 CDT 2015
  options:bn(64,32) rc4(ptr,char) des(idx,cisc,16,long) aes(partial) idea(int) blowfish(ptr)
  compiler: arm-poky-linux-gnueabi-gcc  -march=armv7-a -mthumb-interwork -mfloat-abi=hard
  -mfpu=neon -mtune=cortex-a9 --sysroot=.... -fPIC -DOPENSSL_PIC -DOPENSSL_THREADS
  -D_REENTRANT -DDSO_DLFCN -DHAVE_DLFCN_H -DL_ENDIAN   -DTERMIO  -O2 -pipe -g 
  -feliminate-unused-debug-types -Wall -Wa,--noexecstack -DHAVE_CRYPTODEV -DUSE_CRYPTODEV_DIGESTS
  -DOPENSSL_BN_ASM_MONT -DOPENSSL_BN_ASM_GF2m -DSHA1_ASM -DSHA256_ASM -DSHA512_ASM
  -DAES_ASM -DGHASH_ASM
  
  The 'numbers' are in 1000s of bytes per second processed.
  type             16 bytes     64 bytes    256 bytes   1024 bytes   8192 bytes
  </code></pre>
  
  <p>My question is why is the test running for 10s of millisecond when the test is supposed to run for each block size for 3seconds. Is this a bug in OpenSSL?</p>
  
  <hr>
  
  <p>I went through the code in OpenSSL version 1.0.1j and following is what I have found:</p>
  
  <pre><code>#ifndef OPENSSL_NO_AES
          if (doit[D_CBC_128_AES])
                  {
                  for (j=0; j&lt;SIZE_NUM; j++)
                          {
                          print_message(names[D_CBC_128_AES],c[D_CBC_128_AES][j],lengths[j]);
                          Time_F(START);
                          for (count=0,run=1; COND(c[D_CBC_128_AES][j]); count++)
                                  AES_cbc_encrypt(buf,buf,
                                          (unsigned long)lengths[j],&amp;aes_ks1,
                                          iv,AES_ENCRYPT);
                          d=Time_F(STOP);
                          print_result(D_CBC_128_AES,j,count,d);
                          }
                  }
  </code></pre>
  
  <p>Here Time_F is defined as follows:</p>
  
  <pre><code>static double Time_F(int s)
          {
          return app_tminterval(s,usertime);
          }
  #endif
  </code></pre>
  
  <p>app_tminterval is defined as : </p>
  
  <pre><code>#else
  #include &lt;sys/time.h&gt;
  #include &lt;sys/resource.h&gt;
  
  double app_tminterval(int stop,int usertime)
          {
          double          ret = 0;
          struct rusage   rus;
          struct timeval  now;
          static struct timeval tmstart;
  
          if (usertime)           getrusage(RUSAGE_SELF,&amp;rus), now = rus.ru_utime;
          else                    gettimeofday(&amp;now,NULL);
  
          if (stop==TM_START)     tmstart = now;
          else                    ret = ( (now.tv_sec+now.tv_usec*1e-6)
                                          - (tmstart.tv_sec+tmstart.tv_usec*1e-6) );
  
          return ret;
          }
  #endif
  </code></pre>
  
  <p>Here on I am confused how the timings are handled that the application interval stops at less than 10ms while the actual test without hardware accelerator runs for 3s.</p>
  
  <p>Thanks</p>