mini benchmark vtim formatting
Nils Goroll
slink at schokola.de
Fri Oct 5 11:15:13 UTC 2018
Hi,
having been asked at VDD to do so, I have just committed a trivial
micro-benchmark to vtim.c to get an idea about the overhead of our favorite %.6f
format for timestamps.
I have also changed vtim.c to represent timestamps as uint64_t with compile time
adjustable base (see attached, only tested on Linux and Solaris) to get an idea
about the impact of variations of the representation.
I have used this to run tests on my Linux laptop (i7-8650U, debian 9.5) and our
SmartOS vtest machine (E5645, joyent_20180412T025853Z). Sample runs at the
bottom of this email.
>From these simple tests, I'd draw the following conclusions:
* when representing time as a double, formatting a timestamp is now much more
expensive (7x - 20x) than retrieving the time
* On Linux, formatting an integer can be ~7x more efficient than formatting a
double
- On Solaris, the difference is not that relevant
* If we went for integers, formatting timestamps as microseconds using %06lu
would probably be the best idea in place of the %.6f we use now.
Getting a decimal point to the right place implies an overhead of ~50%
* It seems that the time unit is not that relevant for these tests.
So, for simplicity, we could go for nanoseconds since epoch, which will
wrap 22nd Juli 2554
8th of microseconds would last until the year 75039, 16th of microseconds
until the year 38503.
For other operations, the difference may be relevant.
If you are interested, please re-run the tests on your environment.
* put attached files into lib/libvarnish and cd there
* compile
cc -o double -DTEST_DRIVER -I../.. -I../../include vtim.c vas.c -lm
cc -o uint_nsec -DTEST_DRIVER -I../.. -I../../include vtim_uint64.c vas.c -lm
cc -o uint_usec8 -DUSEC8 -DTEST_DRIVER -I../.. -I../../include vtim_uint64.c
vas.c -lm
* check if the test is working by calling the files double, uint_nsec,
uint_usec8 multiple times
* to just run the benchmark, simply add exit(0); after the call to bench();
Nils
-
Linux 64bit vtim.c bench() (using double):
real: 0.002355s / 100000 = 23.550987ns - tst val 153872535444035.562500
mono: 0.002340s / 100000 = 23.398399ns - tst val 321355539.077222
3213.556566
printf: 0.052920s / 100000 = 529.201860ns - tst val 4600000.000000
real: 0.002430s / 100000 = 24.297237ns - tst val 153872613340620.625000
mono: 0.002403s / 100000 = 24.032593ns - tst val 399251852.306332
3992.519728
printf: 0.049563s / 100000 = 495.630440ns - tst val 4600000.000000
real: 0.002114s / 100000 = 21.140575ns - tst val 153872614232321.562500
mono: 0.002092s / 100000 = 20.923615ns - tst val 400143257.413292
4001.433621
printf: 0.042647s / 100000 = 426.469020ns - tst val 4600000.000000
real: 0.002372s / 100000 = 23.720264ns - tst val 153872614985513.750000
mono: 0.002320s / 100000 = 23.198128ns - tst val 400896625.035718
4008.967414
printf: 0.045916s / 100000 = 459.159040ns - tst val 4600000.000000
real: 0.002112s / 100000 = 21.121502ns - tst val 153872615984353.781250
mono: 0.002082s / 100000 = 20.818710ns - tst val 401895453.048254
4018.955575
printf: 0.047332s / 100000 = 473.323980ns - tst val 4600000.000000
SmartOS 64bit vtim.c bench() (using double):
real: 0.004298s / 100000 = 42.984486ns - tst val 153873606800016.531250
mono: 0.004646s / 100000 = 46.463013ns - tst val 367368452718.765625
3673684.529523
printf: 0.029450s / 100000 = 294.502801ns - tst val 5400000.000000
real: 0.004205s / 100000 = 42.052269ns - tst val 153873606804744.531250
mono: 0.004667s / 100000 = 46.672821ns - tst val 367368456995.426270
3673684.572306
printf: 0.029131s / 100000 = 291.305990ns - tst val 5400000.000000
real: 0.004536s / 100000 = 45.359135ns - tst val 153873606809034.250000
mono: 0.004646s / 100000 = 46.455860ns - tst val 367368461336.529968
3673684.615702
printf: 0.030426s / 100000 = 304.255509ns - tst val 5400000.000000
real: 0.004203s / 100000 = 42.033195ns - tst val 153873606813494.593750
mono: 0.004645s / 100000 = 46.453476ns - tst val 367368465704.614807
3673684.659382
printf: 0.030404s / 100000 = 304.044960ns - tst val 5400000.000000
real: 0.004316s / 100000 = 43.158531ns - tst val 153873606817572.531250
mono: 0.005237s / 100000 = 52.371025ns - tst val 367368470172.232300
3673684.704187
printf: 0.030035s / 100000 = 300.351870ns - tst val 5400000.000000
Linux 64bit vtim_uint64.c 1/8th microseconds // -DUSEC8
1 vt is 125 nsec
real: 5622500ns / 100000 = 56ns - tst val 13497331302862915168
mono: 4339000ns / 100000 = 43ns - tst val 4727458592442259
%lu.%06lu: 19220125ns / 100000 = 192ns - tst val 4600000 5909.325416
%lu.%06lu diff: 13590500ns / 100000 = 135ns - tst val 4600000 5909.344645
%06lu: 8187375ns / 100000 = 81ns - tst val 5100000 5909358251
2printf: 16292125ns / 100000 = 162ns - tst val 4600000 5909.366441
1 vt is 125 nsec
real: 2274000ns / 100000 = 22ns - tst val 13497331355470056350
mono: 2251625ns / 100000 = 22ns - tst val 4727509533282433
%lu.%06lu: 9097500ns / 100000 = 90ns - tst val 4600000 5909.388035
%lu.%06lu diff: 9202125ns / 100000 = 92ns - tst val 4600000 5909.397135
%06lu: 6447375ns / 100000 = 64ns - tst val 5200000 5909406344
2printf: 13142625ns / 100000 = 131ns - tst val 4600000 5909.412795
1 vt is 125 nsec
real: 1907500ns / 100000 = 19ns - tst val 13497331389852240279
mono: 1877000ns / 100000 = 18ns - tst val 4727543608271599
%lu.%06lu: 8324750ns / 100000 = 83ns - tst val 4600000 5909.430450
%lu.%06lu diff: 8124625ns / 100000 = 81ns - tst val 4600000 5909.438780
%06lu: 6225125ns / 100000 = 62ns - tst val 5200000 5909446908
2printf: 13080375ns / 100000 = 130ns - tst val 4600000 5909.453136
1 vt is 125 nsec
real: 1959875ns / 100000 = 19ns - tst val 13497331422083304059
mono: 1884875ns / 100000 = 18ns - tst val 4727575868482680
%lu.%06lu: 8308375ns / 100000 = 83ns - tst val 4600000 5909.470781
%lu.%06lu diff: 8274500ns / 100000 = 82ns - tst val 4600000 5909.479092
%06lu: 6325750ns / 100000 = 63ns - tst val 5200000 5909487370
2printf: 13769875ns / 100000 = 137ns - tst val 4600000 5909.493698
1 vt is 125 nsec
real: 1937500ns / 100000 = 19ns - tst val 13497331455138718337
mono: 1867125ns / 100000 = 18ns - tst val 4727608894328593
%lu.%06lu: 8296875ns / 100000 = 82ns - tst val 4600000 5909.512054
%lu.%06lu diff: 8097250ns / 100000 = 80ns - tst val 4600000 5909.520355
%06lu: 6224000ns / 100000 = 62ns - tst val 5300000 5909528454
2printf: 13066250ns / 100000 = 130ns - tst val 4600000 5909.534684
SmartOS 64bit vtim_uint64.c 1/8th microseconds // -DUSEC8
1 vt is 125 nsec
real: 6644625ns / 100000 = 66ns - tst val 13504082175283590570
mono: 6616875ns / 100000 = 66ns - tst val 2939284261243902679
%lu.%06lu: 42185250ns / 100000 = 421ns - tst val 4900000 3674105.329936
%lu.%06lu diff: 34464375ns / 100000 = 344ns - tst val 4900000 3674105.372162
%06lu: 23622875ns / 100000 = 236ns - tst val 4900000 3674105406659
2printf: 75176125ns / 100000 = 751ns - tst val 4900000 3674105.430309
1 vt is 125 nsec
real: 5383500ns / 100000 = 53ns - tst val 13504082332109593912
mono: 6566000ns / 100000 = 65ns - tst val 2939284417340253304
%lu.%06lu: 32064000ns / 100000 = 320ns - tst val 4900000 3674105.525042
%lu.%06lu diff: 37663625ns / 100000 = 376ns - tst val 4900000 3674105.557138
%06lu: 22300375ns / 100000 = 223ns - tst val 4900000 3674105594834
2printf: 59873000ns / 100000 = 598ns - tst val 4900000 3674105.617163
1 vt is 125 nsec
real: 7150000ns / 100000 = 71ns - tst val 13504082468470874911
mono: 6997000ns / 100000 = 69ns - tst val 2939284554928560611
%lu.%06lu: 32293375ns / 100000 = 322ns - tst val 4900000 3674105.697104
%lu.%06lu diff: 34067500ns / 100000 = 340ns - tst val 4900000 3674105.729432
%06lu: 31384000ns / 100000 = 313ns - tst val 4900000 3674105763544
2printf: 73468000ns / 100000 = 734ns - tst val 4900000 3674105.794971
1 vt is 125 nsec
real: 6757375ns / 100000 = 67ns - tst val 13504082621801712857
mono: 6683125ns / 100000 = 66ns - tst val 2939284707852278262
%lu.%06lu: 37656125ns / 100000 = 376ns - tst val 4900000 3674105.888192
%lu.%06lu diff: 37080375ns / 100000 = 370ns - tst val 4900000 3674105.925882
%06lu: 27612500ns / 100000 = 276ns - tst val 4900000 3674105962996
2printf: 83942000ns / 100000 = 839ns - tst val 4900000 3674105.990650
1 vt is 125 nsec
real: 4760125ns / 100000 = 47ns - tst val 13504082785812051427
mono: 4868625ns / 100000 = 48ns - tst val 2939284870314396946
%lu.%06lu: 27153875ns / 100000 = 271ns - tst val 4900000 3674106.090366
%lu.%06lu diff: 29272750ns / 100000 = 292ns - tst val 4900000 3674106.117556
%06lu: 21217625ns / 100000 = 212ns - tst val 4900000 3674106146859
2printf: 59721875ns / 100000 = 597ns - tst val 4900000 3674106.168103
Linux 64bit vtim_uint64.c nanoseconds
1 vt is 1 nsec
real: 6471658ns / 100000 = 64ns - tst val 8522114927877580954
mono: 3506494ns / 100000 = 35ns - tst val 600345064167526557
%lu.%06lu: 15612387ns / 100000 = 156ns - tst val 4600000 6003.452480
%lu.%06lu diff: 13278403ns / 100000 = 132ns - tst val 4600000 6003.468104
%06lu: 8211335ns / 100000 = 82ns - tst val 5200000 6003481394
2printf: 16426218ns / 100000 = 164ns - tst val 4600000 6003.489609
1 vt is 1 nsec
real: 2177350ns / 100000 = 21ns - tst val 8522121055739749055
mono: 2115589ns / 100000 = 21ns - tst val 600351007284215988
%lu.%06lu: 9808669ns / 100000 = 98ns - tst val 4600000 6003.511130
%lu.%06lu diff: 8982234ns / 100000 = 89ns - tst val 4600000 6003.520941
%06lu: 6887452ns / 100000 = 68ns - tst val 5300000 6003529926
2printf: 13647040ns / 100000 = 136ns - tst val 4600000 6003.536821
1 vt is 1 nsec
real: 1823293ns / 100000 = 18ns - tst val 8522125472179529458
mono: 1786902ns / 100000 = 17ns - tst val 600355389907576048
%lu.%06lu: 8402054ns / 100000 = 84ns - tst val 4600000 6003.554793
%lu.%06lu diff: 8520702ns / 100000 = 85ns - tst val 4600000 6003.563198
%06lu: 6249130ns / 100000 = 62ns - tst val 5300000 6003571724
2printf: 13035186ns / 100000 = 130ns - tst val 4600000 6003.577975
1 vt is 1 nsec
real: 1804644ns / 100000 = 18ns - tst val 8522129526335546761
mono: 1786300ns / 100000 = 17ns - tst val 600359443389283367
%lu.%06lu: 8477539ns / 100000 = 84ns - tst val 4600000 6003.595328
%lu.%06lu diff: 8267460ns / 100000 = 82ns - tst val 4600000 6003.603811
%06lu: 6200255ns / 100000 = 62ns - tst val 5400000 6003612081
2printf: 13069690ns / 100000 = 130ns - tst val 4600000 6003.618286
1 vt is 1 nsec
real: 1839434ns / 100000 = 18ns - tst val 8522133565115078006
mono: 1788811ns / 100000 = 17ns - tst val 600363482945763234
%lu.%06lu: 8347177ns / 100000 = 83ns - tst val 4600000 6003.635724
%lu.%06lu diff: 8177486ns / 100000 = 81ns - tst val 4600000 6003.644078
%06lu: 6274116ns / 100000 = 62ns - tst val 5400000 6003652258
2printf: 13572265ns / 100000 = 135ns - tst val 4600000 6003.658536
SmartOS 64bit vtim_uint64.c nanoseconds
1 vt is 1 nsec
real: 4001319ns / 100000 = 40ns - tst val 9341692761795774739
mono: 3990058ns / 100000 = 39ns - tst val 16907526543020455981
%lu.%06lu: 25480662ns / 100000 = 254ns - tst val 5700000 3673956.641440
%lu.%06lu diff: 24836733ns / 100000 = 248ns - tst val 5700000 3673956.666945
%06lu: 20819684ns / 100000 = 208ns - tst val 5700000 3673956691809
2printf: 56805505ns / 100000 = 568ns - tst val 5700000 3673956.712655
1 vt is 1 nsec
real: 4357576ns / 100000 = 43ns - tst val 9341706878688867866
mono: 4157573ns / 100000 = 41ns - tst val 16907540709171765817
%lu.%06lu: 31060114ns / 100000 = 310ns - tst val 5700000 3673956.783126
%lu.%06lu diff: 26465987ns / 100000 = 264ns - tst val 5700000 3673956.814214
%06lu: 22196569ns / 100000 = 221ns - tst val 5700000 3673956840710
2printf: 52591106ns / 100000 = 525ns - tst val 5700000 3673956.862945
1 vt is 1 nsec
real: 4990835ns / 100000 = 49ns - tst val 9341721592996888443
mono: 3985929ns / 100000 = 39ns - tst val 16907555415553040934
%lu.%06lu: 30840218ns / 100000 = 308ns - tst val 5700000 3673956.930165
%lu.%06lu diff: 29306453ns / 100000 = 293ns - tst val 5700000 3673956.961041
%06lu: 24574870ns / 100000 = 245ns - tst val 5700000 3673956990383
2printf: 55021411ns / 100000 = 550ns - tst val 5700000 3673957.014986
1 vt is 1 nsec
real: 5964321ns / 100000 = 59ns - tst val 9341737111204615366
mono: 5672596ns / 100000 = 56ns - tst val 16907571078315471014
%lu.%06lu: 37606858ns / 100000 = 376ns - tst val 5700000 3673957.087631
%lu.%06lu diff: 36609663ns / 100000 = 366ns - tst val 5700000 3673957.125273
%06lu: 27434026ns / 100000 = 274ns - tst val 5700000 3673957161923
2printf: 68533158ns / 100000 = 685ns - tst val 5700000 3673957.189391
1 vt is 1 nsec
real: 3973381ns / 100000 = 39ns - tst val 9341755714929160410
mono: 3930117ns / 100000 = 39ns - tst val 16907589491415809313
%lu.%06lu: 25384065ns / 100000 = 253ns - tst val 5700000 3673957.270895
%lu.%06lu diff: 25737191ns / 100000 = 257ns - tst val 5700000 3673957.296306
%06lu: 20015972ns / 100000 = 200ns - tst val 5700000 3673957322071
2printf: 60235584ns / 100000 = 602ns - tst val 5700000 3673957.342119
-------------- next part --------------
A non-text attachment was scrubbed...
Name: vtim_uint64.h
Type: text/x-chdr
Size: 1783 bytes
Desc: not available
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-dev/attachments/20181005/1c4bbd61/attachment-0002.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: vtim_uint64.c
Type: text/x-csrc
Size: 15692 bytes
Desc: not available
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-dev/attachments/20181005/1c4bbd61/attachment-0003.bin>
More information about the varnish-dev
mailing list