Bug 1374645

Summary: "oc exec" have performance degression if there is clock skew between the master and nodes
Product: OpenShift Container Platform Reporter: Johnny Liu <jialiu>
Component: NodeAssignee: Paul Morie <pmorie>
Status: CLOSED WONTFIX QA Contact: Xiaoli Tian <xtian>
Severity: low Docs Contact:
Priority: low    
Version: 3.3.0CC: aos-bugs, clichybi, gblomqui, jokerman, mmccomas, wmeng
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-07-03 15:24:34 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:

Description Johnny Liu 2016-09-09 10:09:55 UTC 
Description of problem:
"oc exec" have performance degression if set master's clock slower than node.

Version-Release number of selected component (if applicable):
atomic-openshift-3.3.0.30-1.git.0.c5ee292.el7.x86_64

How reproducible:
Always

Steps to Reproduce:
1. set master's clock 1 second faster than node, "oc exec" has no obvious performance degression.
[root@openshift-216 ~]# time (echo "node: $(oc exec docker-registry-2-05o8i -- date -u)"; echo "master: $(date -u)")
node: Thu Sep  8 11:05:44 UTC 2016
master: Thu Sep  8 11:05:44 UTC 2016

real        0m0.428s
user        0m0.206s
sys        0m0.064s
[root@openshift-216 ~]# date -u -s "11:07:44"    
Thu Sep  8 11:07:44 UTC 2016
[root@openshift-216 ~]# time (echo "node: $(oc exec docker-registry-2-05o8i -- date -u)"; echo "master: $(date -u)")
node: Thu Sep  8 11:06:09 UTC 2016
master: Thu Sep  8 11:07:46 UTC 2016

real        0m0.433s
user        0m0.224s
sys        0m0.054s
2. set master's clock 1 second slower than node, obvious performance degression is seen.
[root@openshift-216 ~]# date -u -s "11:05:44"
Thu Sep  8 11:05:44 UTC 2016

[root@openshift-216 ~]# time (echo "node: $(oc exec docker-registry-2-05o8i -- date -u)"; echo "master: $(date -u)")
node: Thu Sep  8 11:08:33 UTC 2016
master: Thu Sep  8 11:07:54 UTC 2016

real        2m8.681s
user        0m0.237s
sys        0m0.073s
3. run the command again, performance degression disappear.
[root@openshift-216 ~]# time (echo "node: $(oc exec docker-registry-2-05o8i -- date -u)"; echo "master: $(date -u)")
node: Thu Sep  8 11:15:59 UTC 2016
master: Thu Sep  8 11:15:20 UTC 2016

real        0m0.509s
user        0m0.231s
sys        0m0.084s
4. skew master's clock 10 seconds faster than node, more delays are seen.
[root@openshift-216 ~]# time (echo "node: $(oc exec docker-registry-2-05o8i -- date -u)"; echo "master: $(date -u)")
node: Thu Sep  8 12:12:12 UTC 2016
master: Thu Sep  8 12:08:14 UTC 2016

real        0m0.489s
user        0m0.239s
sys        0m0.080s
[root@openshift-216 ~]# date -u -s "12:02:00"
Thu Sep  8 12:02:00 UTC 2016
[root@openshift-216 ~]# time (echo "node: $(oc exec docker-registry-2-05o8i -- date -u)"; echo "master: $(date -u)")
node: Thu Sep  8 12:19:11 UTC 2016
master: Thu Sep  8 12:08:34 UTC 2016

real        6m32.228s
user        0m0.299s
sys        0m0.083s

Actual results:
performance degression for "oc exec" is seen.

