Sequential new-app commands cause possibly exponential and latent CPU consumption

[ironcladlou]

I started an etcd instance, openshift master, and openshift node on Fedora 21. I have a bash script which makes 500 new projects:

#!/bin/bash

count=$1
rate=$2

if [ "${count}" == "" ]; then
  echo "count is required"
  exit 1
fi

for i in $(seq 1 $count); do
  id=$(cat /dev/urandom | tr -cd 'a-f0-0' | head -c 8)
  name="project-${id}"
  /usr/bin/time -f "${i},%e" bash -c "openshift cli new-project $name >/dev/null"
  if [ "${rate}" != "" ]; then
    sleep $rate
  fi
done

The result is CPU usage climbs and the master starts grinding down. Even long after I cut the script off at ~160 projects, master CPU consumption is still at like 60% but seems to be falling very, very gradually. I haven't yet graphed CPU consumption.

I'll attach the openshift cli new-project times and some pprof traces captured during and after the test duirng the weird "idle" period.

[ironcladlou]

X is project number, Y is time to run new-project

[ironcladlou]

Here's a 30s CPU profile from the time long after the test script stopped and while the master CPU consumption was still ~60%.

[ironcladlou]

Sorry I don't have a better place to put this right now, but:

https://drive.google.com/a/redhat.com/file/d/0BxiBh6KZZAOWQ0NMYXNuRnZjbWc/view?usp=sharing

I use this script to start profiling. I then use the script in the issue description to create 300 projects. The profiler script generates the following every 30s:

• pprof cpu graph
• pprof heap alloc_space graph
• system memory (ps)
• system memory (smem)

It was going too slow by the time it got to project 260 so I stopped it and the last several samples have nothing talking to the master. I'm actually still collecting and the CPU is still very high but very slowly scaling down. I'll continue to collect for a while.

[ironcladlou]

Detailed analysis including tarballs containing tons of useful stats: https://docs.google.com/a/redhat.com/spreadsheets/d/1pjTbc6HQaRdybzScXy2NGwg3vIO2qHR7VOChl6-vuYY/edit?usp=sharing

[ironcladlou]

A few things we discovered:

1. oc on the client side will get slower over repeated new-project calls as the local config file is rebuilt, accounting for increased operation times in my original tests
2. back project cache with local authorizer #5760 fixes a logarithmic request count growth associated with project creation which was causing high server CPU usage
3. There still seems to be an unexpectedly huge amount of server request handling and crypto library calls in idle and during project create calls, but we can continue to investigate those further.

The oc discovery combined with #5760 is enough to satisfy my main concerns for this issue, and I'll open followups once I've assessed the impact of item 3.

[ironcladlou]

cc @smarterclayton @liggitt, let's call #5760 a fix for this.

[deads2k]

@ironcladlou I liked the chart of requests. Any chance you ended up getting that fully automated?

[deads2k]

oc on the client side will get slower over repeated new-project calls as the local config file is rebuilt, accounting for increased operation times in my original tests

The slowdown is unexpectedly large at the scales here: #5737 (comment). Its a little better for me on my machine, but I was able to get over 10 seconds at about 300-400 projects. We should try to pin this down. It might just be a matter of generating conversions and codecs.

[smarterclayton]

I'm seeing a ton of garbage created - will look at it with your changes but
we are probably doing a few things in critical path we shouldn't be.

On Nov 6, 2015, at 6:19 PM, David Eads notifications@github.com wrote:

oc on the client side will get slower over repeated new-project calls as
the local config file is rebuilt, accounting for increased operation times
in my original tests

The slowdown is unexpectedly large at the scales here: #5737 (comment)
#5737 (comment).
Its a little better for me on my machine, but I was able to get over 10
seconds at about 300-400 projects. We should try to pin this down. It might
just be a matter of generating conversions and codecs.

—
Reply to this email directly or view it on GitHub
#5737 (comment).

[smarterclayton]

I want to leave this open even after we merge #5760 but will reduce the priority.