Performance analysis: Time spent for each check

[drwetter]

For discussing #581 and #666 here is (as a meta ticket) a table how much time is spend in each function. Measurement is not really accurate (just seconds) and not really a statistical representative -- however it should give a feel.

Time is in seconds and it is relative (+X means +X seconds from start)

check	LAN	LAN2	WAN
protocols	+2	+2	+4
standard cipher lists	+4	+5	+6
PFS	+6	+6	+9
server prefs	+10	+8	+16
server defaults	+12	+10	+21
header response	+13	+11	+23
HB	+13	+22	+23
CCS	+17	+26	+27
Renego	+19	+27	+28
CRIME	+19	+27	+28
BREACH	+20	+28	+29
POODLE	+20	+28	+30
TLS_FALLBACK_SCSV	+20	+28	+30
SWEET32	+20	+28	+30
FREAK	+21	+29	+31
DROWN	+21	+29	+31
LOGJAM	+21	+30	+31
BEAST	+22	+31	+33
LUCKY13	+22	+31	+33
RC4	+22	+32	+33
all_ciphers	+26	+35	+37
client sim	+38	+48	+50

LAN is a Debian stretch VM which has openssl without LAN2 a VM with openssl with heartbeat support. LAN has also support for h2 + http1.1 (both ALPN/SPDY), LAN2 has neither of those. WAN results has been achieved via testssl.sh --ip=one testssl.net (also no heartbeat support, and h2 + http1.1 support).

[drwetter]

code used see 273361f

[drwetter]

According to Einstein time is now (27d0570fb5f15e1636e571b166d9879a62e15e82) relative ;-) -- i.e. to the previous measurement and not to the start time.

Change of PS4 allows now fine granular measurements.

[drwetter]

I did some statistics with 43463da4fc3b6272ee9c7a5f5180ce26d561a9d8 which I like to present. This is for getting a better idea of the overall time sinks for a default run.

In order to get somewhat statistical relevant data I ran for each host ~ for a in 1 2 3; do for h in <hostlist>; do MEASURE_TIME_FILE=$h$a.txt ./testssl.sh --ip=one $a; done; done. Spikes were sorted out and re-done.

Functions / checks which cost more or less considerable amount of time are marked in yellow. Bottomline: Time sinks in ~ descending order are:

1) run_client_simulation() 2) run_server_preference() ¹) 3) run_server_defaults() / run_allciphers() 4) run_std_cipherlists() 5) run_pfs() ¹) 6) run_protocols() 7) run_beast() 8) run_heartbleed() 9) run_ccs()

¹) insecure.org seems to be a special case here but also if it isn't included the order (sorted by WAN time) won't change

[drwetter]

Comments off the top off my head:

1) needs further debugging to understand why this is the top scorer. Last straw could be to exclude in the standard run a few clients 2) It seems to eat more time if there are lots of SPDY protocols provided (except insecure.org which doesn't provide anything here). Does is makes sense at all to include cipher order for h2, spdy/3* and friends? 3) a) run_server_defaults(): lost of single tests. Needs some look at the code. Spikes are amazon.com and insecure.org b) Thx to David this is already fast (maybe with save_time tree there's more gain). Amazon and insecure are the spikes here again. 4) Needs my attention anyway (# of connects will be reduced). Further investigation may follow. 5) see save_time tree 6) what? ;-) 7) Further investigation may follow. 8) That is a binary test in terms of time. 0 secs means no heartbeat extension. ~10 secs is the test for heartbleed which is in all negative test cases determined by the timeout (8 secs). Not so much to do here unless the timeout will be decreased -- which needs to be carefully considered. 9) Here's also a timeout involved. Not sure whether this can be done faster.

[dcooper16]

2. It seems to eat more time if there are lots of SPDY protocols provided (except insecure.org which doesn't provide anything here). Does is makes sense at all to include cipher order for h2, spdy/3* and friends?

I think those tests should be removed. That was my suggestion in #543.

[drwetter]

Am 24.03.2017 um 18:09 schrieb David Cooper:

 2. It seems to eat more time if there are lots of SPDY protocols provided (except
    insecure.org which doesn't provide anything here). Does is makes sense at all to
    include cipher order for h2, spdy/3* and friends?

I think those tests should be removed. That was my suggestion in #543 https://github.com/drwetter/testssl.sh/issues/543.

forgot about that...

[drwetter]

Under the light of #660 and the discussion in #581 I was thinking throwing away run_cipher() and run_cipher_per_proto(). Reason is that run_server_preference() contains this already -- and it is sorted by cipher order which has more value then sorted by strength (supposed there's an server order)

The only catch is that then it should be displayed in wide mode -- but a long and wide output in the middle of the run somehow screws up the visual appearance.

[drwetter]

With the recent update 7953bfda5e3501fdcf9c47ef0fa59f2982aed402 the instructions to do some performance analysis are as follows:

1) run the program in the following way: DEBUGTIME=true bash -x ./testssl.sh <anycmdline> 2) ls -lrt /tmp/testssl* | tail -2 will show you the debugging logfile (.log) and how much time is spend for each call (.time) 3) merge them together (see https://stackoverflow.com/questions/5014823/how-to-profile-a-bash-shell-script-slow-startup#20855353)

paste <(
    while read tim ;do
        crt=000000000$((${tim//.}-10#0$last))
        printf "%12.9f\n" ${crt:0:${#crt}-9}.${crt:${#crt}-9}
        last=${tim//.}
      done < /tmp/testssl-XXX.time
  ) /tmp/testssl-XXX.log  >/tmp/testssl-xxx.difftime.txt

4) the first columns in the resulting file represents the time spend on each call, then comes the line#, function and what has been exec'd (it looks like there's currently an "off-by-one", i.e. the time used is for the previous line in the code.)

An example of DEBUGTIME=true bash -x testssl.sh -c --ip=one testssl.net is @ https://gist.github.com/drwetter/e329ec16e6dbf8d51841e3335f390ba3

[drwetter]

from "the outside" one also can use "ts" from "moreutils":