Bug 1426009

Summary: 3.5: oc get commands on large numbers of resources 90-300% slower than OCP 3.4
Product: OpenShift Container Platform Reporter: Mike Fiedler <mifiedle>
Component: ocAssignee: Maciej Szulik <maszulik>
Status: CLOSED DEFERRED QA Contact: Mike Fiedler <mifiedle>
Severity: low Docs Contact:
Priority: low    
Version: 3.5.0CC: aos-bugs, ccoleman, deads, emarcian, jokerman, mfojtik, mifiedle, mmccomas, vlaad
Target Milestone: ---Keywords: Regression
Target Release: 3.5.z   
Hardware: x86_64   
OS: Linux   
Whiteboard: aos-scalability-35
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-02-26 15:38:03 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
cluster-loader input file to reproduce this none

Description Mike Fiedler 2017-02-23 01:38:04 UTC
Created attachment 1256754 [details]
cluster-loader input file to reproduce this

Description of problem:

Even with the fix for https://bugzilla.redhat.com/show_bug.cgi?id=1421401, oc get commands for large numbers of resources across many namespaces is significantly slower in 3.5 than it was in 3.4 on identically configured clusters

Version-Release number of selected component (if applicable): 3.5.0.31


How reproducible: Always, with large #s of resources


Steps to Reproduce:
1.  Identical 3.4 and 3.5 clusters on AWS.  1 m4.xlarge master, 1 m4.xlarge etcd, 1 m4.xlarge infra (router/registry), 2 m4.xlarge application nodes
2.  Run cluster-loader.py (https://github.com/openshift/svt/tree/master/openshift_scalability) with the attached yaml configuration file on both clusters - it will take a few hours to run and populate both clusters with 1000 projects with thousands of total dc, bc, routes, services, imagestreams, etc. across namespaces.
3. Compare timing of oc get --all-namespaces for various resource types on each cluster

Smaller numbers of total resources can reproduce this as well - e.g. 10000 secrets across 500 projects - but this reproducer is reliable.


Actual results:

3.5 oc get --all-namespaces is significantly slower for all resource types

Expected results:

No regression in oc get time from OCP 3.4


Additional info:

29K secrets - 3.4: 19.2s   3.5:  36.9s
2K routes   - 3.4: 2.9s    3.5:   9.0s
5K dc       - 3.4: 3.2s    3.5:  10.2s
3K bc       - 3.4: 0.8s    3.5:   2.8s

and so on.

Running with --loglevel=6 there is a noticeable and significant difference in the amount of time between the final 2 log messages and then the final log message and the beginning of output.

3.4


I0222 20:30:20.240392   19206 cached_discovery.go:38] returning cached discovery info from /root/.kube/ip_172_31_55_223.us_west_2.compute.internal_8443/v1/serverresources.json
I0222 20:30:20.826442   19206 round_trippers.go:318] GET https://ip-172-31-55-223.us-west-2.compute.internal:8443/oapi/v1/deploymentconfigs 200 OK in 585 milliseconds

Output begins almost immediately after this final message

3.5

222 20:30:11.154199    5201 cached_discovery.go:112] returning cached discovery info from /root/.kube/ip_172_31_55_228.us_west_2.compute.internal_8443/servergroups.json
I0222 20:30:13.338921    5201 round_trippers.go:318] GET https://ip-172-31-55-228.us-west-2.compute.internal:8443/oapi/v1/deploymentconfigs 200 OK in 2184 milliseconds

Output begins several seconds after this final message

At loglevel=8 there is too much output to tell what is happening.   Is there anyway to redirect CLI logging somewhere other than stdout?

Comment 1 Mike Fiedler 2017-02-23 01:41:14 UTC
Contact me for clusters reproducing this.   Will try to keep them up through week's end.

Comment 2 Fabiano Franz 2017-02-24 22:22:40 UTC
Adding David, Andy and Clayton for opinions.

The issue here is the change to make basic crud commands to be agnostic of registered types, which happened in the 3.4->3.5 timeframe. 

In summary, using unstructured objects means unmarshalling json into maps of interfaces, which is known for having poor performance and, multiplied by thousands of objects like is the case here, can lead to many seconds just doing plain unmarshaling. I was able to confirm that by debugging and analyzing profiling reports generated by pproc.

There are basically two places where it hurts badly in the 'get' command: 

1. The actual unmarshaling to unstructured objects when the Visitor's visits happen (a single call to `Infos()` took 18 seconds for 29k secrets.
2. The conversion needed for printing here[1], which took around 12s for the same sampling.

We could use a typed structure and fallback to unstructured in the case of TPR and others, but that would lead to a lot of special-case code. Another option would be to try to solve the second problem by making the printer understand and "map" unstructured to its proper kind while printing, which would make it better but only solve part of the issue. Or, we could postpone this until we move get printing to server-side.

So any other suggestions about how to fix this?

[1] https://github.com/deads2k/kubernetes/blob/61673c4b39606fc7e1de9a3cdd4ff5aaaebc0f31/pkg/kubectl/resource_printer.go#L2263-L2272

Comment 3 Fabiano Franz 2017-02-24 22:27:46 UTC
Also: changing to a better performing JSON library doesn't help here, I tried ffjson[1] and easyjson[2]. The problem is inherent to unmarshalling to interfaces and better performing libs don't fix that, in most cases they just delegate to 'encoding/json' when dealing with structures like that.

[1] https://github.com/pquerna/ffjson
[2] https://github.com/mailru/easyjson

Comment 4 Clayton Coleman 2017-02-24 22:54:08 UTC
Moving printing to the server side fixes the bulk of this.  We should also have a way for the JSON printer to avoid having to decode the returned object if possible.

Comment 5 Fabiano Franz 2017-02-27 16:34:42 UTC
Ok, so we mark this UpcomingRelease?

Comment 6 Andy Goldstein 2017-05-02 18:35:48 UTC
Is there anything we can do for 3.6 or do we need to wait for printing to move to the server?

Comment 7 Fabiano Franz 2017-05-10 13:27:55 UTC
> Is there anything we can do for 3.6 or do we need to wait for printing to move to the server?

Nothing substantial since UnstructuredObject is now at the core of client-side printers.

Comment 8 Fabiano Franz 2017-06-27 14:11:25 UTC
A fix is coming most likely with the rebase of Kube 1.8.

Comment 11 Maciej Szulik 2019-02-26 15:38:03 UTC
I'm closing this in favour of https://bugzilla.redhat.com/show_bug.cgi?id=1626291 which is currently tracking the performance impact.