fortio: Inconsistent behavior noticed in latency across different qps

Issue Fortio shows significantly increased latency at different qps for the same number of threads.

For example,

400 qps with 1 Fortio instance and 48 threads, 99.9% = ~100ms across several runs (consistent behavior) 500qps with 1 Fortio instance and 48 threads 99.9% = ~10ms across several runs with occasional spike to ~50ms 1000qps with 1 Fortio instance and 48 threads 99.9% = ~5ms across several runs

This behavior seems a bit inconsistent.

Test setup k8s on aws 1 master, 2 nodes t2.medium specs: 2 vcpus, 4 gb mem No Istio involved in this.

Fortio as the client lwan as the server

fortio.yaml

apiVersion: extensions/v1beta1
kind: Deployment
metadata:
  name: fortio
spec:
  replicas: 1
  template:
    metadata:
      labels:
        app: fortio
    spec:
      containers:
      - image: istio/fortio
        imagePullPolicy: IfNotPresent
        name: fortio
        resources:
          requests:
            memory: "128Mi"
            cpu: "0.1"
          limits:
            memory: "512Mi"
            cpu: "2"

lwan.yaml

apiVersion: extensions/v1beta1
kind: Deployment
metadata:
  name: lwan
spec:
  replicas: 1
  template:
    metadata:
      labels:
        app: lwan
    spec:
      containers:
      - image: jaxgeller/lwan
        imagePullPolicy: IfNotPresent
        name: lwan
        ports:
        - containerPort: 8080
---
apiVersion: v1
kind: Service
metadata:
  name: lwan
  labels:
    app: lwan
spec:
  ports:
  - port: 8080
    name: http
  selector:
    app: lwan    

Sample run output 400 QPS

kubectl exec fortio-3574055260-gwlj3 -- fortio load -qps 400 -t 10s -c 48 -r 0.0001 http://lwan:8080

