ljfranklin/cc-perf-test.md

## cc-perf-test.md

      
    Raw
  

              cc-perf-test.md
            
          
    What is this?
Some ad-hoc performance testing on cf push. Variables are number of concurrent pushes, number of diego cells, CPU count of API VMs, while the number of API VMs is fixed at one. Disabled resource matching as the test script pushes the same app each time.
Main Findings:

A single cf push takes ~30-32 seconds regardless of number of cores, cells, or workers
The number of diego cells is the main limiter as concurrency increases

32 concurrent pushes took ~59 seconds on average with 1 CC, 4 cores on API, 2 local workers, 4 diego cells
Dropped to ~42 seconds on average by scaling cells from 4 to 8 VMs
Changing properties of CC API VM (# cores, local workers) didn't have much effect on concurrency results


Each package/droplet upload takes 5-7 seconds, each download takes 2-3 seconds

These values didn't change noticability as concurrent increased
Potential max speed up of 14-20 seconds by improving upload/download throughput

4 operations: package upload from CLI to CC, package download from CC to cell, droplet upload from cell to CC, droplet download from CC to cell
The actual blobstore upload delayed_job takes ~0.2-0.4 seconds (webdav blobstore)


Bits service adds noticable latency for large files as compared to uploading directly to webdav:

For a 200MB file, uploads directly to webdav took ~2.1 seconds while uploads to webdav via bits service took ~3.5 seconds
Maybe due to nginx buffering requests to disk on bits service?


Bits service overhead increases as number of concurrent requests increases:

For a single 20MB file upload, direct upload took ~0.1 seconds while bits upload took ~0.3 seconds
For 16 concurrent 20MB uploads, direct upload took ~1.6 seconds on average while bits took ~3.0 seconds
The distribution is also interesting as direct uploads are evenly spaced over time, while bits uploads all complete around the same second:


Webdav average: 1.43563
Webdav rounds:
0.33
0.46
0.62
0.77
0.86
1.02
1.16
1.38
1.50
1.58
1.79
1.91
2.05
2.20
2.63
2.71
Bits average: 2.96688
Bits rounds:
2.97
2.95
2.95
2.96
2.97
2.96
2.96
2.96
2.95
2.96
2.95
2.95
2.96
2.96
2.96
3.10

Deploy:
bosh deploy -d cf ~/workspace/cf-deployment/cf-deployment.yml -o ~/workspace/cf-deployment/operations/scale-to-one-az.yml -o ~/workspace/capi-ci/cf-deployment-operations/performance/scale-cells-to-eight.yml -o ~/workspace/cf-deployment/operations/bypass-cc-bridge.yml -o ~/workspace/cf-deployment/operations/use-compiled-releases.yml --vars-store ./vars-store.yml -v system_domain=arya.capi.land -o ~/workspace/capi-ci/cf-deployment-operations/performance/disable-resource-matching.yml -o ~/workspace/capi-ci/cf-deployment-operations/add-bits-service.yml

Push script (ran from GCP jumpbox):
#!/bin/bash

set -eu

> /tmp/roundup.log
> /tmp/push-debug.log

for round in 1 2 4 8 16 32; do
   echo "Starting round of ${round} concurrent pushes..."
   > /tmp/push.log

   for i in $(seq $round); do
      (
        set +e

        cf delete -f -r "dora${i}"
        /usr/bin/time -f '%e' --output=/tmp/push.log -a cf push "dora${i}" | ts "[%Y-%m-%d %H:%M:%S] dora${i}"
        exit_code="$?"
        if [ "${exit_code}" != "0" ]; then
          echo "Push failed! Check /tmp/push-debug.log for details." 1>&2
        fi
      ) >> /tmp/push-debug.log &
   done

   wait

   echo "Cleaning up..."
   for i in $(seq $round); do
      (
        cf delete -f -r "dora${i}"
      ) >> /tmp/push-debug.log &
   done

   wait

   average_time="$(awk '{ total += $1; count++ } END { print total/count }' /tmp/push.log)"
   echo "Average push time for ${round} concurrent pushes: ${average_time} seconds"
   echo "${average_time}" >> /tmp/roundup.log
done

echo "Rounds:"
cat /tmp/roundup.log

Bits vs Direct upload script:
Note: hacked blobstore's nginx.conf to not require pre-signed URLs for direct upload test.
set -eu

rounds="$1"

rm -rf /tmp/foo
fallocate -l 20M /tmp/foo

> /tmp/webdav.log
> /tmp/bits.log

for i in $(seq $rounds); do
  /usr/bin/time -f '%e' --output=/tmp/bits.log -a curl -X PUT http://bits-service.service.cf.internal/droplets/foo/foo${i} -F droplet=@/tmp/foo &
done

wait

average_time="$(awk '{ total += $1; count++ } END { print total/count }' /tmp/bits.log)"
echo "Bits average: ${average_time}"
echo "Bits rounds:"
cat /tmp/bits.log

for i in $(seq $rounds); do
  /usr/bin/time -f '%e' --output=/tmp/webdav.log -a curl -k -T /tmp/foo -X PUT https://blobstore-user:PASSWORD@blobstore.service.cf.internal:4443/write/foo${i} &
done

wait

average_time="$(awk '{ total += $1; count++ } END { print total/count }' /tmp/webdav.log)"
echo "Webdav average: ${average_time}"
echo "Webdav rounds:"
cat /tmp/webdav.log

1 CC, 2 cores on API, 2 local workers, 4 diego cells
Starting round of 1 concurrent pushes...
Cleaning up...
Average push time for 1 concurrent pushes: 32.1 seconds
Starting round of 2 concurrent pushes...
Cleaning up...
Average push time for 2 concurrent pushes: 32.295 seconds
Starting round of 4 concurrent pushes...
Cleaning up...
Average push time for 4 concurrent pushes: 33.905 seconds
Starting round of 8 concurrent pushes...
Cleaning up...
Average push time for 8 concurrent pushes: 36.1487 seconds
Starting round of 16 concurrent pushes...
Cleaning up...
Average push time for 16 concurrent pushes: 46.0206 seconds
Starting round of 32 concurrent pushes...
Cleaning up...
Average push time for 32 concurrent pushes: 72.0588 seconds
Rounds:
32.1
32.295
33.905
36.1487
46.0206
72.0588

1 CC, 4 cores on API, 2 local workers, 4 diego cells
Starting round of 1 concurrent pushes...
Cleaning up...
Average push time for 1 concurrent pushes: 32.03 seconds
Starting round of 2 concurrent pushes...
Cleaning up...
Average push time for 2 concurrent pushes: 32.165 seconds
Starting round of 4 concurrent pushes...
Cleaning up...
Average push time for 4 concurrent pushes: 34.0025 seconds
Starting round of 8 concurrent pushes...
Cleaning up...
Average push time for 8 concurrent pushes: 34.445 seconds
Starting round of 16 concurrent pushes...
Cleaning up...
Average push time for 16 concurrent pushes: 41.4681 seconds
Starting round of 32 concurrent pushes...
Push failed! Check /tmp/push-debug.log for details.
Cleaning up...
Average push time for 32 concurrent pushes: 60.5985 seconds
Rounds:
32.03
32.165
34.0025
34.445
41.4681
60.5985

1 CC, 4 cores on API, 4 local workers, 4 diego cells
Starting round of 1 concurrent pushes...
Cleaning up...
Average push time for 1 concurrent pushes: 31.86 seconds
Starting round of 2 concurrent pushes...
Cleaning up...
Average push time for 2 concurrent pushes: 32.225 seconds
Starting round of 4 concurrent pushes...
Cleaning up...
Average push time for 4 concurrent pushes: 33.8175 seconds
Starting round of 8 concurrent pushes...
Cleaning up...
Average push time for 8 concurrent pushes: 35.0112 seconds
Starting round of 16 concurrent pushes...
Cleaning up...
Average push time for 16 concurrent pushes: 41.7462 seconds
Starting round of 32 concurrent pushes...
Unexpected error: unexpected end of JSON input
Push failed! Check /tmp/push-debug.log for details.
Unexpected error: unexpected end of JSON input
Push failed! Check /tmp/push-debug.log for details.
Cleaning up...
Average push time for 32 concurrent pushes: 55.4847 seconds
Rounds:
31.86
32.225
33.8175
35.0112
41.7462
59.18368 (discounting errors) ~55.4847~

1 CC, 4 cores on API, 2 local workers, 8 diego cells
Starting round of 1 concurrent pushes...
Cleaning up...
Average push time for 1 concurrent pushes: 31.91 seconds
Starting round of 2 concurrent pushes...
Cleaning up...
Average push time for 2 concurrent pushes: 29.52 seconds
Starting round of 4 concurrent pushes...
Cleaning up...
Average push time for 4 concurrent pushes: 33.37 seconds
Starting round of 8 concurrent pushes...
Cleaning up...
Average push time for 8 concurrent pushes: 32.2413 seconds
Starting round of 16 concurrent pushes...
Cleaning up...
Average push time for 16 concurrent pushes: 27.225 seconds
Starting round of 32 concurrent pushes...
Cleaning up...
Average push time for 32 concurrent pushes: 42.7169 seconds
Rounds:
31.91
29.52
33.37
32.2413
27.225
42.7169

Duration of 30 conccurent pushes:
51.24
56.64
56.09
57.38
56.54
56.95
57.34
56.50
51.27
52.55
61.80
61.83
55.37
61.38
58.50
58.31
58.46
59.81
60.83
65.95
60.54
66.30
60.89
61.06
61.01
63.48
65.01
65.88
65.90

Timing of a single push:
[2017-07-31 03:50:21] dora1 Creating app dora1 in org system / space test as admin...
[2017-07-31 03:50:21] dora1 OK
[2017-07-31 03:50:21] dora1 
[2017-07-31 03:50:21] dora1 Creating route dora1.arya.capi.land...
[2017-07-31 03:50:21] dora1 OK
[2017-07-31 03:50:21] dora1 
[2017-07-31 03:50:21] dora1 Binding dora1.arya.capi.land to dora1...
[2017-07-31 03:50:21] dora1 OK
[2017-07-31 03:50:21] dora1 
[2017-07-31 03:50:21] dora1 Uploading dora1...
[2017-07-31 03:50:21] dora1 Uploading app files from: /root/cf-acceptance-tests/assets/dora
[2017-07-31 03:50:21] dora1 Uploading 1.2M, 44 files
Done uploading               
[2017-07-31 03:50:26] dora1 OK
[2017-07-31 03:50:26] dora1 
[2017-07-31 03:50:26] dora1 Starting app dora1 in org system / space test as admin...
[2017-07-31 03:50:26] dora1 Downloading staticfile_buildpack...
[2017-07-31 03:50:26] dora1 Downloading java_buildpack...
[2017-07-31 03:50:26] dora1 Downloading binary_buildpack...
[2017-07-31 03:50:26] dora1 Downloading python_buildpack...
[2017-07-31 03:50:26] dora1 Downloading nodejs_buildpack...
[2017-07-31 03:50:26] dora1 Downloaded python_buildpack
[2017-07-31 03:50:26] dora1 Downloading ruby_buildpack...
[2017-07-31 03:50:26] dora1 Downloaded java_buildpack
[2017-07-31 03:50:26] dora1 Downloading dotnet_core_buildpack...
[2017-07-31 03:50:26] dora1 Downloaded staticfile_buildpack
[2017-07-31 03:50:26] dora1 Downloading go_buildpack...
[2017-07-31 03:50:26] dora1 Downloaded nodejs_buildpack
[2017-07-31 03:50:26] dora1 Downloaded binary_buildpack
[2017-07-31 03:50:26] dora1 Downloading php_buildpack...
[2017-07-31 03:50:26] dora1 Downloaded ruby_buildpack
[2017-07-31 03:50:26] dora1 Downloaded go_buildpack
[2017-07-31 03:50:26] dora1 Downloaded dotnet_core_buildpack
[2017-07-31 03:50:26] dora1 Downloaded php_buildpack
[2017-07-31 03:50:26] dora1 Creating container
[2017-07-31 03:50:27] dora1 Successfully created container
[2017-07-31 03:50:27] dora1 Downloading app package...
[2017-07-31 03:50:27] dora1 Downloaded app package (1.2M)
[2017-07-31 03:50:29] dora1 -------> Buildpack version 1.6.45
[2017-07-31 03:50:30] dora1        Downloaded [https://buildpacks.cloudfoundry.org/dependencies/bundler/bundler-1.15.3-1bda8458.tgz]
[2017-07-31 03:50:30] dora1 -----> Supplying Ruby/Rack
[2017-07-31 03:50:31] dora1        Downloaded [https://buildpacks.cloudfoundry.org/dependencies/ruby/ruby-2.4.1-linux-x64-9e451858.tgz]
[2017-07-31 03:50:32] dora1 -----> Using Ruby version: ruby-2.4.1
[2017-07-31 03:50:32] dora1 ###### WARNING:
[2017-07-31 03:50:32] dora1        You have not declared a Ruby version in your Gemfile.
[2017-07-31 03:50:32] dora1        To set your Ruby version add this line to your Gemfile:
[2017-07-31 03:50:32] dora1        ruby '~> 2.4.1'
[2017-07-31 03:50:32] dora1        # See http://docs.cloudfoundry.org/buildpacks/ruby/index.html#runtime for more information.
[2017-07-31 03:50:32] dora1 -------> Buildpack version 1.6.45
[2017-07-31 03:50:33] dora1 -----> Finalizing Ruby/Rack
[2017-07-31 03:50:33] dora1 -----> Installing dependencies using bundler 1.15.3
[2017-07-31 03:50:33] dora1        Running: bundle install --without development:test --path vendor/bundle --binstubs vendor/bundle/bin --jobs=4 --retry=4 --deployment
[2017-07-31 03:50:33] dora1        Using bundler 1.15.3
[2017-07-31 03:50:33] dora1        Installing json 2.1.0 with native extensions
[2017-07-31 03:50:33] dora1        Installing mustermann 1.0.0
[2017-07-31 03:50:33] dora1        Installing rack 2.0.3
[2017-07-31 03:50:34] dora1        Installing tilt 2.0.7
[2017-07-31 03:50:34] dora1        Installing rack-protection 2.0.0
[2017-07-31 03:50:34] dora1        Installing sinatra 2.0.0
[2017-07-31 03:50:36] dora1        Bundle complete! 4 Gemfile dependencies, 7 gems now installed.
[2017-07-31 03:50:36] dora1        Gems in the groups development and test were not installed.
[2017-07-31 03:50:36] dora1        Bundled gems are installed into ./vendor/bundle.
[2017-07-31 03:50:36] dora1        Bundle completed (3.25s)
[2017-07-31 03:50:36] dora1        Cleaning up the bundler cache.
[2017-07-31 03:50:37] dora1 -----> Detecting rake tasks
[2017-07-31 03:50:41] dora1 Exit status 0
[2017-07-31 03:50:41] dora1 Uploading droplet, build artifacts cache...
[2017-07-31 03:50:41] dora1 Uploading build artifacts cache...
[2017-07-31 03:50:41] dora1 Uploading droplet...
[2017-07-31 03:50:41] dora1 Uploaded build artifacts cache (2.3M)
[2017-07-31 03:50:47] dora1 Uploaded droplet (20.8M)
[2017-07-31 03:50:47] dora1 Uploading complete
[2017-07-31 03:50:47] dora1 Stopping instance 48ed95f4-5ec2-46c6-9ab7-ef57da7fd51c
[2017-07-31 03:50:47] dora1 Destroying container
[2017-07-31 03:50:47] dora1 Successfully destroyed container
[2017-07-31 03:50:52] dora1 
[2017-07-31 03:50:52] dora1 1 of 1 instances running
[2017-07-31 03:50:52] dora1 
[2017-07-31 03:50:52] dora1 App started
[2017-07-31 03:50:52] dora1 
[2017-07-31 03:50:52] dora1 
[2017-07-31 03:50:52] dora1 OK
[2017-07-31 03:50:52] dora1 
[2017-07-31 03:50:52] dora1 App dora1 was started using this command `bundle exec rackup config.ru -p $PORT`
[2017-07-31 03:50:52] dora1 
[2017-07-31 03:50:52] dora1 Showing health and status for app dora1 in org system / space test as admin...
[2017-07-31 03:50:52] dora1 OK
[2017-07-31 03:50:52] dora1 
[2017-07-31 03:50:52] dora1 requested state: started
[2017-07-31 03:50:52] dora1 instances: 1/1
[2017-07-31 03:50:52] dora1 usage: 1G x 1 instances
[2017-07-31 03:50:52] dora1 urls: dora1.arya.capi.land
[2017-07-31 03:50:52] dora1 last uploaded: Mon Jul 31 03:50:21 UTC 2017
[2017-07-31 03:50:52] dora1 stack: cflinuxfs2
[2017-07-31 03:50:52] dora1 buildpack: ruby 1.6.45
[2017-07-31 03:50:52] dora1 
[2017-07-31 03:50:52] dora1      state     since                    cpu    memory        disk          details
[2017-07-31 03:50:52] dora1 #0   running   2017-07-31 03:50:50 AM   0.0%   18.8M of 1G   84.4M of 1G

Timing of one of the 32 concurrent pushes:
Deleting app dora29 in org system / space test as admin...
App dora29 does not exist.
[2017-07-31 03:46:16] dora29 Creating app dora29 in org system / space test as admin...
[2017-07-31 03:46:16] dora29 OK
[2017-07-31 03:46:16] dora29 
[2017-07-31 03:46:17] dora29 Creating route dora29.arya.capi.land...
[2017-07-31 03:46:18] dora29 OK
[2017-07-31 03:46:18] dora29 
[2017-07-31 03:46:18] dora29 Binding dora29.arya.capi.land to dora29...
[2017-07-31 03:46:19] dora29 OK
[2017-07-31 03:46:19] dora29 
[2017-07-31 03:46:19] dora29 Uploading dora29...
[2017-07-31 03:46:20] dora29 Uploading app files from: /root/cf-acceptance-tests/assets/dora
[2017-07-31 03:46:20] dora29 Uploading 1.2M, 44 files
Done uploading               
[2017-07-31 03:46:27] dora29 OK
[2017-07-31 03:46:27] dora29 
[2017-07-31 03:46:27] dora29 Starting app dora29 in org system / space test as admin...
[2017-07-31 03:46:27] dora29 Downloading staticfile_buildpack...
[2017-07-31 03:46:27] dora29 Downloading binary_buildpack...
[2017-07-31 03:46:27] dora29 Downloading dotnet_core_buildpack...
[2017-07-31 03:46:27] dora29 Downloading go_buildpack...
[2017-07-31 03:46:27] dora29 Downloading python_buildpack...
[2017-07-31 03:46:27] dora29 Downloaded staticfile_buildpack
[2017-07-31 03:46:27] dora29 Downloaded binary_buildpack
[2017-07-31 03:46:27] dora29 Downloading java_buildpack...
[2017-07-31 03:46:27] dora29 Downloading nodejs_buildpack...
[2017-07-31 03:46:27] dora29 Downloaded dotnet_core_buildpack
[2017-07-31 03:46:27] dora29 Downloading php_buildpack...
[2017-07-31 03:46:27] dora29 Downloaded go_buildpack
[2017-07-31 03:46:27] dora29 Downloading ruby_buildpack...
[2017-07-31 03:46:27] dora29 Downloaded python_buildpack
[2017-07-31 03:46:27] dora29 Downloaded java_buildpack
[2017-07-31 03:46:27] dora29 Downloaded ruby_buildpack
[2017-07-31 03:46:27] dora29 Downloaded nodejs_buildpack
[2017-07-31 03:46:27] dora29 Downloaded php_buildpack
[2017-07-31 03:46:27] dora29 Creating container
[2017-07-31 03:46:28] dora29 Successfully created container
[2017-07-31 03:46:28] dora29 Downloading app package...
[2017-07-31 03:46:28] dora29 Downloaded app package (1.2M)
[2017-07-31 03:46:31] dora29 -------> Buildpack version 1.6.45
[2017-07-31 03:46:32] dora29        Downloaded [https://buildpacks.cloudfoundry.org/dependencies/bundler/bundler-1.15.3-1bda8458.tgz]
[2017-07-31 03:46:32] dora29 -----> Supplying Ruby/Rack
[2017-07-31 03:46:33] dora29        Downloaded [https://buildpacks.cloudfoundry.org/dependencies/ruby/ruby-2.4.1-linux-x64-9e451858.tgz]
[2017-07-31 03:46:34] dora29 -----> Using Ruby version: ruby-2.4.1
[2017-07-31 03:46:34] dora29 ###### WARNING:
[2017-07-31 03:46:34] dora29        You have not declared a Ruby version in your Gemfile.
[2017-07-31 03:46:34] dora29        To set your Ruby version add this line to your Gemfile:
[2017-07-31 03:46:34] dora29        ruby '~> 2.4.1'
[2017-07-31 03:46:34] dora29        # See http://docs.cloudfoundry.org/buildpacks/ruby/index.html#runtime for more information.
[2017-07-31 03:46:35] dora29 -------> Buildpack version 1.6.45
[2017-07-31 03:46:35] dora29 -----> Finalizing Ruby/Rack
[2017-07-31 03:46:36] dora29 -----> Installing dependencies using bundler 1.15.3
[2017-07-31 03:46:36] dora29        Running: bundle install --without development:test --path vendor/bundle --binstubs vendor/bundle/bin --jobs=4 --retry=4 --deployment
[2017-07-31 03:46:37] dora29        Using bundler 1.15.3
[2017-07-31 03:46:37] dora29        Installing json 2.1.0 with native extensions
[2017-07-31 03:46:37] dora29        Installing mustermann 1.0.0
[2017-07-31 03:46:37] dora29        Installing rack 2.0.3
[2017-07-31 03:46:37] dora29        Installing tilt 2.0.7
[2017-07-31 03:46:37] dora29        Installing rack-protection 2.0.0
[2017-07-31 03:46:37] dora29        Installing sinatra 2.0.0
[2017-07-31 03:46:41] dora29        Bundle complete! 4 Gemfile dependencies, 7 gems now installed.
[2017-07-31 03:46:41] dora29        Gems in the groups development and test were not installed.
[2017-07-31 03:46:41] dora29        Bundled gems are installed into ./vendor/bundle.
[2017-07-31 03:46:41] dora29        Bundle completed (5.58s)
[2017-07-31 03:46:41] dora29        Cleaning up the bundler cache.
[2017-07-31 03:46:42] dora29 -----> Detecting rake tasks
[2017-07-31 03:46:49] dora29 Exit status 0
[2017-07-31 03:46:49] dora29 Uploading droplet, build artifacts cache...
[2017-07-31 03:46:49] dora29 Uploading build artifacts cache...
[2017-07-31 03:46:49] dora29 Uploading droplet...
[2017-07-31 03:46:49] dora29 Uploaded build artifacts cache (2.3M)
[2017-07-31 03:46:53] dora29 Uploaded droplet (20.8M)
[2017-07-31 03:46:53] dora29 Uploading complete
[2017-07-31 03:46:53] dora29 Stopping instance cc2468e9-58de-4b36-8f32-9ff16b93f58e
[2017-07-31 03:46:53] dora29 Destroying container
[2017-07-31 03:46:54] dora29 Successfully destroyed container
[2017-07-31 03:47:03] dora29 
[2017-07-31 03:47:03] dora29 1 of 1 instances running
[2017-07-31 03:47:03] dora29 
[2017-07-31 03:47:03] dora29 App started
[2017-07-31 03:47:03] dora29 
[2017-07-31 03:47:03] dora29 
[2017-07-31 03:47:03] dora29 OK
[2017-07-31 03:47:03] dora29 
[2017-07-31 03:47:03] dora29 App dora29 was started using this command `bundle exec rackup config.ru -p $PORT`
[2017-07-31 03:47:03] dora29 
[2017-07-31 03:47:03] dora29 Showing health and status for app dora29 in org system / space test as admin...
[2017-07-31 03:47:03] dora29 OK
[2017-07-31 03:47:03] dora29 
[2017-07-31 03:47:03] dora29 requested state: started
[2017-07-31 03:47:03] dora29 instances: 1/1
[2017-07-31 03:47:03] dora29 usage: 1G x 1 instances
[2017-07-31 03:47:03] dora29 urls: dora29.arya.capi.land
[2017-07-31 03:47:03] dora29 last uploaded: Mon Jul 31 03:46:22 UTC 2017
[2017-07-31 03:47:04] dora29 stack: cflinuxfs2
[2017-07-31 03:47:04] dora29 buildpack: ruby 1.6.45
[2017-07-31 03:47:04] dora29 
[2017-07-31 03:47:04] dora29      state     since                    cpu    memory    disk      details
[2017-07-31 03:47:04] dora29 #0   running   2017-07-31 03:46:57 AM   0.0%   0 of 1G   0 of 1G
Deleting app dora29 in org system / space test as admin...