openssl speed test using cryptodev engine along with hardware accelerator leads to spurious timing results
<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>