vkernel observations and time

[Mike Wolman <mike@xxxxxxxxx>]

Hi,

I have been playing about with vkernels some more and have noticed
weirdness with time - which i suppose can be more than expected
running in userland.

For example if the real machine is heavily loaded u can get some odd
results when doing stuff in the vkernel:

> time sleep 10
0.000u 0.000s 0:27.45 0.0%      0+0k 2+0io 2pf+0w
>


I was interested to see the performance hit when doing things under
a vkernel. The openssl test runs about 3 times slower in the vkernel
and bonnie is about 1.5 times slower.

Some numbers:

vkernel:

Version: 1.03
vd1# time openssl speed rsa
To get the most accurate results, try to run this
program when this computer is idle.
Doing 512 bit private rsa's for 10s: 5214 512 bit private RSA's in 20.01s
Doing 512 bit public rsa's for 10s: 90278 512 bit public RSA's in 30.05s
Doing 1024 bit private rsa's for 10s: 1002 1024 bit private RSA's in 20.69s
Doing 1024 bit public rsa's for 10s: 28799 1024 bit public RSA's in 30.04s
Doing 2048 bit private rsa's for 10s: 229 2048 bit private RSA's in 29.22s
Doing 2048 bit public rsa's for 10s: 8667 2048 bit public RSA's in 30.01s
Doing 4096 bit private rsa's for 10s: 36 4096 bit private RSA's in 30.21s
Doing 4096 bit public rsa's for 10s: 2479 4096 bit public RSA's in 30.04s
OpenSSL 0.9.8e 23 Feb 2007
built on: Mon Apr  2 20:27:45 BST 2007
options:bn(64,32) md2(int) rc4(idx,int) des(ptr,risc1,16,long) aes(partial) blowfish(idx)
compiler: cc
available timing options: USE_TOD HZ=128 [sysconf value]
timing function used: getrusage
                  sign    verify    sign/s verify/s
rsa  512 bits 0.003838s 0.000333s    260.5   3004.3
rsa 1024 bits 0.020647s 0.001043s     48.4    958.6
rsa 2048 bits 0.127594s 0.003462s      7.8    288.8
rsa 4096 bits 0.839179s 0.012118s      1.2     82.5
221.309u 0.564s 3:41.90 99.9%   124+53k 12+0io 16pf+0w



Real:

dfly# time openssl speed rsa
To get the most accurate results, try to run this
program when this computer is idle.
Doing 512 bit private rsa's for 10s: 2610 512 bit private RSA's in 9.98s
Doing 512 bit public rsa's for 10s: 29827 512 bit public RSA's in 9.99s
Doing 1024 bit private rsa's for 10s: 486 1024 bit private RSA's in 10.00s
Doing 1024 bit public rsa's for 10s: 9735 1024 bit public RSA's in 10.01s
Doing 2048 bit private rsa's for 10s: 79 2048 bit private RSA's in 10.02s
Doing 2048 bit public rsa's for 10s: 2912 2048 bit public RSA's in 10.02s
Doing 4096 bit private rsa's for 10s: 12 4096 bit private RSA's in 10.00s
Doing 4096 bit public rsa's for 10s: 830 4096 bit public RSA's in 10.01s
OpenSSL 0.9.8e 23 Feb 2007
built on: Mon Apr  2 20:27:45 BST 2007
options:bn(64,32) md2(int) rc4(idx,int) des(ptr,risc1,16,long) aes(partial) blowfish(idx)
compiler: cc
available timing options: USE_TOD HZ=128 [sysconf value]
timing function used: getrusage
                  sign    verify    sign/s verify/s
rsa  512 bits 0.003822s 0.000335s    261.6   2984.9
rsa 1024 bits 0.020577s 0.001028s     48.6    972.8
rsa 2048 bits 0.126784s 0.003440s      7.9    290.7
rsa 4096 bits 0.833317s 0.012066s      1.2     82.9
81.100u 0.031s 1:21.35 99.7%    172+74k 0+0io 0pf+0w



Virtual:
> time bonnie++
Writing with putc()...done
Writing intelligently...done
Rewriting...done
Reading with getc()...done
Reading intelligently...done
start 'em...done...done...done...
Create files in sequential order...done.
Stat files in sequential order...done.
Delete files in sequential order...done.
Create files in random order...done.
Stat files in random order...done.
Delete files in random order...done.
Version  1.03       ------Sequential Output------ --Sequential Input- --Random-
                    -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- --Seeks--
Machine        Size K/sec %CP K/sec %CP K/sec %CP K/sec %CP K/sec %CP  /sec %CP
vd1.mw.office  300M 10330 100 18007 100  5532  99 11184 100 17143  99  57.7  99
                    ------Sequential Create------ --------Random Create--------
                    -Create-- --Read--- -Delete-- -Create-- --Read--- -Delete--
              files  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP
                 16  2011  99 12573  99  6832 100  2691 100 13393  99  4686 100
vd1.mw.office,300M,10330,100,18007,100,5532,99,11184,100,17143,99,57.7,99,16,2011,99,12573,99,6832,100,2691,100,13393,99,4686,100
49.217u 263.608s 5:23.28 96.7%  11+52k 922+209492io 0pf+0w


Real:
> time bonnie++
Writing with putc()...done
Writing intelligently...done
Rewriting...done
Reading with getc()...done
Reading intelligently...done
start 'em...done...done...done...
Create files in sequential order...done.
Stat files in sequential order...done.
Delete files in sequential order...done.
Create files in random order...done.
Stat files in random order...done.
Delete files in random order...done.
Version  1.03       ------Sequential Output------ --Sequential Input- --Random-
                    -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- --Seeks--
Machine        Size K/sec %CP K/sec %CP K/sec %CP K/sec %CP K/sec %CP  /sec %CP
dfly.mw.office 300M 14645  87 19324  16  6945   4 17071  87 18485   6 123.9   0
                    ------Sequential Create------ --------Random Create--------
                    -Create-- --Read--- -Delete-- -Create-- --Read--- -Delete--
              files  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP
                 16  5521  31 26859  81 14964  69 10203  57 20245  51 14779  62
dfly.mw.office,300M,14645,87,19324,16,6945,4,17071,87,18485,6,123.9,0,16,5521,31,26859,81,14964,69,10203,57,20245,51,14779,62
31.322u 13.401s 3:16.31 22.7%   17+80k 1246+9600io 4pf+0w


Mike.