kubernetes/perf-tests PR #2208 pull-perf-tests-clusterloader2 #1595752074044248064
Recent runs || View in Spyglass
Recent runs || View in Spyglass
| PR | mborsz: [WIP] no statefulsets |
| Result | ABORTED |
| Tests | 0 failed / 84 succeeded |
| Started | |
| Elapsed | 40m1s |
| Revision | d690065358d248119a0dbdad60f93842d3c77196 |
| Refs |
2208 |
ClusterLoaderV2 access-tokens overall (testing/access-tokens/config.yaml)
ClusterLoaderV2 access-tokens: [step: 01] Starting measurements [00] - APIResponsivenessPrometheus
ClusterLoaderV2 access-tokens: [step: 01] Starting measurements [01] - TestMetrics
ClusterLoaderV2 access-tokens: [step: 02] Creating ServiceAccounts
ClusterLoaderV2 access-tokens: [step: 03] Creating Tokens
ClusterLoaderV2 access-tokens: [step: 04] Starting measurement for waiting for pods [00] - WaitForRunningPods
ClusterLoaderV2 access-tokens: [step: 05] Creating pods
ClusterLoaderV2 access-tokens: [step: 06] Waiting for pods to be running [00] - WaitForRunningPods
ClusterLoaderV2 access-tokens: [step: 07] Wait 5min [00] - Wait
ClusterLoaderV2 access-tokens: [step: 08] Deleting pods
ClusterLoaderV2 access-tokens: [step: 09] Waiting for pods to be deleted [00] - WaitForRunningPods
ClusterLoaderV2 access-tokens: [step: 10] Collecting measurements [00] - APIResponsivenessPrometheus
ClusterLoaderV2 access-tokens: [step: 10] Collecting measurements [01] - TestMetrics
ClusterLoaderV2 huge-service overall (testing/huge-service/config.yaml)
ClusterLoaderV2 huge-service: [step: 01] starting measurements [00] - APIResponsivenessPrometheus
ClusterLoaderV2 huge-service: [step: 01] starting measurements [01] - APIResponsivenessPrometheusSimple
ClusterLoaderV2 huge-service: [step: 01] starting measurements [02] - TestMetrics
ClusterLoaderV2 huge-service: [step: 01] starting measurements [03] - InClusterNetworkLatency
ClusterLoaderV2 huge-service: [step: 02] Create huge-service
ClusterLoaderV2 huge-service: [step: 03] Creating huge-service measurements [00] - WaitForHugeServiceDeployments
ClusterLoaderV2 huge-service: [step: 04] Creating huge-service pods
ClusterLoaderV2 huge-service: [step: 05] Waiting for huge-service pods to be created [00] - WaitForHugeServiceDeployments
ClusterLoaderV2 huge-service: [step: 06] Updating huge-service pods
ClusterLoaderV2 huge-service: [step: 07] Waiting for huge-service pods to be updated [00] - WaitForHugeServiceDeployments
ClusterLoaderV2 huge-service: [step: 08] Deleting huge-service pods
ClusterLoaderV2 huge-service: [step: 09] Waiting for huge-service pods to be deleted [00] - WaitForHugeServiceDeployments
ClusterLoaderV2 huge-service: [step: 10] Delete huge-service
ClusterLoaderV2 huge-service: [step: 11] gathering measurements [00] - APIResponsivenessPrometheus
ClusterLoaderV2 huge-service: [step: 11] gathering measurements [01] - APIResponsivenessPrometheusSimple
ClusterLoaderV2 huge-service: [step: 11] gathering measurements [02] - TestMetrics
ClusterLoaderV2 huge-service: [step: 11] gathering measurements [03] - InClusterNetworkLatency
ClusterLoaderV2 load overall (testing/load/config.yaml)
ClusterLoaderV2 load: [step: 01] starting measurements [00] - APIResponsivenessPrometheus
ClusterLoaderV2 load: [step: 01] starting measurements [01] - APIResponsivenessPrometheusSimple
ClusterLoaderV2 load: [step: 01] starting measurements [02] - CreatePhasePodStartupLatency
ClusterLoaderV2 load: [step: 01] starting measurements [03] - InClusterNetworkLatency
ClusterLoaderV2 load: [step: 01] starting measurements [04] - SLOMeasurement
ClusterLoaderV2 load: [step: 01] starting measurements [05] - NetworkProgrammingLatency
ClusterLoaderV2 load: [step: 01] starting measurements [06] - Kube-proxy partial iptables restore failures
ClusterLoaderV2 load: [step: 01] starting measurements [07] - APIAvailability
ClusterLoaderV2 load: [step: 01] starting measurements [08] - Quotas total usage
ClusterLoaderV2 load: [step: 01] starting measurements [09] - TestMetrics
ClusterLoaderV2 load: [step: 02] Creating k8s services
ClusterLoaderV2 load: [step: 03] Creating PriorityClass for DaemonSets
ClusterLoaderV2 load: [step: 04] create objects configmaps and secrets
ClusterLoaderV2 load: [step: 05] Starting measurement for 'create objects' [00] -
ClusterLoaderV2 load: [step: 06] create objects
ClusterLoaderV2 load: [step: 07] Waiting for 'create objects' to be completed [00] -
ClusterLoaderV2 load: [step: 08] Creating scheduler throughput measurements [00] - HighThroughputPodStartupLatency
ClusterLoaderV2 load: [step: 08] Creating scheduler throughput measurements [01] - WaitForSchedulerThroughputDeployments
ClusterLoaderV2 load: [step: 08] Creating scheduler throughput measurements [02] - SchedulingThroughput
ClusterLoaderV2 load: [step: 09] create scheduler throughput pods
ClusterLoaderV2 load: [step: 10] Waiting for scheduler throughput pods to be created [00] - WaitForSchedulerThroughputDeployments
ClusterLoaderV2 load: [step: 11] Collecting scheduler throughput measurements [00] - HighThroughputPodStartupLatency
ClusterLoaderV2 load: [step: 11] Collecting scheduler throughput measurements [01] - SchedulingThroughput
ClusterLoaderV2 load: [step: 12] delete scheduler throughput pods
ClusterLoaderV2 load: [step: 13] Waiting for scheduler throughput pods to be deleted [00] - WaitForSchedulerThroughputDeployments
ClusterLoaderV2 load: [step: 14] Starting latency pod measurements [00] - PodStartupLatency
ClusterLoaderV2 load: [step: 14] Starting latency pod measurements [01] - WaitForRunningLatencyDeployments
ClusterLoaderV2 load: [step: 15] Creating latency pods
ClusterLoaderV2 load: [step: 16] Waiting for latency pods to be running [00] - WaitForRunningLatencyDeployments
ClusterLoaderV2 load: [step: 17] Deleting latency pods
ClusterLoaderV2 load: [step: 18] Waiting for latency pods to be deleted [00] - WaitForRunningLatencyDeployments
ClusterLoaderV2 load: [step: 19] Collecting pod startup latency [00] - PodStartupLatency
ClusterLoaderV2 load: [step: 20] Starting measurement for 'scale and update objects' [00] -
ClusterLoaderV2 load: [step: 21] scale and update objects
ClusterLoaderV2 load: [step: 22] Waiting for 'scale and update objects' to be completed [00] -
ClusterLoaderV2 load: [step: 23] Starting measurement for 'delete objects' [00] -
ClusterLoaderV2 load: [step: 24] delete objects
ClusterLoaderV2 load: [step: 25] Waiting for 'delete objects' to be completed [00] -
ClusterLoaderV2 load: [step: 25] Waiting for 'delete objects' to be completed [01] - WaitForPVCsToBeDeleted
ClusterLoaderV2 load: [step: 26] delete objects configmaps and secrets
ClusterLoaderV2 load: [step: 27] Deleting PriorityClass for DaemonSets
ClusterLoaderV2 load: [step: 28] Deleting k8s services
ClusterLoaderV2 load: [step: 29] gathering measurements [00] - APIResponsivenessPrometheus
ClusterLoaderV2 load: [step: 29] gathering measurements [01] - APIResponsivenessPrometheusSimple
ClusterLoaderV2 load: [step: 29] gathering measurements [02] - CreatePhasePodStartupLatency
ClusterLoaderV2 load: [step: 29] gathering measurements [03] - InClusterNetworkLatency
ClusterLoaderV2 load: [step: 29] gathering measurements [04] - SLOMeasurement
ClusterLoaderV2 load: [step: 29] gathering measurements [05] - NetworkProgrammingLatency
ClusterLoaderV2 load: [step: 29] gathering measurements [06] - Kube-proxy partial iptables restore failures
ClusterLoaderV2 load: [step: 29] gathering measurements [07] - APIAvailability
ClusterLoaderV2 load: [step: 29] gathering measurements [08] - Quotas total usage
ClusterLoaderV2 load: [step: 29] gathering measurements [09] - TestMetrics
... skipping 410 lines ... Looking for address 'e2e-2208-62db2-master-ip' Looking for address 'e2e-2208-62db2-master-internal-ip' Using master: e2e-2208-62db2-master (external IP: 34.75.162.54; internal IP: 10.40.0.2) Waiting up to 300 seconds for cluster initialization. This will continually check to see if the API for kubernetes is reachable. This may time out if there was some uncaught error during start up. Kubernetes cluster created. Cluster "k8s-presubmit-scale-37_e2e-2208-62db2" set. User "k8s-presubmit-scale-37_e2e-2208-62db2" set. Context "k8s-presubmit-scale-37_e2e-2208-62db2" created. Switched to context "k8s-presubmit-scale-37_e2e-2208-62db2". ... skipping 233 lines ... e2e-2208-62db2-minion-group-zklq Ready <none> 38s v1.27.0-alpha.0.46+8f2371bcceff79 e2e-2208-62db2-minion-group-zn1r Ready <none> 39s v1.27.0-alpha.0.46+8f2371bcceff79 e2e-2208-62db2-minion-heapster Ready <none> 61s v1.27.0-alpha.0.46+8f2371bcceff79 Warning: v1 ComponentStatus is deprecated in v1.19+ Validate output: Warning: v1 ComponentStatus is deprecated in v1.19+ NAME STATUS MESSAGE ERROR etcd-1 Healthy {"health":"true","reason":""} etcd-0 Healthy {"health":"true","reason":""} controller-manager Healthy ok scheduler Healthy ok [0;33mCluster validation encountered some problems, but cluster should be in working order[0m ...ignoring non-fatal errors in validate-cluster Done, listing cluster services: [0;32mKubernetes control plane[0m is running at [0;33mhttps://34.75.162.54[0m [0;32mGLBCDefaultBackend[0m is running at [0;33mhttps://34.75.162.54/api/v1/namespaces/kube-system/services/default-http-backend:http/proxy[0m [0;32mCoreDNS[0m is running at [0;33mhttps://34.75.162.54/api/v1/namespaces/kube-system/services/kube-dns:dns/proxy[0m [0;32mMetrics-server[0m is running at [0;33mhttps://34.75.162.54/api/v1/namespaces/kube-system/services/https:metrics-server:/proxy[0m ... skipping 1097 lines ... I1124 12:28:46.634455 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(small-deployment-107): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:28:46.702016 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(medium-deployment-14): Pods: 30 out of 30 created, 30 running (30 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:28:46.758115 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(small-deployment-257): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:28:47.846771 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(small-deployment-21): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:28:48.442608 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(small-deployment-103): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:28:48.587882 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(small-deployment-55): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:28:48.634803 15949 wait_for_controlled_pods.go:319] WaitForControlledPodsRunning: running 3, deleted 0, timeout: 0, failed: 0 I1124 12:28:48.634882 15949 wait_for_controlled_pods.go:324] WaitForControlledPodsRunning: maxDuration=5.011456705s, operationTimeout=15m0s, ratio=0.01 I1124 12:28:48.634910 15949 wait_for_controlled_pods.go:338] WaitForControlledPodsRunning: 3/3 Jobs are running with all pods I1124 12:28:48.635383 15949 wait_for_controlled_pods.go:319] WaitForControlledPodsRunning: running 1, deleted 0, timeout: 0, failed: 0 I1124 12:28:48.635592 15949 wait_for_controlled_pods.go:324] WaitForControlledPodsRunning: maxDuration=5.004269309s, operationTimeout=15m0s, ratio=0.01 I1124 12:28:48.635625 15949 wait_for_controlled_pods.go:338] WaitForControlledPodsRunning: 1/1 DaemonSets are running with all pods I1124 12:28:48.635832 15949 wait_for_controlled_pods.go:319] WaitForControlledPodsRunning: running 0, deleted 0, timeout: 0, failed: 0 I1124 12:28:48.635868 15949 wait_for_controlled_pods.go:324] WaitForControlledPodsRunning: maxDuration=0s, operationTimeout=15m0s, ratio=0.00 I1124 12:28:48.636022 15949 wait_for_controlled_pods.go:338] WaitForControlledPodsRunning: 0/0 StatefulSets are running with all pods I1124 12:28:48.846226 15949 wait_for_controlled_pods.go:319] WaitForControlledPodsRunning: running 325, deleted 0, timeout: 0, failed: 0 I1124 12:28:48.846286 15949 wait_for_controlled_pods.go:324] WaitForControlledPodsRunning: maxDuration=5.021189331s, operationTimeout=15m0s, ratio=0.01 I1124 12:28:48.846311 15949 wait_for_controlled_pods.go:338] WaitForControlledPodsRunning: 325/325 Deployments are running with all pods I1124 12:28:48.846339 15949 simple_test_executor.go:171] Step "[step: 07] Waiting for 'create objects' to be completed" ended I1124 12:28:48.846368 15949 simple_test_executor.go:149] Step "[step: 08] Creating scheduler throughput measurements" started I1124 12:28:48.846509 15949 pod_startup_latency.go:132] PodStartupLatency: labelSelector(group = scheduler-throughput): starting pod startup latency measurement... I1124 12:28:48.846581 15949 wait_for_controlled_pods.go:215] WaitForControlledPodsRunning: starting wait for controlled pods measurement... ... skipping 4 lines ... I1124 12:28:48.992380 15949 simple_test_executor.go:171] Step "[step: 09] create scheduler throughput pods" ended I1124 12:28:48.992761 15949 simple_test_executor.go:149] Step "[step: 10] Waiting for scheduler throughput pods to be created" started I1124 12:28:48.993064 15949 wait_for_controlled_pods.go:246] WaitForControlledPodsRunning: waiting for controlled pods measurement... I1124 12:28:54.006033 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-2), controlledBy(scheduler-throughput-deployment-0): Pods: 573 out of 1000 created, 386 running (386 updated), 185 pending scheduled, 2 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:28:59.041839 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-2), controlledBy(scheduler-throughput-deployment-0): Pods: 1000 out of 1000 created, 929 running (929 updated), 71 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:29:04.076001 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-2), controlledBy(scheduler-throughput-deployment-0): Pods: 1000 out of 1000 created, 1000 running (1000 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:29:04.076140 15949 wait_for_controlled_pods.go:319] WaitForControlledPodsRunning: running 1, deleted 0, timeout: 0, failed: 0 I1124 12:29:04.076159 15949 wait_for_controlled_pods.go:324] WaitForControlledPodsRunning: maxDuration=15.084845414s, operationTimeout=20m0s, ratio=0.01 I1124 12:29:04.076203 15949 wait_for_controlled_pods.go:338] WaitForControlledPodsRunning: 1/1 Deployments are running with all pods I1124 12:29:04.076234 15949 simple_test_executor.go:171] Step "[step: 10] Waiting for scheduler throughput pods to be created" ended I1124 12:29:04.076265 15949 simple_test_executor.go:149] Step "[step: 11] Collecting scheduler throughput measurements" started I1124 12:29:04.076339 15949 scheduling_throughput.go:154] SchedulingThroughput: gathering data I1124 12:29:04.076390 15949 pod_startup_latency.go:226] PodStartupLatency: labelSelector(group = scheduler-throughput): gathering pod startup latency measurement... ... skipping 33 lines ... I1124 12:29:04.582461 15949 simple_test_executor.go:149] Step "[step: 13] Waiting for scheduler throughput pods to be deleted" started I1124 12:29:04.582513 15949 wait_for_controlled_pods.go:246] WaitForControlledPodsRunning: waiting for controlled pods measurement... I1124 12:29:04.582966 15949 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-enuk6k-2), controlledBy(scheduler-throughput-deployment-0): starting with timeout: 19m59.999955017s I1124 12:29:09.601877 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-2), controlledBy(scheduler-throughput-deployment-0): Pods: 457 out of 0 created, 457 running (457 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 90 terminating, 0 unknown, 0 runningButNotReady I1124 12:29:14.603243 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-2), controlledBy(scheduler-throughput-deployment-0): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 36 terminating, 0 unknown, 0 runningButNotReady I1124 12:29:19.603593 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-2), controlledBy(scheduler-throughput-deployment-0): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:29:19.604287 15949 wait_for_controlled_pods.go:319] WaitForControlledPodsRunning: running 0, deleted 1, timeout: 0, failed: 0 I1124 12:29:19.604478 15949 wait_for_controlled_pods.go:324] WaitForControlledPodsRunning: maxDuration=15.021273169s, operationTimeout=20m0s, ratio=0.01 I1124 12:29:19.604518 15949 wait_for_controlled_pods.go:338] WaitForControlledPodsRunning: 0/0 Deployments are running with all pods I1124 12:29:19.604559 15949 simple_test_executor.go:171] Step "[step: 13] Waiting for scheduler throughput pods to be deleted" ended I1124 12:29:19.604593 15949 simple_test_executor.go:149] Step "[step: 14] Starting latency pod measurements" started I1124 12:29:19.604726 15949 pod_startup_latency.go:132] PodStartupLatency: labelSelector(group = latency): starting pod startup latency measurement... I1124 12:29:19.605186 15949 wait_for_controlled_pods.go:215] WaitForControlledPodsRunning: starting wait for controlled pods measurement... ... skipping 329 lines ... I1124 12:29:55.042112 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(latency-deployment-151): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:29:55.057715 15949 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(latency-deployment-176): starting with timeout: 14m59.99996378s I1124 12:29:55.241796 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(latency-deployment-152): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:29:55.256568 15949 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(latency-deployment-177): starting with timeout: 14m59.999967062s I1124 12:29:55.448759 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(latency-deployment-153): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:29:55.456217 15949 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(latency-deployment-178): starting with timeout: 14m59.999972427s error dialing prow@34.75.162.54:22: 'ssh: handshake failed: read tcp 10.60.8.145:50702->34.75.162.54:22: read: connection reset by peer', retrying I1124 12:29:55.646432 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(latency-deployment-154): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:29:55.656463 15949 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(latency-deployment-179): starting with timeout: 14m59.999967568s I1124 12:29:55.844214 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(latency-deployment-155): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:29:55.857606 15949 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(latency-deployment-180): starting with timeout: 14m59.99995703s I1124 12:29:56.044002 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(latency-deployment-156): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:29:56.058491 15949 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(latency-deployment-181): starting with timeout: 14m59.999966224s ... skipping 658 lines ... I1124 12:31:03.857795 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(latency-deployment-494): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:31:04.057606 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(latency-deployment-495): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:31:04.257940 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(latency-deployment-496): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:31:04.462303 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(latency-deployment-497): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:31:04.667956 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(latency-deployment-498): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:31:04.861725 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(latency-deployment-499): Pods: 1 out of 1 created, 1 running (1 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:31:05.380657 15949 wait_for_controlled_pods.go:319] WaitForControlledPodsRunning: running 500, deleted 0, timeout: 0, failed: 0 I1124 12:31:05.380715 15949 wait_for_controlled_pods.go:324] WaitForControlledPodsRunning: maxDuration=5.007803344s, operationTimeout=15m0s, ratio=0.01 I1124 12:31:05.380744 15949 wait_for_controlled_pods.go:338] WaitForControlledPodsRunning: 500/500 Deployments are running with all pods I1124 12:31:05.381009 15949 simple_test_executor.go:171] Step "[step: 16] Waiting for latency pods to be running" ended I1124 12:31:05.381338 15949 simple_test_executor.go:149] Step "[step: 17] Deleting latency pods" started I1124 12:31:05.421299 15949 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(latency-deployment-0): starting with timeout: 14m59.999946374s I1124 12:31:05.521517 15949 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(latency-deployment-1): starting with timeout: 14m59.999963184s ... skipping 495 lines ... I1124 12:31:55.122899 15949 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(latency-deployment-497): starting with timeout: 14m59.999964244s I1124 12:31:55.221264 15949 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(latency-deployment-498): starting with timeout: 14m59.999960178s I1124 12:31:55.322418 15949 simple_test_executor.go:171] Step "[step: 17] Deleting latency pods" ended I1124 12:31:55.322875 15949 simple_test_executor.go:149] Step "[step: 18] Waiting for latency pods to be deleted" started I1124 12:31:55.323210 15949 wait_for_controlled_pods.go:246] WaitForControlledPodsRunning: waiting for controlled pods measurement... I1124 12:31:55.322872 15949 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(latency-deployment-499): starting with timeout: 14m59.999948036s I1124 12:32:00.378454 15949 wait_for_controlled_pods.go:319] WaitForControlledPodsRunning: running 0, deleted 500, timeout: 0, failed: 0 I1124 12:32:00.378960 15949 wait_for_controlled_pods.go:324] WaitForControlledPodsRunning: maxDuration=5.012004584s, operationTimeout=15m0s, ratio=0.01 I1124 12:32:00.378992 15949 wait_for_controlled_pods.go:338] WaitForControlledPodsRunning: 0/0 Deployments are running with all pods I1124 12:32:00.379053 15949 simple_test_executor.go:171] Step "[step: 18] Waiting for latency pods to be deleted" ended I1124 12:32:00.379080 15949 simple_test_executor.go:149] Step "[step: 19] Collecting pod startup latency" started I1124 12:32:00.379133 15949 pod_startup_latency.go:226] PodStartupLatency: labelSelector(group = latency): gathering pod startup latency measurement... I1124 12:32:01.062826 15949 phase_latency.go:141] PodStartupLatency: 100 worst schedule_to_run latencies: [{test-enuk6k-1/latency-deployment-267-658c49b79c-bwcls 1s} {test-enuk6k-1/latency-deployment-304-79cb45f44f-66fbd 1s} {test-enuk6k-1/latency-deployment-71-56846c6d7-kwdf7 1s} {test-enuk6k-1/latency-deployment-56-8d4c768d7-6kttj 1s} {test-enuk6k-1/latency-deployment-63-77bc4dc967-vtb6m 1s} {test-enuk6k-1/latency-deployment-97-545cc47887-qkh8c 1s} {test-enuk6k-1/latency-deployment-69-68995f7c9f-gbk4m 1s} {test-enuk6k-1/latency-deployment-348-65c6bd4f49-xsz2k 1s} {test-enuk6k-1/latency-deployment-342-d747b7969-9n6mn 1s} {test-enuk6k-1/latency-deployment-221-5674b9db85-w2pqk 1s} {test-enuk6k-1/latency-deployment-249-b4bb789bf-867tv 1s} {test-enuk6k-1/latency-deployment-367-564cbcc98c-htbr8 1s} {test-enuk6k-1/latency-deployment-104-874b5d545-hf6zx 1s} {test-enuk6k-1/latency-deployment-137-9b5ddc789-8dswq 1s} {test-enuk6k-1/latency-deployment-203-58cdc666b5-xddkf 1s} {test-enuk6k-1/latency-deployment-455-688bfbfbcf-66fjj 1s} {test-enuk6k-1/latency-deployment-235-546789fb59-44x2g 1s} {test-enuk6k-1/latency-deployment-241-86465f5c97-4c89p 1s} {test-enuk6k-1/latency-deployment-295-58c794f695-85qdb 1s} {test-enuk6k-1/latency-deployment-247-6dc56454f-ttg8j 1s} {test-enuk6k-1/latency-deployment-173-6f74865fbf-2c4kw 1s} {test-enuk6k-1/latency-deployment-360-54bf874f97-f2kxb 1s} {test-enuk6k-1/latency-deployment-442-574d85ff4c-pgzhv 1s} {test-enuk6k-1/latency-deployment-479-768cf8b567-shtgd 1s} {test-enuk6k-1/latency-deployment-404-57fff9dd87-n2b56 1s} {test-enuk6k-1/latency-deployment-205-9bb76589c-q8t5j 1s} {test-enuk6k-1/latency-deployment-283-5ffd9cd79c-rnvdc 1s} {test-enuk6k-1/latency-deployment-312-7f9b59bfc9-slwjw 1s} {test-enuk6k-1/latency-deployment-407-b649cb997-4cww8 1s} {test-enuk6k-1/latency-deployment-426-5df9df6fcf-58s26 1s} {test-enuk6k-1/latency-deployment-480-6bb856b9f9-v5rv4 1s} {test-enuk6k-1/latency-deployment-14-8577448d87-8p9qc 1s} {test-enuk6k-1/latency-deployment-195-56c6fdd785-x57dm 1s} {test-enuk6k-1/latency-deployment-268-6d75dbf567-qb4kj 1s} {test-enuk6k-1/latency-deployment-289-7578bf5445-2r7c8 1s} {test-enuk6k-1/latency-deployment-319-6c78bcb66f-k92b9 1s} {test-enuk6k-1/latency-deployment-465-7bd646b4d9-mmr6s 1s} {test-enuk6k-1/latency-deployment-496-6bd4fdc86f-l8dkx 1s} {test-enuk6k-1/latency-deployment-20-857fcc5d8c-w8ncc 1s} {test-enuk6k-1/latency-deployment-157-596cf84d6f-2fdrt 1s} {test-enuk6k-1/latency-deployment-208-7c994ffcdc-zj7mv 1s} {test-enuk6k-1/latency-deployment-151-6775f4b54f-x7wnd 1s} {test-enuk6k-1/latency-deployment-182-5bdd56f88f-tg4tb 1s} {test-enuk6k-1/latency-deployment-495-5788dc8b99-g59hv 1s} {test-enuk6k-1/latency-deployment-338-f44c9d7bc-8pt5g 1s} {test-enuk6k-1/latency-deployment-445-5799bcdd7c-8vv8z 1s} {test-enuk6k-1/latency-deployment-477-5cb68dc95f-b4k47 1s} {test-enuk6k-1/latency-deployment-0-64c4b7bcf9-bhk8w 1s} {test-enuk6k-1/latency-deployment-163-687d84d77f-9m2k5 1s} {test-enuk6k-1/latency-deployment-231-5cc9dcf4cf-xswft 1s} {test-enuk6k-1/latency-deployment-52-5d97b5bb55-6576h 1s} {test-enuk6k-1/latency-deployment-162-6fd598d69-s96hl 1s} {test-enuk6k-1/latency-deployment-311-85fb4c4b6f-dkvc9 1s} {test-enuk6k-1/latency-deployment-435-7448d885dc-psxlc 1s} {test-enuk6k-1/latency-deployment-158-78d55f944c-z2mzw 1s} {test-enuk6k-1/latency-deployment-212-648556c585-765n2 1s} {test-enuk6k-1/latency-deployment-307-78d67b4c99-z985j 1s} {test-enuk6k-1/latency-deployment-26-69b66f8dc9-gpwjd 1s} {test-enuk6k-1/latency-deployment-222-767c47f75-gsw4h 1s} {test-enuk6k-1/latency-deployment-433-7579584c5f-92v4v 1s} {test-enuk6k-1/latency-deployment-378-6f7b684987-sxpf9 1s} {test-enuk6k-1/latency-deployment-398-985d766bc-pdrk2 1s} {test-enuk6k-1/latency-deployment-115-b5f7f4f45-nz8wt 1s} {test-enuk6k-1/latency-deployment-140-8454fd57c7-p8wfp 1s} {test-enuk6k-1/latency-deployment-302-ffd8bd5b9-4dgds 1s} {test-enuk6k-1/latency-deployment-13-f594dd687-mmg5g 1s} {test-enuk6k-1/latency-deployment-310-6874655447-x9c98 1s} {test-enuk6k-1/latency-deployment-386-fc6f7f585-6gv9x 1s} {test-enuk6k-1/latency-deployment-12-6b7647c479-txmvk 1s} {test-enuk6k-1/latency-deployment-191-77495cb46f-gb2c2 1s} {test-enuk6k-1/latency-deployment-349-5bc8959999-j2n42 1s} {test-enuk6k-1/latency-deployment-292-6fb7dc6cdf-6rmsc 1s} {test-enuk6k-1/latency-deployment-497-77d8b78cf9-qqp7v 1s} {test-enuk6k-1/latency-deployment-1-6779775c85-qtw8z 1s} {test-enuk6k-1/latency-deployment-47-545569bcb7-5wrz7 1s} {test-enuk6k-1/latency-deployment-285-9b75b8cbf-chldz 1s} {test-enuk6k-1/latency-deployment-170-6b5d45fb47-ghtb2 1s} {test-enuk6k-1/latency-deployment-389-74d587bdc9-cnjzb 1s} {test-enuk6k-1/latency-deployment-308-5d485658d5-b2vjj 1s} {test-enuk6k-1/latency-deployment-88-78bfbb578c-gxfpx 1s} {test-enuk6k-1/latency-deployment-223-66ff7578b5-xsp8n 1s} {test-enuk6k-1/latency-deployment-459-b895cb955-sn8tc 1s} {test-enuk6k-1/latency-deployment-131-6f54bb85-fw9jd 1s} {test-enuk6k-1/latency-deployment-270-77c49b4f89-5ctwr 1s} {test-enuk6k-1/latency-deployment-476-7d648bd7d9-n4gw4 1s} {test-enuk6k-1/latency-deployment-473-ff97b46dc-dc7qh 1s} {test-enuk6k-1/latency-deployment-488-6b4856dfcf-cv9gk 1s} {test-enuk6k-1/latency-deployment-80-7878757b47-8nr9s 1s} {test-enuk6k-1/latency-deployment-95-778c9fb86c-vhgcj 1s} {test-enuk6k-1/latency-deployment-254-57f84497c7-8j7vr 1s} {test-enuk6k-1/latency-deployment-364-775cf57b8f-hcnlj 1s} {test-enuk6k-1/latency-deployment-294-ff686499c-9mj6h 1s} {test-enuk6k-1/latency-deployment-298-59449f5d57-n7fhg 1s} {test-enuk6k-1/latency-deployment-375-786d4ffccc-xpvzl 2s} {test-enuk6k-1/latency-deployment-260-76589b78c9-ftwhp 2s} {test-enuk6k-1/latency-deployment-309-5b7bc584c9-pcd9j 2s} {test-enuk6k-1/latency-deployment-345-759995649f-r7dpq 2s} {test-enuk6k-1/latency-deployment-245-5456dd46c7-jfp2w 2s} {test-enuk6k-1/latency-deployment-320-5b68dfd757-9j8s7 2s} {test-enuk6k-1/latency-deployment-31-7548446687-zffkb 2s}] ... skipping 615 lines ... I1124 12:32:42.644955 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(daemonset-0): Pods: 100 out of 100 created, 100 running (100 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:32:42.734987 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(small-deployment-280): Pods: 7 out of 7 created, 7 running (7 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:32:42.735658 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(small-deployment-16): Pods: 6 out of 6 created, 6 running (6 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:32:42.858479 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(small-deployment-281): Pods: 4 out of 4 created, 4 running (4 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:32:43.026462 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(small-deployment-122): Pods: 4 out of 4 created, 4 running (4 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:32:43.082412 15949 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(small-deployment-14): Pods: 7 out of 7 created, 7 running (7 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1124 12:32:43.126072 15949 wait_for_controlled_pods.go:319] WaitForControlledPodsRunning: running 3, deleted 0, timeout: 0, failed: 0 I1124 12:32:43.126130 15949 wait_for_controlled_pods.go:324] WaitForControlledPodsRunning: maxDuration=5.006328965s, operationTimeout=15m0s, ratio=0.01 I1124 12:32:43.126159 15949 wait_for_controlled_pods.go:338] WaitForControlledPodsRunning: 3/3 Jobs are running with all pods I1124 12:32:43.127274 15949 wait_for_controlled_pods.go:319] WaitForControlledPodsRunning: running 0, deleted 0, timeout: 0, failed: 0 I1124 12:32:43.127311 15949 wait_for_controlled_pods.go:324] WaitForControlledPodsRunning: maxDuration=0s, operationTimeout=15m0s, ratio=0.00 I1124 12:32:43.127606 15949 wait_for_controlled_pods.go:319] WaitForControlledPodsRunning: running 1, deleted 0, timeout: 0, failed: 0 I1124 12:32:43.127631 15949 wait_for_controlled_pods.go:324] WaitForControlledPodsRunning: maxDuration=30.19911949s, operationTimeout=15m0s, ratio=0.03 I1124 12:32:43.127649 15949 wait_for_controlled_pods.go:338] WaitForControlledPodsRunning: 1/1 DaemonSets are running with all pods I1124 12:32:43.127917 15949 wait_for_controlled_pods.go:338] WaitForControlledPodsRunning: 0/0 StatefulSets are running with all pods I1124 12:32:43.603573 15949 wait_for_controlled_pods.go:319] WaitForControlledPodsRunning: running 325, deleted 0, timeout: 0, failed: 0 I1124 12:32:43.603627 15949 wait_for_controlled_pods.go:324] WaitForControlledPodsRunning: maxDuration=5.017640548s, operationTimeout=15m0s, ratio=0.01 I1124 12:32:43.603657 15949 wait_for_controlled_pods.go:338] WaitForControlledPodsRunning: 325/325 Deployments are running with all pods I1124 12:32:43.603695 15949 simple_test_executor.go:171] Step "[step: 22] Waiting for 'scale and update objects' to be completed" ended I1124 12:32:43.603722 15949 simple_test_executor.go:149] Step "[step: 23] Starting measurement for 'delete objects'" started I1124 12:32:43.603958 15949 wait_for_controlled_pods.go:212] WaitForControlledPodsRunning: wait for controlled pods measurement already running I1124 12:32:43.604058 15949 wait_for_controlled_pods.go:212] WaitForControlledPodsRunning: wait for controlled pods measurement already running ... skipping 333 lines ... I1124 12:36:17.354465 15949 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-enuk6k-1), controlledBy(small-deployment-125): starting with timeout: 14m59.999975714s I1124 12:36:17.354485 15949 simple_test_executor.go:149] Step "[step: 25] Waiting for 'delete objects' to be completed" started I1124 12:36:17.354529 15949 wait_for_controlled_pods.go:246] WaitForControlledPodsRunning: waiting for controlled pods measurement... I1124 12:36:17.354580 15949 wait_for_controlled_pods.go:246] WaitForControlledPodsRunning: waiting for controlled pods measurement... I1124 12:36:17.354815 15949 wait_for_controlled_pods.go:246] WaitForControlledPodsRunning: waiting for controlled pods measurement... I1124 12:36:17.354870 15949 wait_for_controlled_pods.go:246] WaitForControlledPodsRunning: waiting for controlled pods measurement... I1124 12:36:22.398514 15949 wait_for_controlled_pods.go:319] WaitForControlledPodsRunning: running 0, deleted 3, timeout: 0, failed: 0 I1124 12:36:22.398892 15949 wait_for_controlled_pods.go:324] WaitForControlledPodsRunning: maxDuration=5.001429141s, operationTimeout=15m0s, ratio=0.01 I1124 12:36:22.399248 15949 wait_for_controlled_pods.go:338] WaitForControlledPodsRunning: 0/0 Jobs are running with all pods I1124 12:36:22.398514 15949 wait_for_controlled_pods.go:319] WaitForControlledPodsRunning: running 0, deleted 0, timeout: 0, failed: 0 I1124 12:36:22.399443 15949 wait_for_controlled_pods.go:324] WaitForControlledPodsRunning: maxDuration=0s, operationTimeout=15m0s, ratio=0.00 I1124 12:36:22.399521 15949 wait_for_controlled_pods.go:338] WaitForControlledPodsRunning: 0/0 StatefulSets are running with all pods I1124 12:36:22.400920 15949 wait_for_controlled_pods.go:319] WaitForControlledPodsRunning: running 0, deleted 325, timeout: 0, failed: 0 I1124 12:36:22.400955 15949 wait_for_controlled_pods.go:324] WaitForControlledPodsRunning: maxDuration=5.00581763s, operationTimeout=15m0s, ratio=0.01 I1124 12:36:22.400974 15949 wait_for_controlled_pods.go:338] WaitForControlledPodsRunning: 0/0 Deployments are running with all pods I1124 12:36:22.401010 15949 wait_for_controlled_pods.go:319] WaitForControlledPodsRunning: running 0, deleted 1, timeout: 0, failed: 0 I1124 12:36:22.401020 15949 wait_for_controlled_pods.go:324] WaitForControlledPodsRunning: maxDuration=5.00150918s, operationTimeout=15m0s, ratio=0.01 I1124 12:36:22.401036 15949 wait_for_controlled_pods.go:338] WaitForControlledPodsRunning: 0/0 DaemonSets are running with all pods I1124 12:36:22.406127 15949 wait_for_pvcs.go:78] WaitForBoundPVCs: labelSelector(group = load): PVCs: 0 out of 0 created, 0 bound, 0 pending, 0 lost I1124 12:36:22.406190 15949 simple_test_executor.go:171] Step "[step: 25] Waiting for 'delete objects' to be completed" ended I1124 12:36:22.406224 15949 simple_test_executor.go:149] Step "[step: 26] delete objects configmaps and secrets" started I1124 12:36:54.882923 15949 simple_test_executor.go:171] Step "[step: 26] delete objects configmaps and secrets" ended ... skipping 193 lines ... I1124 12:37:04.419446 15949 ooms_tracker.go:230] ClusterOOMsTracker: gathering cluster OOMs tracking measurement I1124 12:37:04.419589 15949 simple_test_executor.go:171] Step "[step: 29] gathering measurements" ended I1124 12:37:04.419648 15949 simple_test_executor.go:80] Waiting for the chaos monkey subroutine to end... I1124 12:37:04.419665 15949 simple_test_executor.go:82] Chaos monkey ended. I1124 12:37:04.451836 15949 simple_test_executor.go:102] I1124 12:37:04.451883 15949 probes.go:151] Stopping DnsLookupLatency probe... {"component":"entrypoint","file":"k8s.io/test-infra/prow/entrypoint/run.go:168","func":"k8s.io/test-infra/prow/entrypoint.Options.ExecuteProcess","level":"error","msg":"Entrypoint received interrupt: terminated","severity":"error","time":"2022-11-24T12:37:08Z"} ++ early_exit_handler ++ '[' -n 28 ']'