Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1343196

Summary:

Density e2e takes 60% longer on OpenShift due to ose-pod startup delay

Product:

OpenShift Container Platform

Reporter:

Mike Fiedler <mifiedle>

Component:

Node

Assignee:

Timothy St. Clair <tstclair>

Status:

CLOSED NOTABUG

QA Contact:

DeShuai Ma <dma>

Severity:

low

Docs Contact:

Priority:

low

Version:

3.2.1

CC:

agoldste, aos-bugs, bbennett, decarr, eparis, jeder, jokerman, mifiedle, mmccomas, rrati, tstclair

Target Milestone:

---

Target Release:

---

Hardware:

x86_64

OS:

Linux

Whiteboard:

Fixed In Version:

Doc Type:

If docs needed, set a value

Doc Text:

Story Points:

---

Clone Of:

Environment:

Last Closed:

2017-02-14 19:28:16 UTC

Type:

Bug

Regression:

---

Mount Type:

---

Documentation:

---

CRM:

Verified Versions:

Category:

---

oVirt Team:

---

RHEL 7.3 requirements from Atomic Host:

Cloudforms Team:

---

Target Upstream Version:

Embargoed:

Attachments:

Description	Flags
Density 100 pods per node Kubernetes results	none
Density 100 pods per node OpenShift results	none
OSE density results with requested change to node-config.yaml	none
ps auxwf during delay	none
Docker and node logs for density test on openshift	none

Description Mike Fiedler 2016-06-06 18:34:27 UTC

Description of problem:

The e2e density test to start 100 pods per node takes 60% longer on OpenShift 3.2.1 than it does on Kubernetes 1.2.4.   The apparent cause is that none of the application pods start running until all of the openshift3/ose-pod pods are started. The first application pods don't start running under OpenShift until 1m 10s into the test.  In Kubernetes, the application pods start right away (see details below in additional info).


Version-Release number of selected component (if applicable):
OpenShift v3.2.1.1-1 vs Kubernetes 1.2.4, both running on Docker 1.10.3

Both are running master + 2 nodes on AWS m4.xlarge instances


How reproducible: Always


Steps to Reproduce:
1. Install clusters
2. Run the e2e tests with focus="should allow starting 100 pods per node"

I verified by watching docker ps that none of the application pods are started until all 100 ose-pod pods have started

Note, you need to modify density.go to run on OpenShift since we don't expose the endpoint to reset metrics (1.2 version of tests) and have not yet adopted re-based Kubernetes 1.3 which resets the metrics with a DELETE on the metrics endpoint.   You can comment out the call to ResetMetrics() or you can get a binary from mffiedler

Results:   

Full results attached.

Kubernetes:  application pods start right away.  Time for test is 1m40s

Jun  6 18:06:15.929: INFO: Created replication controller with name: density200-0-5c7e8e5b-2c11-11e6-bea0-022f87834141, namespace: e2e-tests-density-d4gct, replica count: 200
Jun  6 18:06:25.925: INFO: Density Pods: 200 out of 200 created, 1 running, 199 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 18:06:35.925: INFO: Density Pods: 200 out of 200 created, 2 running, 198 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 18:06:45.925: INFO: Density Pods: 200 out of 200 created, 3 running, 197 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 18:06:55.925: INFO: Density Pods: 200 out of 200 created, 15 running, 185 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 18:07:05.925: INFO: Density Pods: 200 out of 200 created, 46 running, 154 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 18:07:15.925: INFO: Density Pods: 200 out of 200 created, 71 running, 129 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 18:07:25.925: INFO: Density Pods: 200 out of 200 created, 102 running, 98 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 18:07:35.925: INFO: Density Pods: 200 out of 200 created, 132 running, 68 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 18:07:45.925: INFO: Density Pods: 200 out of 200 created, 180 running, 20 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 18:07:55.925: INFO: Density Pods: 200 out of 200 created, 200 running, 0 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 18:07:55.932: INFO: E2E startup time for 200 pods: 1m40.00783213s
Jun  6 18:07:55.932: INFO: Throughput (pods/s) during cluster saturation phase: 2