Fortio 0.6.9 running at 400 queries per second, 2->2 procs, for 10s: http://lwan:8080
23:48:20 I httprunner.go:72> Starting http test for http://lwan:8080 with 48 threads at 400.0 qps
Starting at 400 qps with 48 thread(s) [gomax 2] for 10s : 83 calls each (total 3984)
23:48:30 I periodic.go:523> T005 ended after 9.960805951s : 83 calls. qps=8.332659064768484
23:48:30 I periodic.go:523> T044 ended after 9.961062894s : 83 calls. qps=8.332444126017382
23:48:30 I periodic.go:523> T007 ended after 9.961083142s : 83 calls. qps=8.332427188569289
23:48:30 I periodic.go:523> T013 ended after 9.961111262s : 83 calls. qps=8.332403666308933
23:48:30 I periodic.go:523> T001 ended after 9.961122899s : 83 calls. qps=8.332393932046797
23:48:30 I periodic.go:523> T040 ended after 9.961133784s : 83 calls. qps=8.33238482684754
23:48:30 I periodic.go:523> T032 ended after 9.961146691s : 83 calls. qps=8.332374030290245
23:48:30 I periodic.go:523> T008 ended after 9.961103667s : 83 calls. qps=8.332410019481028
23:48:30 I periodic.go:523> T047 ended after 9.961159719s : 83 calls. qps=8.332363132546215
23:48:30 I periodic.go:523> T024 ended after 9.961170942s : 83 calls. qps=8.33235374468288
23:48:30 I periodic.go:523> T019 ended after 9.96117004s : 83 calls. qps=8.33235449919094
23:48:30 I periodic.go:523> T034 ended after 9.961185669s : 83 calls. qps=8.332341425810641
23:48:30 I periodic.go:523> T020 ended after 9.961181548s : 83 calls. qps=8.332344872949804
23:48:30 I periodic.go:523> T031 ended after 9.961198843s : 83 calls. qps=8.332330406026008
23:48:30 I periodic.go:523> T023 ended after 9.96126432s : 83 calls. qps=8.332275636271843
23:48:30 I periodic.go:523> T021 ended after 9.961282372s : 83 calls. qps=8.332260536384682
23:48:30 I periodic.go:523> T042 ended after 9.961296011s : 83 calls. qps=8.332249127858992
23:48:30 I periodic.go:523> T012 ended after 9.961306972s : 83 calls. qps=8.332239959405198
23:48:30 I periodic.go:523> T002 ended after 9.96132023s : 83 calls. qps=8.332228869626451
23:48:30 I periodic.go:523> T045 ended after 9.961332797s : 83 calls. qps=8.332218357868403
23:48:30 I periodic.go:523> T043 ended after 9.961382117s : 83 calls. qps=8.332177104053963
23:48:30 I periodic.go:523> T011 ended after 9.961399215s : 83 calls. qps=8.3321628024924
23:48:30 I periodic.go:523> T036 ended after 9.961410528s : 83 calls. qps=8.332153339800595
23:48:30 I periodic.go:523> T017 ended after 9.961423037s : 83 calls. qps=8.332142876746698
23:48:30 I periodic.go:523> T003 ended after 9.961439493s : 83 calls. qps=8.33212911229596
23:48:30 I periodic.go:523> T016 ended after 9.961517764s : 83 calls. qps=8.332063643951356
23:48:30 I periodic.go:523> T041 ended after 9.961539418s : 83 calls. qps=8.332045532041281
23:48:30 I periodic.go:523> T010 ended after 9.961561477s : 83 calls. qps=8.332027081460735
23:48:30 I periodic.go:523> T037 ended after 9.961577422s : 83 calls. qps=8.332013744800667
23:48:30 I periodic.go:523> T009 ended after 9.961590801s : 83 calls. qps=8.332002554418116
23:48:30 I periodic.go:523> T028 ended after 9.96165136s : 83 calls. qps=8.331951902400247
23:48:30 I periodic.go:523> T015 ended after 9.961670434s : 83 calls. qps=8.33193594888606
23:48:30 I periodic.go:523> T033 ended after 9.961681563s : 83 calls. qps=8.331926640606671
23:48:30 I periodic.go:523> T039 ended after 9.961693734s : 83 calls. qps=8.331916460823809
23:48:30 I periodic.go:523> T000 ended after 9.961706738s : 83 calls. qps=8.331905584350078
23:48:30 I periodic.go:523> T038 ended after 9.961717795s : 83 calls. qps=8.331896336358723
23:48:30 I periodic.go:523> T029 ended after 9.961728429s : 83 calls. qps=8.331887442180742
23:48:30 I periodic.go:523> T006 ended after 9.961740571s : 83 calls. qps=8.331877286748908
23:48:30 I periodic.go:523> T025 ended after 9.961754097s : 83 calls. qps=8.331865973784236
23:48:30 I periodic.go:523> T026 ended after 9.961779398s : 83 calls. qps=8.331844812450242
23:48:30 I periodic.go:523> T018 ended after 9.961800968s : 83 calls. qps=8.331826771747243
23:48:30 I periodic.go:523> T046 ended after 9.961816454s : 83 calls. qps=8.331813819624506
23:48:30 I periodic.go:523> T004 ended after 9.961827661s : 83 calls. qps=8.331804446380897
23:48:30 I periodic.go:523> T027 ended after 9.961839786s : 83 calls. qps=8.331794305369689
23:48:30 I periodic.go:523> T022 ended after 9.961850935s : 83 calls. qps=8.331784980679396
23:48:30 I periodic.go:523> T035 ended after 9.961862575s : 83 calls. qps=8.331775245353654
23:48:30 I periodic.go:523> T030 ended after 9.961876412s : 83 calls. qps=8.33176367255659
23:48:30 I periodic.go:523> T014 ended after 9.961892403s : 83 calls. qps=8.3317502982671
Ended after 9.961925336s : 3984 calls. qps=399.92
Sleep times : count 3936 avg 0.11784792 +/- 0.01339 min 0.021110807 max 0.120651298 sum 463.849417
Aggregated Function Time : count 3984 avg 0.003122779 +/- 0.0133 min 0.000246807 max 0.099868211 sum 12.4411514
# range, mid point, percentile, count
>= 0.000246807 <= 0.0003 , 0.000273404 , 0.05, 2
> 0.0003 <= 0.0004 , 0.00035 , 0.18, 5
> 0.0004 <= 0.0005 , 0.00045 , 0.38, 8
> 0.0005 <= 0.0006 , 0.00055 , 1.13, 30
> 0.0006 <= 0.0007 , 0.00065 , 2.94, 72
> 0.0007 <= 0.0008 , 0.00075 , 10.24, 291
> 0.0008 <= 0.0009 , 0.00085 , 24.25, 558
> 0.0009 <= 0.001 , 0.00095 , 38.96, 586
> 0.001 <= 0.0011 , 0.00105 , 52.66, 546
> 0.0011 <= 0.0012 , 0.00115 , 64.43, 469
> 0.0012 <= 0.0014 , 0.0013 , 83.21, 748
> 0.0014 <= 0.0016 , 0.0015 , 93.45, 408
> 0.0016 <= 0.0018 , 0.0017 , 96.64, 127
> 0.0018 <= 0.002 , 0.0019 , 97.26, 25
> 0.002 <= 0.0025 , 0.00225 , 97.67, 16
> 0.05 <= 0.06 , 0.055 , 98.09, 17
> 0.08 <= 0.09 , 0.085 , 98.44, 14
> 0.09 <= 0.0998682 , 0.0949341 , 100.00, 62
# target 50% 0.00108059
# target 75% 0.00131257
# target 90% 0.00153265
# target 99% 0.0935271
# target 99.9% 0.0992341
Code 200 : 3984 (100.0 %)
Response Header Sizes : count 3984 avg 227 +/- 0 min 227 max 227 sum 904368
Response Body/Total Sizes : count 3984 avg 1281 +/- 0 min 1281 max 1281 sum 5103504
All done 3984 calls (plus 48 warmup) 3.123 ms avg, 399.9 qps