[root@openshift-216 ~]# date -u -s "08:23:02"
Fri Sep  9 08:23:02 UTC 2016
[root@openshift-216 ~]# oc exec --loglevel=8 docker-registry-2-05o8i -- date -u
I0909 04:23:05.047937   33390 loader.go:330] Config loaded from file /root/.kube/config
I0909 04:23:05.059670   33390 round_trippers.go:296] GET https://openshift-216.lab.sjc.redhat.com:8443/api
I0909 04:23:05.059704   33390 round_trippers.go:303] Request Headers:
I0909 04:23:05.059714   33390 round_trippers.go:306]     Accept: application/json, */*
I0909 04:23:05.059745   33390 round_trippers.go:306]     User-Agent: oc/v1.3.0+52492b4 (linux/amd64) kubernetes/52492b4
I0909 04:23:05.127008   33390 round_trippers.go:321] Response Status: 200 OK in 67 milliseconds
I0909 04:23:05.127072   33390 round_trippers.go:324] Response Headers:
I0909 04:23:05.127084   33390 round_trippers.go:327]     Cache-Control: no-store
I0909 04:23:05.127095   33390 round_trippers.go:327]     Content-Type: application/json
I0909 04:23:05.127105   33390 round_trippers.go:327]     Date: Fri, 09 Sep 2016 08:23:05 GMT
I0909 04:23:05.127116   33390 round_trippers.go:327]     Content-Length: 136
I0909 04:23:05.127237   33390 request.go:901] Response Body: {"kind":"APIVersions","versions":["v1"],"serverAddressByClientCIDRs":[{"clientCIDR":"0.0.0.0/0","serverAddress":"192.168.1.203:8443"}]}
I0909 04:23:05.127893   33390 round_trippers.go:296] GET https://openshift-216.lab.sjc.redhat.com:8443/apis
I0909 04:23:05.127908   33390 round_trippers.go:303] Request Headers:
I0909 04:23:05.127918   33390 round_trippers.go:306]     Accept: application/json, */*
I0909 04:23:05.127928   33390 round_trippers.go:306]     User-Agent: oc/v1.3.0+52492b4 (linux/amd64) kubernetes/52492b4
I0909 04:23:05.129456   33390 round_trippers.go:321] Response Status: 200 OK in 1 milliseconds
I0909 04:23:05.129489   33390 round_trippers.go:324] Response Headers:
I0909 04:23:05.129500   33390 round_trippers.go:327]     Cache-Control: no-store
I0909 04:23:05.129511   33390 round_trippers.go:327]     Content-Type: application/json
I0909 04:23:05.129522   33390 round_trippers.go:327]     Date: Fri, 09 Sep 2016 08:23:05 GMT
I0909 04:23:05.129533   33390 round_trippers.go:327]     Content-Length: 1382
I0909 04:23:05.129618   33390 request.go:901] Response Body: {"kind":"APIGroupList","groups":[{"name":"apps","versions":[{"groupVersion":"apps/v1alpha1","version":"v1alpha1"}],"preferredVersion":{"groupVersion":"apps/v1alpha1","version":"v1alpha1"},"serverAddressByClientCIDRs":[{"clientCIDR":"0.0.0.0/0","serverAddress":"192.168.1.203:8443"}]},{"name":"authentication.k8s.io","versions":[{"groupVersion":"authentication.k8s.io/v1beta1","version":"v1beta1"}],"preferredVersion":{"groupVersion":"authentication.k8s.io/v1beta1","version":"v1beta1"},"serverAddressByClientCIDRs":[{"clientCIDR":"0.0.0.0/0","serverAddress":"192.168.1.203:8443"}]},{"name":"autoscaling","versions":[{"groupVersion":"autoscaling/v1","version":"v1"}],"preferredVersion":{"groupVersion":"autoscaling/v1","version":"v1"},"serverAddressByClientCIDRs":[{"clientCIDR":"0.0.0.0/0","serverAddress":"192.168.1.203:8443"}]},{"name":"batch","versions":[{"groupVersion":"batch/v1","version":"v1"},{"groupVersion":"batch/v2alpha1","version":"v2alpha1"}],"preferredVersion":{"groupVersion":"batch/v1","version":"v1"},"serverAddressByClientCIDRs":[{"clientCIDR":"0.0.0.0/0","serverAddress":"192.168.1.203:8443"}]},{"name":"extensions","versions":[{"groupVersion":"extensions/v1beta1","version":"v1beta1"}],"preferredVersion":{"groupVersion":"extensions/v1beta1","version":"v1beta1"},"serverAddressByClientCIDRs":[{"clientCIDR":"0.0.0.0/0","serverAddress":"192.168.1.203:8443"}]}]}
I0909 04:23:05.132454   33390 round_trippers.go:296] GET https://openshift-216.lab.sjc.redhat.com:8443/api
I0909 04:23:05.132476   33390 round_trippers.go:303] Request Headers:
I0909 04:23:05.132486   33390 round_trippers.go:306]     Accept: application/json, */*
I0909 04:23:05.132496   33390 round_trippers.go:306]     User-Agent: oc/v1.3.0+52492b4 (linux/amd64) kubernetes/52492b4
I0909 04:23:05.133565   33390 round_trippers.go:321] Response Status: 200 OK in 1 milliseconds
I0909 04:23:05.133588   33390 round_trippers.go:324] Response Headers:
I0909 04:23:05.133599   33390 round_trippers.go:327]     Date: Fri, 09 Sep 2016 08:23:05 GMT
I0909 04:23:05.133610   33390 round_trippers.go:327]     Content-Length: 136
I0909 04:23:05.133621   33390 round_trippers.go:327]     Cache-Control: no-store
I0909 04:23:05.133631   33390 round_trippers.go:327]     Content-Type: application/json
I0909 04:23:05.133716   33390 request.go:901] Response Body: {"kind":"APIVersions","versions":["v1"],"serverAddressByClientCIDRs":[{"clientCIDR":"0.0.0.0/0","serverAddress":"192.168.1.203:8443"}]}
I0909 04:23:05.133992   33390 round_trippers.go:296] GET https://openshift-216.lab.sjc.redhat.com:8443/apis
I0909 04:23:05.134006   33390 round_trippers.go:303] Request Headers:
I0909 04:23:05.134016   33390 round_trippers.go:306]     Accept: application/json, */*
I0909 04:23:05.134025   33390 round_trippers.go:306]     User-Agent: oc/v1.3.0+52492b4 (linux/amd64) kubernetes/52492b4
I0909 04:23:05.135527   33390 round_trippers.go:321] Response Status: 200 OK in 1 milliseconds
I0909 04:23:05.135548   33390 round_trippers.go:324] Response Headers:
I0909 04:23:05.135559   33390 round_trippers.go:327]     Cache-Control: no-store
I0909 04:23:05.135569   33390 round_trippers.go:327]     Content-Type: application/json
I0909 04:23:05.135580   33390 round_trippers.go:327]     Date: Fri, 09 Sep 2016 08:23:05 GMT
I0909 04:23:05.135590   33390 round_trippers.go:327]     Content-Length: 1382
I0909 04:23:05.135644   33390 request.go:901] Response Body: {"kind":"APIGroupList","groups":[{"name":"apps","versions":[{"groupVersion":"apps/v1alpha1","version":"v1alpha1"}],"preferredVersion":{"groupVersion":"apps/v1alpha1","version":"v1alpha1"},"serverAddressByClientCIDRs":[{"clientCIDR":"0.0.0.0/0","serverAddress":"192.168.1.203:8443"}]},{"name":"authentication.k8s.io","versions":[{"groupVersion":"authentication.k8s.io/v1beta1","version":"v1beta1"}],"preferredVersion":{"groupVersion":"authentication.k8s.io/v1beta1","version":"v1beta1"},"serverAddressByClientCIDRs":[{"clientCIDR":"0.0.0.0/0","serverAddress":"192.168.1.203:8443"}]},{"name":"autoscaling","versions":[{"groupVersion":"autoscaling/v1","version":"v1"}],"preferredVersion":{"groupVersion":"autoscaling/v1","version":"v1"},"serverAddressByClientCIDRs":[{"clientCIDR":"0.0.0.0/0","serverAddress":"192.168.1.203:8443"}]},{"name":"batch","versions":[{"groupVersion":"batch/v1","version":"v1"},{"groupVersion":"batch/v2alpha1","version":"v2alpha1"}],"preferredVersion":{"groupVersion":"batch/v1","version":"v1"},"serverAddressByClientCIDRs":[{"clientCIDR":"0.0.0.0/0","serverAddress":"192.168.1.203:8443"}]},{"name":"extensions","versions":[{"groupVersion":"extensions/v1beta1","version":"v1beta1"}],"preferredVersion":{"groupVersion":"extensions/v1beta1","version":"v1beta1"},"serverAddressByClientCIDRs":[{"clientCIDR":"0.0.0.0/0","serverAddress":"192.168.1.203:8443"}]}]}
I0909 04:23:05.138414   33390 round_trippers.go:296] GET https://openshift-216.lab.sjc.redhat.com:8443/api/v1/namespaces/default/pods/docker-registry-2-05o8i
I0909 04:23:05.138454   33390 round_trippers.go:303] Request Headers:
I0909 04:23:05.138464   33390 round_trippers.go:306]     Accept: application/json, */*
I0909 04:23:05.138474   33390 round_trippers.go:306]     User-Agent: oc/v1.3.0+52492b4 (linux/amd64) kubernetes/52492b4
I0909 04:23:05.142977   33390 round_trippers.go:321] Response Status: 200 OK in 4 milliseconds
I0909 04:23:05.143003   33390 round_trippers.go:324] Response Headers:
I0909 04:23:05.143014   33390 round_trippers.go:327]     Cache-Control: no-store
I0909 04:23:05.143024   33390 round_trippers.go:327]     Content-Type: application/json
I0909 04:23:05.143035   33390 round_trippers.go:327]     Date: Fri, 09 Sep 2016 08:23:05 GMT
I0909 04:23:05.143192   33390 request.go:901] Response Body: {"kind":"Pod","apiVersion":"v1","metadata":{"name":"docker-registry-2-05o8i","generateName":"docker-registry-2-","namespace":"default","selfLink":"/api/v1/namespaces/default/pods/docker-registry-2-05o8i","uid":"26e6df3b-759f-11e6-bac7-fa163e6e710b","resourceVersion":"4237","creationTimestamp":"2016-09-08T08:35:09Z","labels":{"deployment":"docker-registry-2","deploymentconfig":"docker-registry","docker-registry":"default"},"annotations":{"kubernetes.io/created-by":"{\"kind\":\"SerializedReference\",\"apiVersion\":\"v1\",\"reference\":{\"kind\":\"ReplicationController\",\"namespace\":\"default\",\"name\":\"docker-registry-2\",\"uid\":\"1dc842de-759f-11e6-bac7-fa163e6e710b\",\"apiVersion\":\"v1\",\"resourceVersion\":\"1190\"}}\n","openshift.io/deployment-config.latest-version":"2","openshift.io/deployment-config.name":"docker-registry","openshift.io/deployment.name":"docker-registry-2","openshift.io/scc":"restricted"}},"spec":{"volumes":[{"name":"registry-storage","persistentVolumeClaim":{"claimName":"regpv-claim"}},{"name":"registry-token-fw7du","secret":{"secretName":"registry-token-fw7du"}}],"containers":[{"name":"registry","image":"brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/ose-docker-registry:v3.3.0.30","ports":[{"containerPort":5000,"protocol":"TCP"}],"env":[{"name":"REGISTRY_HTTP_ADDR","value":":5000"},{"name":"REGISTRY_HTTP_NET","value":"tcp"},{"name":"REGISTRY_HTTP_SECRET","value":"n4h6fOYlVcTJ0F/YFycuB2vQ5BMF0vBay6CqhPwHlkc="},{"name":"REGISTRY_MIDDLEWARE_REPOSITORY_OPENSHIFT_ENFORCEQUOTA","value":"false"}],"resources":{"requests":{"cpu":"100m","memory":"256Mi"}},"volumeMounts":[{"name":"registry-storage","mountPath":"/registry"},{"name":"registry-token-fw7du","readOnly":true,"mountPath":"/var/run/secrets/kubernetes.io/serviceaccount"}],"livenessProbe":{"httpGet":{"path":"/healthz","port":5000,"scheme":"HTTP"},"initialDelaySeconds":10,"timeoutSeconds":5,"periodSeconds":10,"successThreshold":1,"failureThreshold":3},"readinessProbe":{"httpGet":{"path":"/healthz","port":5000,"scheme":"HTTP"},"timeoutSeconds":5,"periodSeconds":10,"successThreshold":1,"failureThreshold":3},"terminationMessagePath":"/dev/termination-log","imagePullPolicy":"IfNotPresent","securityContext":{"capabilities":{"drop":["KILL","MKNOD","SETGID","SETUID","SYS_CHROOT"]},"privileged":false,"seLinuxOptions":{"level":"s0:c3,c2"},"runAsUser":1000010000}}],"restartPolicy":"Always","terminationGracePeriodSeconds":30,"dnsPolicy":"ClusterFirst","nodeSelector":{"registry":"enabled","role":"node"},"host":"openshift-207.lab.sjc.redhat.com","serviceAccountName":"registry","serviceAccount":"registry","nodeName":"openshift-207.lab.sjc.redhat.com","securityContext":{"seLinuxOptions":{"level":"s0:c3,c2"},"fsGroup":1000010000},"imagePullSecrets":[{"name":"registry-dockercfg-8lxus"}]},"status":{"phase":"Running","conditions":[{"type":"Initialized","status":"True","lastProbeTime":null,"lastTransitionTime":"2016-09-08T08:35:09Z"},{"type":"Ready","status":"True","lastProbeTime":null,"lastTransitionTime":"2016-09-08T11:05:15Z"},{"type":"PodScheduled","status":"True","lastProbeTime":null,"lastTransitionTime":"2016-09-08T08:35:09Z"}],"hostIP":"10.14.6.207","podIP":"10.1.1.4","startTime":"2016-09-08T08:35:09Z","containerStatuses":[{"name":"registry","state":{"running":{"startedAt":"2016-09-08T08:36:35Z"}},"lastState":{},"ready":true,"restartCount":0,"image":"brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/ose-docker-registry:v3.3.0.30","imageID":"docker://sha256:0aa89bc8be38152b1b4142fc8a35e6164255c0ef486ff79d6cec56ab5341c79a","containerID":"docker://c89fb7a83101ab7c76843f157c05b12d86c1cba5fdb5e761e12d06eb6279fb35"}]}}
I0909 04:23:05.148170   33390 round_trippers.go:296] POST https://openshift-216.lab.sjc.redhat.com:8443/api/v1/namespaces/default/pods/docker-registry-2-05o8i/exec?command=date&command=-u&container=registry&container=registry&stderr=true&stdout=true
I0909 04:23:05.148195   33390 round_trippers.go:303] Request Headers:
I0909 04:23:05.148205   33390 round_trippers.go:306]     X-Stream-Protocol-Version: v3.channel.k8s.io
I0909 04:23:05.148215   33390 round_trippers.go:306]     X-Stream-Protocol-Version: v2.channel.k8s.io
I0909 04:23:05.148225   33390 round_trippers.go:306]     X-Stream-Protocol-Version: channel.k8s.io
I0909 04:23:05.148243   33390 round_trippers.go:296] POST https://openshift-216.lab.sjc.redhat.com:8443/api/v1/namespaces/default/pods/docker-registry-2-05o8i/exec?command=date&command=-u&container=registry&container=registry&stderr=true&stdout=true
I0909 04:23:05.148254   33390 round_trippers.go:303] Request Headers:
I0909 04:23:05.148263   33390 round_trippers.go:306]     X-Stream-Protocol-Version: v3.channel.k8s.io
I0909 04:23:05.148273   33390 round_trippers.go:306]     X-Stream-Protocol-Version: v2.channel.k8s.io
I0909 04:23:05.148282   33390 round_trippers.go:306]     X-Stream-Protocol-Version: channel.k8s.io
I0909 04:23:05.148292   33390 round_trippers.go:306]     User-Agent: oc/v1.3.0+52492b4 (linux/amd64) kubernetes/52492b4

<---hang here for 40 mins>

I0909 05:03:45.075351   33390 round_trippers.go:321] Response Status: 101 Switching Protocols in 2439926 milliseconds
I0909 05:03:45.075672   33390 round_trippers.go:324] Response Headers:
I0909 05:03:45.075707   33390 round_trippers.go:327]     Connection: Upgrade
I0909 05:03:45.075724   33390 round_trippers.go:327]     Upgrade: SPDY/3.1
I0909 05:03:45.075735   33390 round_trippers.go:327]     X-Stream-Protocol-Version: v3.channel.k8s.io
I0909 05:03:45.075746   33390 round_trippers.go:327]     Date: Fri, 09 Sep 2016 09:56:49 GMT
I0909 05:03:45.075788   33390 round_trippers.go:321] Response Status: 101 Switching Protocols in 2439927 milliseconds
I0909 05:03:45.075800   33390 round_trippers.go:324] Response Headers:
I0909 05:03:45.075811   33390 round_trippers.go:327]     Connection: Upgrade
I0909 05:03:45.075821   33390 round_trippers.go:327]     Upgrade: SPDY/3.1
I0909 05:03:45.075831   33390 round_trippers.go:327]     X-Stream-Protocol-Version: v3.channel.k8s.io
I0909 05:03:45.075842   33390 round_trippers.go:327]     Date: Fri, 09 Sep 2016 09:56:49 GMT
Fri Sep  9 09:56:49 UTC 2016


Expected results:
No performance degression.

Additional info:
The same behavior is also seen on 3.1 and 3.2.
If replace "oc exec" with "oc logs" in the above test step, no such issue.
Comment 2 Greg Blomquist 2019-07-03 15:24:34 UTC 
No activity in 3 years on a low priority bug.