OpenShift:  application pod start delayed.  Time for test is 2m40s


Jun  6 13:24:37.319: INFO: Created replication controller with name: density200-0-8b2a210c-2c0b-11e6-964f-02c436ffda23, namespace: e2e-tests-density-ilr22, replica count: 200
Jun  6 13:24:47.250: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 13:24:57.244: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 13:25:07.244: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 13:25:17.244: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 13:25:27.244: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 13:25:37.244: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 13:25:47.244: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 13:25:57.244: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 13:26:07.244: INFO: Density Pods: 200 out of 200 created, 9 running, 191 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 13:26:17.244: INFO: Density Pods: 200 out of 200 created, 28 running, 172 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 13:26:27.244: INFO: Density Pods: 200 out of 200 created, 46 running, 154 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 13:26:37.244: INFO: Density Pods: 200 out of 200 created, 64 running, 136 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 13:26:47.244: INFO: Density Pods: 200 out of 200 created, 87 running, 113 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 13:26:57.245: INFO: Density Pods: 200 out of 200 created, 108 running, 92 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 13:27:07.245: INFO: Density Pods: 200 out of 200 created, 141 running, 59 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 13:27:17.245: INFO: Density Pods: 200 out of 200 created, 200 running, 0 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Jun  6 13:27:17.326: INFO: E2E startup time for 200 pods: 2m40.082123191s
Jun  6 13:27:17.326: INFO: Throughput (pods/s) during cluster saturation phase: 1.25

Comment 1 Timothy St. Clair 2016-06-06 19:25:32 UTC

Thanks for creating the apples-to-apples test case!

Comment 2 Mike Fiedler 2016-06-06 19:50:46 UTC

Created attachment 1165356 [details]
Density 100 pods per node Kubernetes results

Comment 3 Mike Fiedler 2016-06-06 19:51:14 UTC

Created attachment 1165357 [details]
Density 100 pods per node OpenShift results

Comment 4 Andy Goldstein 2016-06-08 14:30:07 UTC

If you run the test against OSE multiple times, do the times improve or stay the same?

Comment 5 Mike Fiedler 2016-06-08 17:52:15 UTC

The times stay the same - the test tears down the namespace after each run and running containers in Docker always returns to 0.

Comment 6 Andy Goldstein 2016-06-08 17:53:59 UTC

Can you try editing the node-config.yaml file for each node, comment out the network plugin info, and then restart atomic-openshift-node and see if it goes any faster?

Comment 7 Mike Fiedler 2016-06-10 17:42:08 UTC

Created attachment 1166703 [details]
OSE density results with requested change to node-config.yaml

Comment 8 Andy Goldstein 2016-06-10 18:00:51 UTC