500 QPS

kubectl exec fortio-3574055260-gwlj3 -- fortio load -qps 500 -t 10s -c 48 -r 0.0001 http://lwan:8080

Fortio 0.6.9 running at 500 queries per second, 2->2 procs, for 10s: http://lwan:8080
23:50:15 I httprunner.go:72> Starting http test for http://lwan:8080 with 48 threads at 500.0 qps
Starting at 500 qps with 48 thread(s) [gomax 2] for 10s : 104 calls each (total 4992)
23:50:25 I periodic.go:523> T004 ended after 9.984983608s : 104 calls. qps=10.415640534119142
23:50:25 I periodic.go:523> T009 ended after 9.985004899s : 104 calls. qps=10.415618324875897
23:50:25 I periodic.go:523> T017 ended after 9.98513712s : 104 calls. qps=10.415480403538014
23:50:25 I periodic.go:523> T011 ended after 9.985172021s : 104 calls. qps=10.415443998488525
23:50:25 I periodic.go:523> T030 ended after 9.985185073s : 104 calls. qps=10.415430384081375
23:50:25 I periodic.go:523> T023 ended after 9.985221263s : 104 calls. qps=10.41539263485022
23:50:25 I periodic.go:523> T025 ended after 9.985240744s : 104 calls. qps=10.415372314632696
23:50:25 I periodic.go:523> T006 ended after 9.985270162s : 104 calls. qps=10.415341629491708
23:50:25 I periodic.go:523> T043 ended after 9.985282213s : 104 calls. qps=10.41532905946321
23:50:25 I periodic.go:523> T028 ended after 9.985292325s : 104 calls. qps=10.415318511969554
23:50:25 I periodic.go:523> T012 ended after 9.985504083s : 104 calls. qps=10.415097639092318
23:50:25 I periodic.go:523> T026 ended after 9.985427892s : 104 calls. qps=10.415177108566516
23:50:25 I periodic.go:523> T013 ended after 9.985535321s : 104 calls. qps=10.415065057281769
23:50:25 I periodic.go:523> T000 ended after 9.98557891s : 104 calls. qps=10.41501959349095
23:50:25 I periodic.go:523> T020 ended after 9.985594448s : 104 calls. qps=10.415003387287575
23:50:25 I periodic.go:523> T001 ended after 9.985566141s : 104 calls. qps=10.415032911652716
23:50:25 I periodic.go:523> T033 ended after 9.985729107s : 104 calls. qps=10.414862939461871
23:50:25 I periodic.go:523> T015 ended after 9.985776165s : 104 calls. qps=10.414813859389165
23:50:25 I periodic.go:523> T046 ended after 9.985747964s : 104 calls. qps=10.414843272124868
23:50:25 I periodic.go:523> T005 ended after 9.98581892s : 104 calls. qps=10.414769267616562
23:50:25 I periodic.go:523> T035 ended after 9.985832769s : 104 calls. qps=10.414754823739628
23:50:25 I periodic.go:523> T029 ended after 9.985820783s : 104 calls. qps=10.414767324589988
23:50:25 I periodic.go:523> T036 ended after 9.985852639s : 104 calls. qps=10.4147341003036
23:50:25 I periodic.go:523> T018 ended after 9.985867263s : 104 calls. qps=10.414718848241113
23:50:25 I periodic.go:523> T010 ended after 9.985875791s : 104 calls. qps=10.414709954006478
23:50:25 I periodic.go:523> T019 ended after 9.985889476s : 104 calls. qps=10.414695681336418
23:50:25 I periodic.go:523> T041 ended after 9.985899204s : 104 calls. qps=10.414685535614185
23:50:25 I periodic.go:523> T024 ended after 9.985933164s : 104 calls. qps=10.414650117520052
23:50:25 I periodic.go:523> T007 ended after 9.985949526s : 104 calls. qps=10.414633053093201
23:50:25 I periodic.go:523> T008 ended after 9.98595977s : 104 calls. qps=10.41462236934287
23:50:25 I periodic.go:523> T040 ended after 9.985992054s : 104 calls. qps=10.414588699611636
23:50:25 I periodic.go:523> T022 ended after 9.986007188s : 104 calls. qps=10.41457291608751
23:50:25 I periodic.go:523> T002 ended after 9.985908867s : 104 calls. qps=10.414675457702634
23:50:25 I periodic.go:523> T039 ended after 9.986036175s : 104 calls. qps=10.414542685151048
23:50:25 I periodic.go:523> T042 ended after 9.986086286s : 104 calls. qps=10.414490424121697
23:50:25 I periodic.go:523> T003 ended after 9.986105459s : 104 calls. qps=10.414470428636397
23:50:25 I periodic.go:523> T037 ended after 9.98612033s : 104 calls. qps=10.414454919751602
23:50:25 I periodic.go:523> T032 ended after 9.98613706s : 104 calls. qps=10.414437472181058
23:50:25 I periodic.go:523> T047 ended after 9.986150561s : 104 calls. qps=10.414423392148974
23:50:25 I periodic.go:523> T044 ended after 9.986162249s : 104 calls. qps=10.41441120290374
23:50:25 I periodic.go:523> T045 ended after 9.98607751s : 104 calls. qps=10.414499576621052
23:50:25 I periodic.go:523> T038 ended after 9.986176009s : 104 calls. qps=10.414396852836404
23:50:25 I periodic.go:523> T014 ended after 9.986220728s : 104 calls. qps=10.41435021643355
23:50:25 I periodic.go:523> T021 ended after 9.986229418s : 104 calls. qps=10.414341153883552
23:50:25 I periodic.go:523> T031 ended after 9.986252957s : 104 calls. qps=10.414316605819582
23:50:25 I periodic.go:523> T027 ended after 9.986267394s : 104 calls. qps=10.414301549995127
23:50:25 I periodic.go:523> T034 ended after 9.986285601s : 104 calls. qps=10.414282562636274
23:50:25 I periodic.go:523> T016 ended after 9.986322467s : 104 calls. qps=10.4142441167577
Ended after 9.986387637s : 4992 calls. qps=499.88
Sleep times : count 4944 avg 0.095253811 +/- 0.0004905 min 0.093113617 max 0.096379504 sum 470.934841
Aggregated Function Time : count 4992 avg 0.0012533189 +/- 0.0004252 min 0.000395221 max 0.003483806 sum 6.25656772
# range, mid point, percentile, count
>= 0.000395221 <= 0.0004 , 0.000397611 , 0.02, 1
> 0.0004 <= 0.0005 , 0.00045 , 0.10, 4
> 0.0005 <= 0.0006 , 0.00055 , 0.36, 13
> 0.0006 <= 0.0007 , 0.00065 , 1.60, 62
> 0.0007 <= 0.0008 , 0.00075 , 6.91, 265
> 0.0008 <= 0.0009 , 0.00085 , 19.31, 619
> 0.0009 <= 0.001 , 0.00095 , 30.99, 583
> 0.001 <= 0.0011 , 0.00105 , 41.31, 515
> 0.0011 <= 0.0012 , 0.00115 , 52.72, 570
> 0.0012 <= 0.0014 , 0.0013 , 73.82, 1053
> 0.0014 <= 0.0016 , 0.0015 , 84.15, 516
> 0.0016 <= 0.0018 , 0.0017 , 90.40, 312
> 0.0018 <= 0.002 , 0.0019 , 93.91, 175
> 0.002 <= 0.0025 , 0.00225 , 97.54, 181
> 0.0025 <= 0.003 , 0.00275 , 99.60, 103
> 0.003 <= 0.00348381 , 0.0032419 , 100.00, 20
# target 50% 0.00117614
# target 75% 0.00142287
# target 90% 0.00178705
# target 99% 0.00285476
# target 99.9% 0.00336305
Code 200 : 4992 (100.0 %)
Response Header Sizes : count 4992 avg 227 +/- 0 min 227 max 227 sum 1133184
Response Body/Total Sizes : count 4992 avg 1281 +/- 0 min 1281 max 1281 sum 6394752
All done 4992 calls (plus 48 warmup) 1.253 ms avg, 499.9 qps

Steps to reproduce

kubectl apply -f lwan.yaml,fortio.yaml

FORTIO_POD=(`kubectl get pod -l app=fortio -o 'jsonpath={.items[0].metadata.name}'`)
kubectl exec $FORTIO_POD -- fortio load -qps 400 -t 10s -c 48 -r 0.0001 http://lwan:8080
kubectl exec $FORTIO_POD -- fortio load -qps 500 -t 10s -c 48 -r 0.0001 http://lwan:8080
kubectl exec $FORTIO_POD -- fortio load -qps 1000 -t 10s -c 48 -r 0.0001 http://lwan:8080

You will notice the 99.9% latency numbers to be (unexpectedly) different.

Did several runs and here’s what it looks like 400_qps -> [0.09644731014560001, 0.08844548379251616, 0.08479641347120001, 0.08803804884235297, 0.09211128102000012, 0.09824750542400003, 0.09444713951127276, 0.09299937388800011, 0.09640822985230772, 0.09928206268215387] 500_qps -> [0.0029606315789473723, 0.002360964036869566, 0.002587489654400001, 0.0038180038545454573, 0.002710201872000003, 0.0021935881120000015, 0.004699181960000007, 0.004695572256000007, 0.0036297072160000102, 0.005376915061090915]