How to measure increment of latency from fortio outcome

[eoregua]

Hi,

I'm looking at the outcome from fortio to valuate in the right way what is the increment of latency between 2 TCs execution in different scenarios :

1. No disturbances on the system under test, pods up and running and ready so to serve traffic generated by fortio
2. Disturbances due the restart of pods (helm upgrade)

Outcome from first scenario:

fortio load -a -grpc -ping -cacert cacert.pem -cert client.pem -key clientkey.pem -c 8 -qps 1000  -p 1024 -t 60s  tls-p_local.it:32607
Fortio 1.24.0-pre1 running at 1000 queries per second, 4->4 procs, for 1m0s: tls-p_local.it:32607
10:51:03 I grpcrunner.go:145> Starting GRPC Ping test for tls-p_local.it:32607 with 1*8 threads at 1000.0 qps
Starting at 1000 qps with 8 thread(s) [gomax 4] for 1m0s : 7500 calls each (total 60000)
10:52:03 I periodic.go:693> T004 ended after 1m0.002166983s : 7500 calls. qps=124.99548561512658
10:52:03 I periodic.go:693> T002 ended after 1m0.002201557s : 7500 calls. qps=124.99541359120401
10:52:03 I periodic.go:693> T003 ended after 1m0.002210267s : 7500 calls. qps=124.99539544670486
10:52:03 I periodic.go:693> T001 ended after 1m0.002224181s : 7500 calls. qps=124.99536646134713
10:52:03 I periodic.go:693> T007 ended after 1m0.002253477s : 7500 calls. qps=124.99530543256833
10:52:03 I periodic.go:693> T006 ended after 1m0.0022561s : 7500 calls. qps=124.9952999683957
10:52:03 I periodic.go:693> T005 ended after 1m0.002264082s : 7500 calls. qps=124.99528334048172
10:52:03 I periodic.go:693> T000 ended after 1m0.002285297s : 7500 calls. qps=124.99523914591609
Ended after 1m0.00241081s : 60000 calls. qps=999.96
Sleep times : count 59992 avg 0.0061304446 +/- 0.0009789 min -0.010986677 max 0.007296473 sum 367.777631
**Aggregated Function Time : count 60000 avg 0.0012472604 +/- 0.0008438 min 0.00047214 max 0.018668829 sum 74.8356253**
# range, mid point, percentile, count
>= **0.00047214** <= 0.001 , 0.00073607 , 26.02, 15614
> 0.001 <= 0.002 , 0.0015 , 95.27, 41547
> 0.002 <= 0.003 , 0.0025 , 97.47, 1320
> 0.003 <= 0.004 , 0.0035 , 98.59, 675
> 0.004 <= 0.005 , 0.0045 , 99.06, 279
> 0.005 <= 0.006 , 0.0055 , 99.33, 161
> 0.006 <= 0.007 , 0.0065 , 99.50, 106
> 0.007 <= 0.008 , 0.0075 , 99.62, 73
> 0.008 <= 0.009 , 0.0085 , 99.76, 82
> 0.009 <= 0.01 , 0.0095 , 99.82, 36
> 0.01 <= 0.011 , 0.0105 , 99.86, 21
> 0.011 <= 0.012 , 0.0115 , 99.90, 24
> 0.012 <= 0.014 , 0.013 , 99.94, 26
> 0.014 <= 0.016 , 0.015 , 99.96, 14
> 0.016 <= 0.018 , 0.017 , 99.98, 8
> 0.018 <= 0.0186688 , **0.0183344** , 100.00, 14
# target 1024% 0.0186688
Jitter: false
Ping SERVING : 60000
All done 60000 calls (plus 8 warmup) 1.247 ms avg, 1000.0 qps

Outcome from the second scenario with disturbances on the pods serving the traffic from fortio:

