PR #104660 pull-kubernetes-e2e-gce-100-performance #1608477027227144192
Recent runs || View in Spyglass
Recent runs || View in Spyglass
| PR | claudiubelu: Windows file permissions |
| Result | ABORTED |
| Tests | 0 failed / 71 succeeded |
| Started | |
| Elapsed | 53m51s |
| Revision | a086352e325c7733271ad4e6f2f8778b248451f5 |
| Refs |
104660 |
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 691 lines ... Looking for address 'e2e-104660-95a39-master-ip' Looking for address 'e2e-104660-95a39-master-internal-ip' Using master: e2e-104660-95a39-master (external IP: 34.148.180.162; 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-infra-e2e-boskos-scale-15_e2e-104660-95a39" set. User "k8s-infra-e2e-boskos-scale-15_e2e-104660-95a39" set. Context "k8s-infra-e2e-boskos-scale-15_e2e-104660-95a39" created. Switched to context "k8s-infra-e2e-boskos-scale-15_e2e-104660-95a39". ... skipping 240 lines ... e2e-104660-95a39-minion-group-z41k Ready <none> 82s v1.27.0-alpha.0.661+3f5b8396c0b851 e2e-104660-95a39-minion-group-zd9j Ready <none> 84s v1.27.0-alpha.0.661+3f5b8396c0b851 e2e-104660-95a39-minion-heapster Ready <none> 96s v1.27.0-alpha.0.661+3f5b8396c0b851 Warning: v1 ComponentStatus is deprecated in v1.19+ Validate output: Warning: v1 ComponentStatus is deprecated in v1.19+ NAME STATUS MESSAGE ERROR etcd-0 Healthy {"health":"true","reason":""} etcd-1 Healthy {"health":"true","reason":""} scheduler Healthy ok controller-manager 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.148.180.162[0m [0;32mGLBCDefaultBackend[0m is running at [0;33mhttps://34.148.180.162/api/v1/namespaces/kube-system/services/default-http-backend:http/proxy[0m [0;32mCoreDNS[0m is running at [0;33mhttps://34.148.180.162/api/v1/namespaces/kube-system/services/kube-dns:dns/proxy[0m [0;32mMetrics-server[0m is running at [0;33mhttps://34.148.180.162/api/v1/namespaces/kube-system/services/https:metrics-server:/proxy[0m ... skipping 61 lines ... k8s.io/perf-tests git log: ce673a95df72623c76837d6e5bf0996b69c175a4 - Mon Dec 19 11:11:44 2022 (Merge pull request #2220 from mborsz/race) 19927c1a477eaebeb004387972def1db75142c10 - Mon Dec 19 10:15:11 2022 (Avoid race in subsequent changes to the same controller) 83e45df022caa7507aa84f5b8af85db2af153c6e - Fri Dec 16 10:00:17 2022 (Merge pull request #2217 from marseel/update_owners_files) 4cc5ad908a71038c26dc4f9aefe9fbefa11bc1e2 - Thu Dec 15 17:55:35 2022 (Merge pull request #2219 from mborsz/log) 945ac9ae9ef72c5f89545902059f27f878919dec - Thu Dec 15 16:27:35 2022 (Merge pull request #2218 from mborsz/prio) 67cd0ed08c922b8b8132b34383e614404aac502e - Thu Dec 15 14:50:23 2022 (Improve error logging in exec service) 08a85529d689ddca53221b6434fd4b7453b557d2 - Thu Dec 15 12:29:49 2022 (Set priorityclass in prometheus) e135cee4571a243b0cce2845b8656e33f12bbb21 - Thu Dec 15 10:25:01 2022 (Update all OWNERS files and add tosi3k as reviewer) 38556c50c41c7597d54902051c3bd70310e426c3 - Thu Dec 15 10:01:36 2022 (Merge pull request #2207 from HuShaoRu/waitForDeletion) 1a1a8ef1b4dde1c04865cfa01f0e80d484fcab47 - Wed Dec 14 12:53:34 2022 (Merge pull request #2215 from MadhavJivrajani/scrape-block-profiles) COMMAND: /home/prow/go/src/k8s.io/perf-tests/clusterloader2 && ./run-e2e.sh --nodes=100 --provider=gce --experimental-gcp-snapshot-prometheus-disk=true --experimental-prometheus-disk-snapshot-name=pull-kubernetes-e2e-gce-100-performance-1608477027227144192 --experimental-prometheus-snapshot-to-report-dir=true --prometheus-scrape-kubelets=true --prometheus-scrape-node-exporter --report-dir=/logs/artifacts --testconfig=testing/load/config.yaml --testconfig=testing/huge-service/config.yaml --testoverrides=./testing/experiments/enable_restart_count_check.yaml --testoverrides=./testing/experiments/use_simple_latency_query.yaml --testoverrides=./testing/overrides/load_throughput.yaml namespace/gce-pd-csi-driver created ... skipping 1032 lines ... I1229 15:30:27.567305 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(small-deployment-110): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1229 15:30:27.713946 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(small-deployment-151): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1229 15:30:28.092860 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(small-deployment-175): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1229 15:30:28.305595 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(small-deployment-102): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1229 15:30:28.514040 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(small-deployment-89): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1229 15:30:28.528194 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(small-deployment-143): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1229 15:30:28.566059 90280 wait_for_controlled_pods.go:365] WaitForControlledPodsRunning: running 1, deleted 0, timeout: 0, failed: 0 I1229 15:30:28.566130 90280 wait_for_controlled_pods.go:370] WaitForControlledPodsRunning: maxDuration=5.002097668s, operationTimeout=15m0s, ratio=0.01 I1229 15:30:28.566152 90280 wait_for_controlled_pods.go:384] WaitForControlledPodsRunning: 1/1 DaemonSets are running with all pods I1229 15:30:28.569285 90280 wait_for_controlled_pods.go:365] WaitForControlledPodsRunning: running 3, deleted 0, timeout: 0, failed: 0 I1229 15:30:28.569323 90280 wait_for_controlled_pods.go:370] WaitForControlledPodsRunning: maxDuration=5.007746663s, operationTimeout=15m0s, ratio=0.01 I1229 15:30:28.569338 90280 wait_for_controlled_pods.go:384] WaitForControlledPodsRunning: 3/3 Jobs are running with all pods I1229 15:30:28.581628 90280 wait_for_controlled_pods.go:365] WaitForControlledPodsRunning: running 2, deleted 0, timeout: 0, failed: 0 I1229 15:30:28.581678 90280 wait_for_controlled_pods.go:370] WaitForControlledPodsRunning: maxDuration=40.007547901s, operationTimeout=15m0s, ratio=0.04 I1229 15:30:28.581696 90280 wait_for_controlled_pods.go:384] WaitForControlledPodsRunning: 2/2 StatefulSets are running with all pods I1229 15:30:28.778361 90280 wait_for_controlled_pods.go:365] WaitForControlledPodsRunning: running 323, deleted 0, timeout: 0, failed: 0 I1229 15:30:28.778420 90280 wait_for_controlled_pods.go:370] WaitForControlledPodsRunning: maxDuration=5.008473636s, operationTimeout=15m0s, ratio=0.01 I1229 15:30:28.778440 90280 wait_for_controlled_pods.go:384] WaitForControlledPodsRunning: 323/323 Deployments are running with all pods I1229 15:30:28.778479 90280 simple_test_executor.go:171] Step "[step: 07] Waiting for 'create objects' to be completed" ended I1229 15:30:28.778505 90280 simple_test_executor.go:149] Step "[step: 08] Creating scheduler throughput measurements" started I1229 15:30:28.778585 90280 pod_startup_latency.go:132] PodStartupLatency: labelSelector(group = scheduler-throughput): starting pod startup latency measurement... I1229 15:30:28.778714 90280 wait_for_controlled_pods.go:257] WaitForControlledPodsRunning: starting wait for controlled pods measurement... ... skipping 4 lines ... I1229 15:30:28.925375 90280 simple_test_executor.go:171] Step "[step: 09] create scheduler throughput pods" ended I1229 15:30:28.925403 90280 simple_test_executor.go:149] Step "[step: 10] Waiting for scheduler throughput pods to be created" started I1229 15:30:28.925440 90280 wait_for_controlled_pods.go:288] WaitForControlledPodsRunning: waiting for controlled pods measurement... I1229 15:30:33.933495 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-2), controlledBy(scheduler-throughput-deployment-0): Pods: 569 out of 1000 created, 437 running (437 updated), 131 pending scheduled, 1 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1229 15:30:38.952749 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-2), controlledBy(scheduler-throughput-deployment-0): Pods: 1000 out of 1000 created, 915 running (915 updated), 85 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1229 15:30:43.972535 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-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 I1229 15:30:43.972614 90280 wait_for_controlled_pods.go:365] WaitForControlledPodsRunning: running 1, deleted 0, timeout: 0, failed: 0 I1229 15:30:43.972627 90280 wait_for_controlled_pods.go:370] WaitForControlledPodsRunning: maxDuration=15.048664923s, operationTimeout=20m0s, ratio=0.01 I1229 15:30:43.972644 90280 wait_for_controlled_pods.go:384] WaitForControlledPodsRunning: 1/1 Deployments are running with all pods I1229 15:30:43.972671 90280 simple_test_executor.go:171] Step "[step: 10] Waiting for scheduler throughput pods to be created" ended I1229 15:30:43.972693 90280 simple_test_executor.go:149] Step "[step: 11] Collecting scheduler throughput measurements" started I1229 15:30:43.972726 90280 scheduling_throughput.go:154] SchedulingThroughput: gathering data I1229 15:30:43.972838 90280 pod_startup_latency.go:226] PodStartupLatency: labelSelector(group = scheduler-throughput): gathering pod startup latency measurement... ... skipping 33 lines ... I1229 15:30:44.391066 90280 wait_for_pods.go:64] WaitForControlledPodsRunning: namespace(test-gomgd6-2), controlledBy(scheduler-throughput-deployment-0): starting with timeout: 19m59.999972405s I1229 15:30:44.391088 90280 simple_test_executor.go:149] Step "[step: 13] Waiting for scheduler throughput pods to be deleted" started I1229 15:30:44.391123 90280 wait_for_controlled_pods.go:288] WaitForControlledPodsRunning: waiting for controlled pods measurement... I1229 15:30:49.401802 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-2), controlledBy(scheduler-throughput-deployment-0): Pods: 459 out of 0 created, 459 running (459 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 84 terminating, 0 unknown, 0 runningButNotReady I1229 15:30:54.403375 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-2), controlledBy(scheduler-throughput-deployment-0): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 37 terminating, 0 unknown, 0 runningButNotReady I1229 15:30:59.403645 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-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 I1229 15:30:59.403706 90280 wait_for_controlled_pods.go:365] WaitForControlledPodsRunning: running 0, deleted 1, timeout: 0, failed: 0 I1229 15:30:59.403719 90280 wait_for_controlled_pods.go:370] WaitForControlledPodsRunning: maxDuration=15.012618829s, operationTimeout=20m0s, ratio=0.01 I1229 15:30:59.403738 90280 wait_for_controlled_pods.go:384] WaitForControlledPodsRunning: 0/0 Deployments are running with all pods I1229 15:30:59.403759 90280 simple_test_executor.go:171] Step "[step: 13] Waiting for scheduler throughput pods to be deleted" ended I1229 15:30:59.403779 90280 simple_test_executor.go:149] Step "[step: 14] Starting latency pod measurements" started I1229 15:30:59.403841 90280 wait_for_controlled_pods.go:257] WaitForControlledPodsRunning: starting wait for controlled pods measurement... I1229 15:30:59.403862 90280 pod_startup_latency.go:132] PodStartupLatency: labelSelector(group = latency): starting pod startup latency measurement... ... skipping 999 lines ... I1229 15:32:43.629614 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-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 I1229 15:32:43.832109 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-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 I1229 15:32:44.031515 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-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 I1229 15:32:44.234010 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-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 I1229 15:32:44.433566 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-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 I1229 15:32:44.633046 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-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 I1229 15:32:45.052541 90280 wait_for_controlled_pods.go:365] WaitForControlledPodsRunning: running 500, deleted 0, timeout: 0, failed: 0 I1229 15:32:45.052604 90280 wait_for_controlled_pods.go:370] WaitForControlledPodsRunning: maxDuration=5.001532667s, operationTimeout=15m0s, ratio=0.01 I1229 15:32:45.052639 90280 wait_for_controlled_pods.go:384] WaitForControlledPodsRunning: 500/500 Deployments are running with all pods I1229 15:32:45.052674 90280 simple_test_executor.go:171] Step "[step: 16] Waiting for latency pods to be running" ended I1229 15:32:45.052699 90280 simple_test_executor.go:149] Step "[step: 17] Deleting latency pods" started I1229 15:32:45.091060 90280 wait_for_pods.go:64] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(latency-deployment-0): starting with timeout: 14m59.999975974s I1229 15:32:45.191731 90280 wait_for_pods.go:64] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(latency-deployment-1): starting with timeout: 14m59.99997541s ... skipping 495 lines ... I1229 15:33:34.791751 90280 wait_for_pods.go:64] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(latency-deployment-497): starting with timeout: 14m59.999975811s I1229 15:33:34.893429 90280 wait_for_pods.go:64] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(latency-deployment-498): starting with timeout: 14m59.999971534s I1229 15:33:34.990867 90280 simple_test_executor.go:171] Step "[step: 17] Deleting latency pods" ended I1229 15:33:34.990901 90280 simple_test_executor.go:149] Step "[step: 18] Waiting for latency pods to be deleted" started I1229 15:33:34.990927 90280 wait_for_pods.go:64] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(latency-deployment-499): starting with timeout: 14m59.999977238s I1229 15:33:34.990933 90280 wait_for_controlled_pods.go:288] WaitForControlledPodsRunning: waiting for controlled pods measurement... I1229 15:33:40.038598 90280 wait_for_controlled_pods.go:365] WaitForControlledPodsRunning: running 0, deleted 500, timeout: 0, failed: 0 I1229 15:33:40.038641 90280 wait_for_controlled_pods.go:370] WaitForControlledPodsRunning: maxDuration=5.001276683s, operationTimeout=15m0s, ratio=0.01 I1229 15:33:40.038668 90280 wait_for_controlled_pods.go:384] WaitForControlledPodsRunning: 0/0 Deployments are running with all pods I1229 15:33:40.038764 90280 simple_test_executor.go:171] Step "[step: 18] Waiting for latency pods to be deleted" ended I1229 15:33:40.038789 90280 simple_test_executor.go:149] Step "[step: 19] Collecting pod startup latency" started I1229 15:33:40.038842 90280 pod_startup_latency.go:226] PodStartupLatency: labelSelector(group = latency): gathering pod startup latency measurement... I1229 15:33:40.441004 90280 phase_latency.go:141] PodStartupLatency: 100 worst run_to_watch latencies: [{test-gomgd6-1/latency-deployment-206-7d555567-l86tj 1.383660948s} {test-gomgd6-1/latency-deployment-12-6b7647c479-r6hmr 1.384180685s} {test-gomgd6-1/latency-deployment-197-65f7bb4585-mxk2l 1.384592472s} {test-gomgd6-1/latency-deployment-401-7d4f474f5c-wv42q 1.388135687s} {test-gomgd6-1/latency-deployment-287-7974bfd769-9mzpb 1.397300701s} {test-gomgd6-1/latency-deployment-101-7bfd77dc59-n75dl 1.398678956s} {test-gomgd6-1/latency-deployment-10-cddb4d6d7-tq9jh 1.3993675s} {test-gomgd6-1/latency-deployment-335-59dc6855cc-zlzsp 1.399479137s} {test-gomgd6-1/latency-deployment-471-9cd6784f5-m6crj 1.401009217s} {test-gomgd6-1/latency-deployment-361-5f7495cb5f-qsq4m 1.402510076s} {test-gomgd6-1/latency-deployment-425-7f8cf5d98f-nvztq 1.40287627s} {test-gomgd6-1/latency-deployment-67-75f744f959-ckppb 1.405706125s} {test-gomgd6-1/latency-deployment-77-5fcd98dd6c-wl8hp 1.410861386s} {test-gomgd6-1/latency-deployment-301-5c75dbfc4c-tpmwn 1.411146543s} {test-gomgd6-1/latency-deployment-485-76c54579c7-chj8j 1.413286466s} {test-gomgd6-1/latency-deployment-435-7448d885dc-bjwln 1.414011537s} {test-gomgd6-1/latency-deployment-225-6d7bbcd8fc-tksnk 1.41682406s} {test-gomgd6-1/latency-deployment-315-6dd9dcd8d9-zrt2z 1.417348385s} {test-gomgd6-1/latency-deployment-245-5456dd46c7-cxvs7 1.418028322s} {test-gomgd6-1/latency-deployment-201-578579bd4f-6c6qq 1.422262801s} {test-gomgd6-1/latency-deployment-499-7c8bc8bd8c-trtmq 1.426052062s} {test-gomgd6-1/latency-deployment-291-74c4fbdd79-sc84t 1.437902821s} {test-gomgd6-1/latency-deployment-68-7496dcd4b7-lc6l4 1.442612829s} {test-gomgd6-1/latency-deployment-491-5d69b44c79-t7wpw 1.445057417s} {test-gomgd6-1/latency-deployment-252-b4c6d9657-9dtx7 1.447462585s} {test-gomgd6-1/latency-deployment-227-7d55db5ffc-f6lw6 1.447594028s} {test-gomgd6-1/latency-deployment-150-6cf6dc48b7-dvb5p 1.447962276s} {test-gomgd6-1/latency-deployment-410-6f6ccd4769-7nx9s 1.448406631s} {test-gomgd6-1/latency-deployment-108-544c6b64d9-cn46v 1.448567923s} {test-gomgd6-1/latency-deployment-27-6754848b5f-qvd8b 1.453593486s} {test-gomgd6-1/latency-deployment-41-864fcfc9d7-77j68 1.462038796s} {test-gomgd6-1/latency-deployment-286-6cc6546fcf-xr6gh 1.46656049s} {test-gomgd6-1/latency-deployment-476-7d648bd7d9-x4fnd 1.468923665s} {test-gomgd6-1/latency-deployment-319-6c78bcb66f-rzf66 1.475614829s} {test-gomgd6-1/latency-deployment-161-648f7f57f-5mpcd 1.480385008s} {test-gomgd6-1/latency-deployment-17-b589f64d7-zdhr5 1.482926478s} {test-gomgd6-1/latency-deployment-321-b7dbb577f-sph55 1.486536447s} {test-gomgd6-1/latency-deployment-11-5d46758d7-k8hmg 1.487200122s} {test-gomgd6-1/latency-deployment-387-758bcb6d79-5cnrm 1.487321722s} {test-gomgd6-1/latency-deployment-148-6c79776cc-4ffgd 1.497020526s} {test-gomgd6-1/latency-deployment-137-9b5ddc789-4hk72 1.500574547s} {test-gomgd6-1/latency-deployment-390-8874dc7dc-f7mm4 1.507822892s} {test-gomgd6-1/latency-deployment-51-6bc4b99b7-xsvfg 1.515699452s} {test-gomgd6-1/latency-deployment-215-765f6b6d5f-t2jgw 1.51917509s} {test-gomgd6-1/latency-deployment-1-6779775c85-86crb 1.525064967s} {test-gomgd6-1/latency-deployment-424-747648cf8c-pbjqj 1.528400905s} {test-gomgd6-1/latency-deployment-382-c6f7444bf-55x8x 1.535118077s} {test-gomgd6-1/latency-deployment-276-686564d685-q558s 1.538273267s} {test-gomgd6-1/latency-deployment-72-7bbc49f8c5-vbcdj 1.545311003s} {test-gomgd6-1/latency-deployment-490-6cd947dbf7-2ldt7 1.550546341s} {test-gomgd6-1/latency-deployment-172-69cc877955-9zfdz 1.551197614s} {test-gomgd6-1/latency-deployment-236-66c84469c-8kf7n 1.55766467s} {test-gomgd6-1/latency-deployment-36-7588ddd7c9-l7lnr 1.563426993s} {test-gomgd6-1/latency-deployment-492-75958df4b5-p7hzm 1.566800999s} {test-gomgd6-1/latency-deployment-166-65d7cc57b5-m8f6p 1.580690518s} {test-gomgd6-1/latency-deployment-226-db7fcddc9-8cq8s 1.583001872s} {test-gomgd6-1/latency-deployment-375-786d4ffccc-xn46b 1.587964033s} {test-gomgd6-1/latency-deployment-131-6f54bb85-x5stc 1.591445048s} {test-gomgd6-1/latency-deployment-474-598bc58d5c-bvhdm 1.593362323s} {test-gomgd6-1/latency-deployment-341-bbd9cd767-wrbvg 1.59520579s} {test-gomgd6-1/latency-deployment-347-7dd444cf59-76kv4 1.598533446s} {test-gomgd6-1/latency-deployment-242-d89584495-d67ht 1.601236165s} {test-gomgd6-1/latency-deployment-127-6db8d9dcc5-fnc6t 1.603556782s} {test-gomgd6-1/latency-deployment-381-67755bc66c-2x8gn 1.613139668s} {test-gomgd6-1/latency-deployment-391-576d8bcc5c-x6hgz 1.630193979s} {test-gomgd6-1/latency-deployment-427-75ff7b6477-vl4lh 1.637859931s} {test-gomgd6-1/latency-deployment-152-58bb9c9dc9-69254 1.638752014s} {test-gomgd6-1/latency-deployment-416-76f8b4ffc7-r24xf 1.64002492s} {test-gomgd6-1/latency-deployment-496-6bd4fdc86f-9szvw 1.663651764s} {test-gomgd6-1/latency-deployment-317-76c7dd97b9-rvmct 1.666265494s} {test-gomgd6-1/latency-deployment-37-9fb5bb9c5-q2bs6 1.670095336s} {test-gomgd6-1/latency-deployment-241-86465f5c97-4n74v 1.679358886s} {test-gomgd6-1/latency-deployment-156-55f7c9b7c5-n9c9b 1.681473314s} {test-gomgd6-1/latency-deployment-47-545569bcb7-7c85r 1.687207404s} {test-gomgd6-1/latency-deployment-61-658fd58d75-pjt66 1.688335766s} {test-gomgd6-1/latency-deployment-332-5bdcffc54c-gd286 1.690531617s} {test-gomgd6-1/latency-deployment-117-746947766f-5jnc2 1.705375796s} {test-gomgd6-1/latency-deployment-221-5674b9db85-whlqd 1.727954199s} {test-gomgd6-1/latency-deployment-112-84f8b5fb47-q2m56 1.732853048s} {test-gomgd6-1/latency-deployment-132-8585b76859-vt7bt 1.735192986s} {test-gomgd6-1/latency-deployment-411-6c4f8674c5-mbn26 1.746590288s} {test-gomgd6-1/latency-deployment-371-55f9d8db69-2s4wf 1.754655377s} {test-gomgd6-1/latency-deployment-162-6fd598d69-dd8nr 1.761478944s} {test-gomgd6-1/latency-deployment-237-c6bddcd55-v5bjh 1.764672683s} {test-gomgd6-1/latency-deployment-272-d45957d4f-thxzb 1.765510358s} {test-gomgd6-1/latency-deployment-42-7d7d5f7bb7-96w5r 1.780091181s} {test-gomgd6-1/latency-deployment-337-66d7b78869-zk6ts 1.787349765s} {test-gomgd6-1/latency-deployment-436-b8977748f-zntdl 1.797735672s} {test-gomgd6-1/latency-deployment-297-5b47fd7cc9-bjxnh 1.806567987s} {test-gomgd6-1/latency-deployment-23-7bbb55f647-8kfbm 1.832132613s} {test-gomgd6-1/latency-deployment-451-7668f97995-lhvvd 1.833323514s} {test-gomgd6-1/latency-deployment-292-6fb7dc6cdf-v98hk 1.836274708s} {test-gomgd6-1/latency-deployment-2-66bd84bb95-2p8sp 1.844650837s} {test-gomgd6-1/latency-deployment-466-8674b98479-txjhq 1.847514123s} {test-gomgd6-1/latency-deployment-295-58c794f695-cmprv 1.8621151s} {test-gomgd6-1/latency-deployment-163-687d84d77f-qwk9x 1.883822024s} {test-gomgd6-1/latency-deployment-282-566cc9d647-qb448 1.887954272s} {test-gomgd6-1/latency-deployment-377-74574dff7c-m45bv 1.897423857s} {test-gomgd6-1/latency-deployment-426-5df9df6fcf-pp4zc 1.96367858s} {test-gomgd6-1/latency-deployment-143-5556c9cb5f-vqx99 2.008067641s}] ... skipping 585 lines ... I1229 15:34:21.820295 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(small-deployment-249): Pods: 2 out of 2 created, 2 running (2 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1229 15:34:21.873645 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(small-deployment-107): Pods: 6 out of 6 created, 6 running (6 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1229 15:34:21.873819 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(small-deployment-146): Pods: 2 out of 2 created, 2 running (2 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1229 15:34:22.322259 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(small-deployment-261): Pods: 4 out of 4 created, 4 running (4 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1229 15:34:22.417471 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(small-deployment-294): Pods: 2 out of 2 created, 2 running (2 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1229 15:34:22.432717 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(small-deployment-271): Pods: 2 out of 2 created, 2 running (2 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1229 15:34:22.473554 90280 wait_for_controlled_pods.go:365] WaitForControlledPodsRunning: running 3, deleted 0, timeout: 0, failed: 0 I1229 15:34:22.473602 90280 wait_for_controlled_pods.go:370] WaitForControlledPodsRunning: maxDuration=5.005964086s, operationTimeout=15m0s, ratio=0.01 I1229 15:34:22.473626 90280 wait_for_controlled_pods.go:384] WaitForControlledPodsRunning: 3/3 Jobs are running with all pods I1229 15:34:22.631065 90280 wait_for_controlled_pods.go:365] WaitForControlledPodsRunning: running 323, deleted 0, timeout: 0, failed: 0 I1229 15:34:22.631114 90280 wait_for_controlled_pods.go:370] WaitForControlledPodsRunning: maxDuration=5.011794352s, operationTimeout=15m0s, ratio=0.01 I1229 15:34:22.631137 90280 wait_for_controlled_pods.go:384] WaitForControlledPodsRunning: 323/323 Deployments are running with all pods I1229 15:34:24.615096 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(daemonset-0): Pods: 97 out of 100 created, 90 running (69 updated), 7 pending scheduled, 0 not scheduled, 0 inactive, 3 terminating, 0 unknown, 0 runningButNotReady I1229 15:34:29.413554 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(medium-statefulset-0): Pods: 44 out of 44 created, 39 running (39 updated), 5 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1229 15:34:29.617873 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(daemonset-0): Pods: 100 out of 100 created, 94 running (94 updated), 6 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1229 15:34:34.415145 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(medium-statefulset-0): Pods: 44 out of 44 created, 40 running (40 updated), 4 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1229 15:34:34.619949 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-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 I1229 15:34:34.620022 90280 wait_for_controlled_pods.go:365] WaitForControlledPodsRunning: running 1, deleted 0, timeout: 0, failed: 0 I1229 15:34:34.620037 90280 wait_for_controlled_pods.go:370] WaitForControlledPodsRunning: maxDuration=25.0826537s, operationTimeout=15m0s, ratio=0.03 I1229 15:34:34.620053 90280 wait_for_controlled_pods.go:384] WaitForControlledPodsRunning: 1/1 DaemonSets are running with all pods I1229 15:34:39.416782 90280 wait_for_pods.go:117] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(medium-statefulset-0): Pods: 44 out of 44 created, 44 running (44 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady I1229 15:34:39.416896 90280 wait_for_controlled_pods.go:365] WaitForControlledPodsRunning: running 2, deleted 0, timeout: 0, failed: 0 I1229 15:34:39.416918 90280 wait_for_controlled_pods.go:370] WaitForControlledPodsRunning: maxDuration=30.008992746s, operationTimeout=15m0s, ratio=0.03 I1229 15:34:39.416941 90280 wait_for_controlled_pods.go:384] WaitForControlledPodsRunning: 2/2 StatefulSets are running with all pods I1229 15:34:39.416970 90280 simple_test_executor.go:171] Step "[step: 22] Waiting for 'scale and update objects' to be completed" ended I1229 15:34:39.416994 90280 simple_test_executor.go:149] Step "[step: 23] Starting measurement for 'delete objects'" started I1229 15:34:39.417062 90280 wait_for_controlled_pods.go:254] WaitForControlledPodsRunning: wait for controlled pods measurement already running I1229 15:34:39.417098 90280 wait_for_controlled_pods.go:254] WaitForControlledPodsRunning: wait for controlled pods measurement already running ... skipping 251 lines ... I1229 15:37:09.050307 90280 wait_for_pods.go:64] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(small-deployment-184): starting with timeout: 14m59.999978149s I1229 15:37:10.113801 90280 wait_for_pods.go:64] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(small-deployment-143): starting with timeout: 14m59.999976843s I1229 15:37:10.697080 90280 wait_for_pods.go:64] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(small-deployment-263): starting with timeout: 14m59.999976071s I1229 15:37:11.070557 90280 wait_for_pods.go:64] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(small-deployment-55): starting with timeout: 14m59.999973541s I1229 15:37:11.378762 90280 wait_for_pods.go:64] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(small-deployment-207): starting with timeout: 14m59.999940789s I1229 15:37:11.403793 90280 wait_for_pods.go:64] WaitForControlledPodsRunning: namespace(test-gomgd6-1), controlledBy(small-deployment-146): starting with timeout: 14m59.999977721s {"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-12-29T15:37:11Z"} ++ early_exit_handler ++ '[' -n 168 ']' ++ kill -TERM 168 ++ cleanup_dind ++ [[ true == \t\r\u\e ]] ++ echo 'Cleaning up after docker' ... skipping 4 lines ...