Jan, could you please look into this? 1 theory is that the openshift sdn plugin has a lot of file locking contention as part of setting up networking for new pods (I've verified this by looking at the output from `ps`), which is why I asked Mike to remove the sdn plugin setup from the node configs. Hopefully you can keep digging and found out what's going on. Thanks.

Comment 9 Jan Chaloupka 2016-08-17 13:24:57 UTC

==1-node cluster experiment==
# oc version
oc v3.3.0.21+335bd7b
kubernetes v1.3.0+507d3a7
features: Basic-Auth

Running "should allow starting 100 pods per node" test, startup time takes 1m40s:

Aug 17 09:16:33.450: INFO: Created replication controller with name: density100-0-d177366f-647c-11e6-af8a-fa163e614721, namespace: e2e-tests-density-7se7q, replica count: 100
Aug 17 09:16:43.437: INFO: Density Pods: 100 out of 100 created, 0 running, 100 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Aug 17 09:16:53.437: INFO: Density Pods: 100 out of 100 created, 0 running, 100 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Aug 17 09:17:03.437: INFO: Density Pods: 100 out of 100 created, 2 running, 98 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Aug 17 09:17:13.437: INFO: Density Pods: 100 out of 100 created, 4 running, 96 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Aug 17 09:17:23.437: INFO: Density Pods: 100 out of 100 created, 7 running, 93 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Aug 17 09:17:33.438: INFO: Density Pods: 100 out of 100 created, 8 running, 92 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Aug 17 09:17:33.446: INFO: Error while reading data from jchaloup-ose.localdomain: an error on the server has prevented the request from succeeding (post nodes jchaloup-ose.localdomain:10250)
Aug 17 09:17:43.437: INFO: Density Pods: 100 out of 100 created, 14 running, 86 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Aug 17 09:17:53.439: INFO: Density Pods: 100 out of 100 created, 21 running, 79 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Aug 17 09:18:03.437: INFO: Density Pods: 100 out of 100 created, 59 running, 41 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Aug 17 09:18:13.437: INFO: Density Pods: 100 out of 100 created, 100 running, 0 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Aug 17 09:18:13.452: INFO: E2E startup time for 100 pods: 1m40.016001738s
Aug 17 09:18:13.452: INFO: Throughput (pods/s) during cluster saturation phase: 1

Comment 10 Jan Chaloupka 2016-08-17 13:25:54 UTC

About to run the experiment with multi-node cluster.

Comment 11 Mike Fiedler 2016-08-17 20:49:40 UTC

I still see this on 3.3.0.18.   My setup is

1 master
1 registry/router
2 nodes

All are m4.xlarge (4 vCPU/16GB) on AWS EC2.

- OpenShift install is containerized (I'll try rpm tonight)
- Using the multitenant SDN plugin

3m20s for all nodes to start
Long period after pods created before any came running.   Verified on the node that the 100 ose-pod pods all started before any of the pause pods.

Aug 17 16:41:21.664: INFO: Created replication controller with name: density200-0-f4dc68c3-64ba-11e6-bd4c-02a86e5559df, namespace: e2e-tests-density-xqx2n, replica count: 200
Aug 17 16:41:31.617: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 16:41:41.617: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 16:41:51.617: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 16:42:01.617: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 16:42:11.617: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 16:42:21.617: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 16:42:31.617: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 16:42:41.617: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 16:42:51.617: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 16:43:01.617: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 16:43:11.617: INFO: Density Pods: 200 out of 200 created, 1 running, 199 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 16:43:21.617: INFO: Density Pods: 200 out of 200 created, 4 running, 196 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 16:43:31.617: INFO: Density Pods: 200 out of 200 created, 8 running, 192 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 16:43:41.617: INFO: Density Pods: 200 out of 200 created, 16 running, 184 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 16:43:51.617: INFO: Density Pods: 200 out of 200 created, 24 running, 176 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 16:44:01.617: INFO: Density Pods: 200 out of 200 created, 36 running, 164 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 16:44:11.617: INFO: Density Pods: 200 out of 200 created, 49 running, 151 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 16:44:21.617: INFO: Density Pods: 200 out of 200 created, 88 running, 112 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 16:44:31.617: INFO: Density Pods: 200 out of 200 created, 138 running, 62 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 16:44:41.617: INFO: Density Pods: 200 out of 200 created, 200 running, 0 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 16:44:41.672: INFO: E2E startup time for 200 pods: 3m20.055176094s

Comment 12 Mike Fiedler 2016-08-18 00:57:47 UTC

rpm install of 3.3.0.21 in the same cluster config as comment 11 was faster than the containerized install, but it was still 2m40 (same as original bug description) vs 1m40 for k8s and the test fails to meet the pass/fail criteria.

• Failure in Spec Teardown (AfterEach) [220.442 seconds]
[k8s.io] Density
/root/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/test/e2e/framework/framework.go:685
  [Feature:ManualPerformance] should allow starting 100 pods per node [AfterEach]
  /root/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/test/e2e/density.go:632

  Expected
      <time.Duration>: 160050102852
  not to be >
      <time.Duration>: 120000000000




Aug 17 20:48:59.414: INFO: Created replication controller with name: density200-0-8cc60369-64dd-11e6-8927-024594a7cebd, namespace: e2e-tests-density-8fh0e, replica count: 200
Aug 17 20:49:09.372: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 20:49:19.372: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 20:49:29.372: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 20:49:39.372: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 20:49:49.372: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 20:49:59.373: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 20:50:09.372: INFO: Density Pods: 200 out of 200 created, 1 running, 199 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 20:50:19.372: INFO: Density Pods: 200 out of 200 created, 1 running, 199 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 20:50:29.372: INFO: Density Pods: 200 out of 200 created, 2 running, 198 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 20:50:39.372: INFO: Density Pods: 200 out of 200 created, 7 running, 193 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 20:50:49.372: INFO: Density Pods: 200 out of 200 created, 18 running, 182 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 20:50:59.372: INFO: Density Pods: 200 out of 200 created, 25 running, 175 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 20:51:09.372: INFO: Density Pods: 200 out of 200 created, 35 running, 165 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 20:51:19.372: INFO: Density Pods: 200 out of 200 created, 44 running, 156 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 20:51:29.372: INFO: Density Pods: 200 out of 200 created, 61 running, 139 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 20:51:39.373: INFO: Density Pods: 200 out of 200 created, 200 running, 0 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 17 20:51:39.422: INFO: E2E startup time for 200 pods: 2m40.050102852s

Comment 13 Jan Chaloupka 2016-08-18 15:06:27 UTC

==3-node cluster experiment==
- flavor: m4.xlarge
- oc v3.3.0.22-1-gda84acd
- kubernetes v1.3.0+507d3a7
- building from master head da84acd4e710e8380044bb6b0a5d1e62e60193f1
- cluster:
  - nodes: 10.8.168.79, 10.8.168.8
  - master: 10.8.168.80

Aug 18 10:58:01.294: INFO: Created replication controller with name: density200-0-2884a486-6554-11e6-ab78-fa163eea056e, namespace: e2e-tests-density-9upio, replica count: 200
Aug 18 10:58:11.283: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Aug 18 10:58:21.283: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Aug 18 10:58:31.283: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Aug 18 10:58:41.283: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Aug 18 10:58:51.283: INFO: Density Pods: 200 out of 200 created, 13 running, 187 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Aug 18 10:59:01.283: INFO: Density Pods: 200 out of 200 created, 47 running, 153 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Aug 18 10:59:11.283: INFO: Density Pods: 200 out of 200 created, 200 running, 0 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Aug 18 10:59:11.296: INFO: E2E startup time for 200 pods: 1m10.013916202s
Aug 18 10:59:11.296: INFO: Throughput (pods/s) during cluster saturation phase: 2.857143

• Failure in Spec Teardown (AfterEach) [127.294 seconds]
[k8s.io] Density
/root/ose/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/test/e2e/framework/framework.go:685
  [Feature:ManualPerformance] should allow starting 100 pods per node [AfterEach]
  /root/ose/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/test/e2e/density.go:632

  There should be no high-latency requests
  Expected
      <int>: 2
  not to be >
      <int>: 0

Mike, is it possible the "2m40s" is AWS network specific issue?

Comment 14 Jan Chaloupka 2016-08-18 15:10:45 UTC

Deploying the cluster with openshift-ansible, non-containerized, from rpms.

Comment 19 Mike Fiedler 2016-08-19 14:36:31 UTC

Tried updating an existing cluster per comment 17 but didn't have any luck - something still trying to use multitenant.  I'm going to try a new install and specify "" in ansible 

1.  master-config.yaml

networkConfig:
# clusterNetworkCIDR: 172.20.0.0/14
# hostSubnetLength: 8
# networkPluginName: redhat/openshift-ovs-multitenant
# serviceNetworkCIDR must match kubernetesMasterConfig.servicesSubnet
  externalIPNetworkCIDRs: null
  serviceNetworkCIDR: 172.24.0.0/14

2. node-config.yaml on all nodes

networkConfig:
   mtu: 8951


3. restarted atomic-openshift-master, atomic-openshift-node and iptables everywhere.   Did I miss something?   Getting this when pods try to start:

2016-08-19T10:18:23-04:00   2016-08-19T10:15:21-04:00   4         density200-0-2b3bee68-6617-11e6-b87a-024594a7cebd-b0kij   Pod                 Warning   FailedSync   {kubelet ip-172-31-22-64.us-west-2.compute.internal}   Error syncing pod, skipping: failed to "SetupNetwork" for "density200-0-2b3bee68-6617-11e6-b87a-024594a7cebd-b0kij_e2e-tests-density-n0zkv" with SetupNetworkError: "Failed to setup network for pod \"density200-0-2b3bee68-6617-11e6-b87a-024594a7cebd-b0kij_e2e-tests-density-n0zkv(2c42a514-6617-11e6-b90c-024594a7cebd)\" using network plugins \"redhat/openshift-ovs-multitenant\": Failed to find netid for namespace: e2e-tests-density-n0zkv in vnid map; Skipping pod"


In any case, spinning up a new install now

Comment 20 Rajat Chopra 2016-08-19 15:20:46 UTC

To be clear, both node-config.yaml and master-config.yaml need to have networkPluginName as "" (empty).

Comment 21 Mike Fiedler 2016-08-19 17:37:16 UTC

I ran the test with the following:

master-config.yaml:

networkConfig:
  clusterNetworkCIDR: 172.20.0.0/14
  hostSubnetLength: 8
  networkPluginName: ""                         
  externalIPNetworkCIDRs: null
# serviceNetworkCIDR must match kubernetesMasterConfig.servicesSubnet
  serviceNetworkCIDR: 172.24.0.0/14

Without clusterNetworkCIDR, atomic-openshift-master would not start

node-config.yaml:

networkConfig:
   networkPluginName: ""
   mtu: 8951


Results were the same, though.  3 minutes to start and the same long delay before the first pod goes to Running.

Aug 19 13:24:40.149: INFO: Created replication controller with name: density200-0-cf713afa-6631-11e6-b182-02c95f3a7fd1, namespace: e2e-tests-density-hs7jh, replica count: 200
Aug 19 13:24:50.112: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 13:25:00.112: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 13:25:10.112: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 13:25:20.112: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 13:25:30.112: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 13:25:40.112: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 13:25:50.112: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 13:26:00.112: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 13:26:10.112: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 13:26:20.112: INFO: Density Pods: 200 out of 200 created, 4 running, 196 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 13:26:30.112: INFO: Density Pods: 200 out of 200 created, 10 running, 190 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 13:26:40.112: INFO: Density Pods: 200 out of 200 created, 15 running, 185 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 13:26:50.112: INFO: Density Pods: 200 out of 200 created, 25 running, 175 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 13:27:00.112: INFO: Density Pods: 200 out of 200 created, 33 running, 167 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 13:27:10.118: INFO: Density Pods: 200 out of 200 created, 46 running, 154 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 13:27:20.112: INFO: Density Pods: 200 out of 200 created, 108 running, 92 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 13:27:30.113: INFO: Density Pods: 200 out of 200 created, 135 running, 65 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 13:27:40.113: INFO: Density Pods: 200 out of 200 created, 200 running, 0 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 13:27:40.158: INFO: E2E startup time for 200 pods: 3m0.046217797s

Comment 22 Andy Goldstein 2016-08-19 17:58:10 UTC

I jumped on the cluster and despite removing the sdn config settings from node-config.yaml, the sdn plugin is still enabled:

Initializing SDN node of type "redhat/openshift-ovs-subnet" with configured hostname "ip-172-31-7-32.us-west-2.compute.internal" (IP ""), iptables sync period "30


ps auxwf yields:

root      16150  5.1  0.9 3983024 153568 ?      Ssl  13:18   1:40 /usr/bin/openshift start node --config=/etc/origin/node/node-config.yaml --loglevel=2
root      16269  0.0  0.0 217240 12612 ?        S    13:18   0:00  \_ journalctl -k -f
root      72754  0.0  0.0 115240  1480 ?        S    13:50   0:00  \_ /bin/bash /usr/bin/openshift-sdn-ovs setup d8183e61f8f5273aec6ddf6d0fe22063a57690ec0a56f96506c52117aafeab36 0   false
root      72760  0.0  0.0 115240   856 ?        S    13:50   0:00  |   \_ /bin/bash /usr/bin/openshift-sdn-ovs setup d8183e61f8f5273aec6ddf6d0fe22063a57690ec0a56f96506c52117aafeab36 0   false
root      72764  0.0  0.0 107888   360 ?        S    13:50   0:00  |       \_ flock 200
root      73166  0.0  0.0 115240  1484 ?        S    13:50   0:00  \_ /bin/bash /usr/bin/openshift-sdn-ovs setup 12c2f839598fa6161a98f1511b45af58c4d5a6dfaa39a81392a474799a34d355 0   false
root      73167  0.0  0.0 115240   860 ?        S    13:50   0:00  |   \_ /bin/bash /usr/bin/openshift-sdn-ovs setup 12c2f839598fa6161a98f1511b45af58c4d5a6dfaa39a81392a474799a34d355 0   false
root      73168  0.0  0.0 107888   356 ?        S    13:50   0:00  |       \_ flock 200
.......

Comment 23 Mike Fiedler 2016-08-19 18:27:47 UTC

Thanks to danw, got SDN fully disabled.   oc delete clusternetwork default was the trick.   No "Initializing SDN" on node startup and no openshift-sdn-ovs processes during the run. 

However, results are unchanged:

Aug 19 14:13:06.849: INFO: Created replication controller with name: density200-0-93f6d8c4-6638-11e6-bf50-02c95f3a7fd1, namespace: e2e-tests-density-985ow, replica count: 200
Aug 19 14:13:16.803: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 14:13:26.803: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 14:13:36.803: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 14:13:46.803: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 14:13:56.803: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 14:14:06.803: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 14:14:16.803: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 14:14:26.803: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 14:14:36.803: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 14:14:46.803: INFO: Density Pods: 200 out of 200 created, 5 running, 195 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 14:14:56.803: INFO: Density Pods: 200 out of 200 created, 16 running, 184 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 14:15:06.803: INFO: Density Pods: 200 out of 200 created, 26 running, 174 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 14:15:16.803: INFO: Density Pods: 200 out of 200 created, 38 running, 162 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 14:15:26.803: INFO: Density Pods: 200 out of 200 created, 54 running, 146 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 14:15:36.803: INFO: Density Pods: 200 out of 200 created, 71 running, 129 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 14:15:46.803: INFO: Density Pods: 200 out of 200 created, 138 running, 62 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 14:15:56.803: INFO: Density Pods: 200 out of 200 created, 143 running, 57 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 14:16:06.803: INFO: Density Pods: 200 out of 200 created, 200 running, 0 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
Aug 19 14:16:06.855: INFO: E2E startup time for 200 pods: 3m0.052372713s


ps auxwf during the "delay" attached

Comment 24 Mike Fiedler 2016-08-19 18:29:02 UTC

Created attachment 1192261 [details]
ps auxwf during delay

Comment 26 Derek Carr 2016-08-19 20:32:21 UTC

Other theory re: apples to apples testing: 

when you ran upstream kubernetes, you ran with fewer admission plug-ins.  Can you specify the list of upstream admission plug-ins you ran so we can compare the default set in origin?

Comment 27 Mike Fiedler 2016-08-21 16:08:59 UTC

Created attachment 1192623 [details]
Docker and node logs for density test on openshift

docker and node log attached

Comment 28 Mike Fiedler 2016-08-21 19:33:40 UTC

re:  comment 26.   Upstream Kubernetes 1.3:

--admission-control=NamespaceLifecycle,NamespaceExists,LimitRanger,ServiceAccount,ResourceQuota

OpenShift: OOTB controllers, no custom admissionConfig.   (How do I display active admission plugins for OpenShift?)

Comment 29 Andy Goldstein 2016-08-22 20:28:02 UTC

Mike, can you edit the 2 (two!) admissionConfig sections in master-config.yaml so they look like this, restart the master, and rerun your test?

admissionConfig:
  pluginOrderOverride:
  - NamespaceLifecycle
  - NamespaceExists
  - LimitRanger
  - ServiceAccount
  - ResourceQuota


Also, given that OpenShift is performing additional functionality (SDN, additional admission plugins, additional security among other things), the upstream Kube density performance numbers are probably not applicable to OpenShift without some modifications  (i.e. it will take longer to run the same number of pods).

I ran some tests today using OpenShift built from source on a single m4.xlarge AWS VM. This is by no means a valid comparison to how Mike deployed, since I wasn't using the installer, I wasn't running containerized, and I had an all-in-one, but, here are the results:

origin master, origin admission: 2m20s
origin master, kube admission: 2m20s
kube master: 2m40s
kube v1.3.5: unable to complete due to failed containers, but was much slower than the other 3 tests

Comment 30 Mike Fiedler 2016-08-22 22:24:42 UTC

I'll set something up to run that test.   Despite the title of this bug my biggest concern here wasn't the time difference.  tstclair and I noticed how long it was taking for the first pod to come ready/running under OpenShift vs k8s and thought that should be investigated.   I think (maybe naively) that it would be a positive for the first pods for a service to be ready to service requests very quickly.   How long it takes for the remainder to come to Running is probably of less consequence.

Comment 31 Mike Fiedler 2016-08-22 23:36:38 UTC

Set the admissionConfig as specified in comment 29, restarted the master service, ran the test once as a warmup and then ran it again.   The results were essentially the same:

 13:   36 Aug 22 19:05:17.494: INFO: Created replication controller with name: density200-0-e4476864-68bc-11e6-9b2e-02c95f3a7fd1, namespace: e2e-tests-density-g7zm1, replica count: 200
 14:   37 Aug 22 19:05:27.443: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
 15:   38 Aug 22 19:05:37.443: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
 16:   39 Aug 22 19:05:47.443: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
 17:   40 Aug 22 19:05:57.443: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
 18:   41 Aug 22 19:06:07.443: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
 19:   42 Aug 22 19:06:17.443: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
 20:   43 Aug 22 19:06:27.443: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
 21:   44 Aug 22 19:06:37.443: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
 22:   45 Aug 22 19:06:47.443: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
 23:   46 Aug 22 19:06:57.443: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
 24:   47 Aug 22 19:07:07.443: INFO: Density Pods: 200 out of 200 created, 2 running, 198 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
 25:   48 Aug 22 19:07:17.443: INFO: Density Pods: 200 out of 200 created, 8 running, 192 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
 26:   49 Aug 22 19:07:27.443: INFO: Density Pods: 200 out of 200 created, 22 running, 178 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
 27:   50 Aug 22 19:07:37.443: INFO: Density Pods: 200 out of 200 created, 36 running, 164 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
 28:   51 Aug 22 19:07:47.443: INFO: Density Pods: 200 out of 200 created, 45 running, 155 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
 29:   52 Aug 22 19:07:57.443: INFO: Density Pods: 200 out of 200 created, 57 running, 143 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
 30:   53 Aug 22 19:08:07.443: INFO: Density Pods: 200 out of 200 created, 70 running, 130 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
 31:   54 Aug 22 19:08:17.443: INFO: Density Pods: 200 out of 200 created, 159 running, 41 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
 32:   55 Aug 22 19:08:27.443: INFO: Density Pods: 200 out of 200 created, 200 running, 0 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
 33:   56 Aug 22 19:08:27.501: INFO: E2E startup time for 200 pods: 3m10.057974003s

Comment 34 Mike Fiedler 2017-02-14 19:08:04 UTC

OCP 3.5.0.18:

Feb 14 13:59:43.974: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
^[[5~^[[5~^[[5~Feb 14 13:59:53.974: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 14:00:03.974: INFO: Density Pods: 200 out of 200 created, 1 running, 199 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 14:00:13.974: INFO: Density Pods: 200 out of 200 created, 1 running, 199 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 14:00:23.974: INFO: Density Pods: 200 out of 200 created, 1 running, 199 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 14:00:33.974: INFO: Density Pods: 200 out of 200 created, 1 running, 199 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 14:00:43.974: INFO: Density Pods: 200 out of 200 created, 1 running, 199 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 14:00:53.974: INFO: Density Pods: 200 out of 200 created, 1 running, 199 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 14:01:03.974: INFO: Density Pods: 200 out of 200 created, 3 running, 197 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 14:01:13.974: INFO: Density Pods: 200 out of 200 created, 8 running, 192 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 14:01:23.974: INFO: Density Pods: 200 out of 200 created, 18 running, 182 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 14:01:33.974: INFO: Density Pods: 200 out of 200 created, 28 running, 172 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 14:01:43.974: INFO: Density Pods: 200 out of 200 created, 38 running, 162 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 14:01:53.974: INFO: Density Pods: 200 out of 200 created, 53 running, 147 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 14:02:03.974: INFO: Density Pods: 200 out of 200 created, 194 running, 6 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 14:02:13.974: INFO: Density Pods: 200 out of 200 created, 200 running, 0 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 14:02:13.993: INFO: E2E startup time for 200 pods: 2m40.019242294s
Feb 14 14:02:13.993: INFO: Throughput (pods/s) during cluster saturation phase: 1.25

Kubernetes 1.5.2 installed via kubeadm:

I0214 13:50:18.990395   48537 reflector.go:234] Listing and watching *api.Pod from github.com/openshift/origin/vendor/k8s.io/kubernetes/test/utils/pod_store.go:52
Feb 14 13:50:28.978: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 13:50:38.978: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 13:50:48.978: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 13:50:58.978: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 13:51:08.978: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 13:51:18.978: INFO: Density Pods: 200 out of 200 created, 0 running, 200 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 13:51:28.978: INFO: Density Pods: 200 out of 200 created, 24 running, 176 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 13:51:38.978: INFO: Density Pods: 200 out of 200 created, 27 running, 173 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 13:51:48.978: INFO: Density Pods: 200 out of 200 created, 30 running, 170 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 13:51:58.978: INFO: Density Pods: 200 out of 200 created, 34 running, 166 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 13:52:08.978: INFO: Density Pods: 200 out of 200 created, 46 running, 154 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 13:52:18.978: INFO: Density Pods: 200 out of 200 created, 65 running, 135 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 13:52:28.978: INFO: Density Pods: 200 out of 200 created, 74 running, 126 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 13:52:38.978: INFO: Density Pods: 200 out of 200 created, 81 running, 119 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 13:52:48.978: INFO: Density Pods: 200 out of 200 created, 99 running, 101 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 13:52:58.978: INFO: Density Pods: 200 out of 200 created, 129 running, 71 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 13:53:08.978: INFO: Density Pods: 200 out of 200 created, 172 running, 28 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 13:53:18.978: INFO: Density Pods: 200 out of 200 created, 195 running, 5 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 13:53:28.978: INFO: Density Pods: 200 out of 200 created, 200 running, 0 pending, 0 waiting, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
Feb 14 13:53:28.995: INFO: E2E startup time for 200 pods: 3m10.017874754s
Feb 14 13:53:28.995: INFO: Throughput (pods/s) during cluster saturation phase: 1.0526316


So, OCP 3.5 is on par with earlier versions and Kubernetes 1.5.2 is much slower than 1.4.    I'll try to bi-sect that.  NOTABUG?  or is there something to run down here?