Fortio 1.24.0-pre1 running at 1000 queries per second, 4->4 procs, for 1m0s: tls-p_local.it:32607
10:39:16 I grpcrunner.go:145> Starting GRPC Ping test for tls-p_local.it:32607 with 1*8 threads at 1000.0 qps
Starting at 1000 qps with 8 thread(s) [gomax 4] for 1m0s : 7500 calls each (total 60000)
10:39:29 W grpcrunner.go:100> Error making grpc call: rpc error: code = Unavailable desc = error reading from server: EOF
10:39:29 W grpcrunner.go:100> Error making grpc call: rpc error: code = Unavailable desc = error reading from server: EOF
10:39:29 W grpcrunner.go:100> Error making grpc call: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: read tcp 10.210.155.43:38594->10.139.91.134:32607: read: connection reset by peer"
10:39:29 W grpcrunner.go:100> Error making grpc call: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: read tcp 10.210.155.43:38596->10.139.91.134:32607: read: connection reset by peer"
10:39:29 W grpcrunner.go:100> Error making grpc call: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: read tcp 10.210.155.43:38594->10.139.91.134:32607: read: connection reset by peer"
10:39:29 W grpcrunner.go:100> Error making grpc call: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: read tcp 10.210.155.43:38594->10.139.91.134:32607: read: connection reset by peer"
10:39:29 W grpcrunner.go:100> Error making grpc call: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: read tcp 10.210.155.43:38594->10.139.91.134:32607: read: connection reset by peer"
10:39:29 W grpcrunner.go:100> Error making grpc call: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: read tcp 10.210.155.43:38594->10.139.91.134:32607: read: connection reset by peer"
10:39:29 W grpcrunner.go:100> Error making grpc call: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: read tcp 10.210.155.43:38594->10.139.91.134:32607: read: connection reset by peer"
10:39:29 W grpcrunner.go:100> Error making grpc call: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: read tcp 10.210.155.43:38594->10.139.91.134:32607: read: connection reset by peer"
10:39:29 W grpcrunner.go:100> Error making grpc call: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: read tcp 10.210.155.43:38594->10.139.91.134:32607: read: connection reset by peer"
10:39:29 W grpcrunner.go:100> Error making grpc call: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: read tcp 10.210.155.43:38594->10.139.91.134:32607: read: connection reset by peer"
10:39:29 W grpcrunner.go:100> Error making grpc call: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: read tcp 10.210.155.43:38594->10.139.91.134:32607: read: connection reset by peer"
10:39:29 W grpcrunner.go:100> Error making grpc call: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: read tcp 10.210.155.43:38594->10.139.91.134:32607: read: connection reset by peer"
10:39:29 W grpcrunner.go:100> Error making grpc call: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: read tcp 10.210.155.43:38594->10.139.91.134:32607: read: connection reset by peer"

...............

10:39:40 W grpcrunner.go:100> Error making grpc call: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: read tcp 10.210.155.43:38682->10.139.91.134:32607: read: connection reset by peer"
10:39:40 W grpcrunner.go:100> Error making grpc call: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: read tcp 10.210.155.43:38682->10.139.91.134:32607: read: connection reset by peer"
10:39:40 W grpcrunner.go:100> Error making grpc call: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: read tcp 10.210.155.43:38686->10.139.91.134:32607: read: connection reset by peer"
10:39:40 W grpcrunner.go:100> Error making grpc call: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: read tcp 10.210.155.43:38680->10.139.91.134:32607: read: connection reset by peer"
10:39:40 W grpcrunner.go:100> Error making grpc call: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: read tcp 10.210.155.43:38682->10.139.91.134:32607: read: connection reset by peer"
10:39:40 W grpcrunner.go:100> Error making grpc call: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: read tcp 10.210.155.43:38686->10.139.91.134:32607: read: connection reset by peer"
10:39:40 W grpcrunner.go:100> Error making grpc call: rpc error: code = Unavailable desc = connection error: desc = "transport: authentication handshake failed: read tcp 10.210.155.43:38680->10.139.91.134:32607: read: connection reset by peer"
10:40:16 I periodic.go:693> T006 ended after 1m0.009651079s : 7500 calls. qps=124.9798968190398
10:40:16 I periodic.go:693> T002 ended after 1m0.009655772s : 7500 calls. qps=124.97988704510178
10:40:16 I periodic.go:693> T005 ended after 1m0.013971899s : 7500 calls. qps=124.97089865376785
10:40:16 I periodic.go:693> T003 ended after 1m0.014054447s : 7500 calls. qps=124.97072675907022
10:40:16 I periodic.go:693> T001 ended after 1m0.014120324s : 7500 calls. qps=124.97058957974438
10:40:16 I periodic.go:693> T004 ended after 1m0.014220372s : 7500 calls. qps=124.97038124482862
10:40:16 I periodic.go:693> T007 ended after 1m0.014317371s : 7500 calls. qps=124.97017925966006
10:40:16 I periodic.go:693> T000 ended after 1m0.014353395s : 7500 calls. qps=124.97010424550955
Ended after 1m0.014613849s : 60000 calls. qps=999.76
Sleep times : count 59992 avg 0.0059865501 +/- 0.002024 min -0.082382022 max 0.00793078 sum 359.145112
Aggregated Function Time : count 60000 avg 0.0013089009 +/- 0.001321 min 1.0091e-05 max 0.085475874 sum 78.5340525
# range, mid point, percentile, count
>= 1.0091e-05 <= 0.001 , 0.000505046 , 25.40, 15242
> 0.001 <= 0.002 , 0.0015 , 93.69, 40974
> 0.002 <= 0.003 , 0.0025 , 96.33, 1583
> 0.003 <= 0.004 , 0.0035 , 97.64, 786
> 0.004 <= 0.005 , 0.0045 , 98.48, 503
> 0.005 <= 0.006 , 0.0055 , 98.89, 247
> 0.006 <= 0.007 , 0.0065 , 99.33, 263
> 0.007 <= 0.008 , 0.0075 , 99.52, 113
> 0.008 <= 0.009 , 0.0085 , 99.64, 72
> 0.009 <= 0.01 , 0.0095 , 99.72, 47
> 0.01 <= 0.011 , 0.0105 , 99.77, 33
> 0.011 <= 0.012 , 0.0115 , 99.79, 12
> 0.012 <= 0.014 , 0.013 , 99.86, 41
> 0.014 <= 0.016 , 0.015 , 99.91, 29
> 0.016 <= 0.018 , 0.017 , 99.94, 19
> 0.018 <= 0.02 , 0.019 , 99.97, 19
> 0.02 <= 0.025 , 0.0225 , 99.98, 7
> 0.025 <= 0.03 , 0.0275 , 99.99, 2
> 0.03 <= 0.035 , 0.0325 , 99.99, 2
> 0.05 <= 0.06 , 0.055 , 99.99, 1
> 0.07 <= 0.08 , 0.075 , 100.00, 2
> 0.08 <= 0.0854759 , 0.0827379 , 100.00, 3
# target 1024% 0.0854759
Jitter: false
Ping SERVING : 59055
Ping ERROR : 945
All done 60000 calls (plus 8 warmup) 1.309 ms avg, 999.8 qps

Basically from the printout I can immediately detect what is the traffic lost in percentange but to detect in the righ way eventually the increment for the latency due to the disturbances I want to understand what is exactly the meaning of avg and sum reported in in the "Aggregate Function Count":

From first TC:

Aggregated Function Time : count 60000 avg 0.0012472604 +/- 0.0008438 min 0.00047214 max 0.018668829 sum 74.835625

From the second TC:

Aggregated Function Time : count 60000 avg 0.0013089009 +/- 0.001321 min 1.0091e-05 max 0.085475874 sum 78.5340525

Thanks!

[ldemailly]

you probably want to use the new -nocatchup option which will prevent fortio from trying to make up for slowdown by going faster later to try to attain the target qps despite errors/slowdown

also you are using -p incorrectly, it's meant to change the pXX and you probably should leave the defaults alone (50,75,90,99,99.9) as p1024 is meaningless (fixing this in #606 so thanks for giving your full command line). once you remove -p 1024 (maybe you meant to use -payload-size 1024 ?) you will see the p90, p99 latencies (ie the slowest 10 and 1% respectively) jump

despite this, you can still see some degradation:

1: 0.0012472604 +/- 0.0008438
2: 0.0013089009 +/- 0.001321 

so the standard deviation of latency in first case is 0.8ms and it goes to 1.3ms in second case
avg latency also moves from 1.25ms to 1.30ms

likewise indeed the max latency/call duration went from 18.6ms to 85.4ms, likely during the errors or because of needing to reconnect after the errors

[eoregua]

Thanks a lot for the clarification and suggestion on the new option "-nocatchup"!