This job view page is being replaced by Spyglass soon. Check out the new job view.
PRlogicalhan: wire up feature enablement metric in feature_gate.go
ResultABORTED
Tests 0 failed / 67 succeeded
Started2022-09-23 02:05
Elapsed56m8s
Revision272ec583884727e0f1230378f5720d96c4ba4350
Refs 112690

No Test Failures!


Show 67 Passed Tests

Error lines from build-log.txt

... skipping 723 lines ...
Looking for address 'e2e-112690-95a39-master-ip'
Looking for address 'e2e-112690-95a39-master-internal-ip'
Using master: e2e-112690-95a39-master (external IP: 35.237.69.128; 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-29_e2e-112690-95a39" set.
User "k8s-infra-e2e-boskos-scale-29_e2e-112690-95a39" set.
Context "k8s-infra-e2e-boskos-scale-29_e2e-112690-95a39" created.
Switched to context "k8s-infra-e2e-boskos-scale-29_e2e-112690-95a39".
... skipping 227 lines ...
e2e-112690-95a39-minion-group-z7rm   Ready                         <none>   60s    v1.26.0-alpha.1.92+2ec9e4a56fe065
e2e-112690-95a39-minion-group-zxr8   Ready                         <none>   59s    v1.26.0-alpha.1.92+2ec9e4a56fe065
e2e-112690-95a39-minion-heapster     Ready                         <none>   78s    v1.26.0-alpha.1.92+2ec9e4a56fe065
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":""}   
scheduler            Healthy   ok                              
etcd-0               Healthy   {"health":"true","reason":""}   
controller-manager   Healthy   ok                              
Cluster validation encountered some problems, but cluster should be in working order
...ignoring non-fatal errors in validate-cluster
Done, listing cluster services:

Kubernetes control plane is running at https://35.237.69.128
GLBCDefaultBackend is running at https://35.237.69.128/api/v1/namespaces/kube-system/services/default-http-backend:http/proxy
CoreDNS is running at https://35.237.69.128/api/v1/namespaces/kube-system/services/kube-dns:dns/proxy
Metrics-server is running at https://35.237.69.128/api/v1/namespaces/kube-system/services/https:metrics-server:/proxy
... skipping 59 lines ...
2022/09/23 02:33:00 process.go:153: Running: /home/prow/go/src/k8s.io/perf-tests/run-e2e.sh cluster-loader2 --nodes=100 --provider=gce --experimental-gcp-snapshot-prometheus-disk=true --experimental-prometheus-disk-snapshot-name=pull-kubernetes-e2e-gce-100-performance-1573130218040725504 --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
TOOL_NAME: cluster-loader2
k8s.io/perf-tests git log:
964ccc47d59c35296e44e8a12079df1ece47d12b - Tue Sep 20 08:15:20 2022 (Merge pull request #2064 from oprinmarius/patch/azure-disk)
349be8a8c2c040a684deee24a99e3ba4ec27b468 - Fri Sep 9 09:27:22 2022 (Merge pull request #2139 from Argh4k/apiserver-calls)
f2db8e258d4e34a29c79c53a409c26b8ac302a64 - Thu Sep 8 13:01:44 2022 (Merge pull request #2140 from dlapcevic/new-dns-client-1)
1bdbd6df74b1bb0bb39762a96ff9a6f41b53f471 - Thu Sep 8 12:10:22 2022 (Add DNS lookup error percentage threshold instead of error count)
5985db0548d268abc4cd733006f0d743fbb5baaa - Wed Sep 7 13:38:21 2022 (Add dashboards for calls made from apiserver)
19e50ee9b6e2dacbdaad9ab12e4b2270f2cbc80e - Thu Sep 1 18:33:07 2022 (Merge pull request #2138 from tosi3k/gci-driver-adc)
e058a80f38dedb901ff996d8771446cbabf70be7 - Thu Sep 1 13:29:07 2022 (Fall back to using ADC when setting up GCE PD CSI driver in CL2)
f77b43a9b2cc79d59d5ac1cb8f77f41edda4dc86 - Wed Aug 31 13:27:00 2022 (Merge pull request #2113 from jupblb/b235038746)
2ccc73a91a2a54c42cf50d88e3fe6b4e24f757d4 - Thu Aug 4 14:53:56 2022 (Add documentation about adding new clusterloader2 test)
483fe918a398c30962c414ddd22750b82a6597bd - Wed Aug 31 06:51:02 2022 (Merge pull request #2132 from mborsz/startup-delete)
... skipping 1018 lines ...
I0923 02:40:48.307578  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(small-deployment-115): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I0923 02:40:49.175845  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(small-deployment-66): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I0923 02:40:49.796649  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(small-deployment-101): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I0923 02:40:49.816804  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(small-deployment-283): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I0923 02:40:50.132024  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(small-deployment-20): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I0923 02:40:50.381360  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(small-deployment-185): Pods: 5 out of 5 created, 5 running (5 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I0923 02:40:50.432237  100352 wait_for_controlled_pods.go:320] WaitForControlledPodsRunning: running 3, deleted 0, timeout: 0, failed: 0
I0923 02:40:50.432281  100352 wait_for_controlled_pods.go:325] WaitForControlledPodsRunning: maxDuration=5.004501s, operationTimeout=15m0s, ratio=0.01
I0923 02:40:50.432302  100352 wait_for_controlled_pods.go:339] WaitForControlledPodsRunning: 3/3 Jobs are running with all pods
I0923 02:40:50.432368  100352 wait_for_controlled_pods.go:320] WaitForControlledPodsRunning: running 2, deleted 0, timeout: 0, failed: 0
I0923 02:40:50.432410  100352 wait_for_controlled_pods.go:325] WaitForControlledPodsRunning: maxDuration=40.007651346s, operationTimeout=15m0s, ratio=0.04
I0923 02:40:50.432425  100352 wait_for_controlled_pods.go:339] WaitForControlledPodsRunning: 2/2 StatefulSets are running with all pods
I0923 02:40:50.438776  100352 wait_for_controlled_pods.go:320] WaitForControlledPodsRunning: running 1, deleted 0, timeout: 0, failed: 0
I0923 02:40:50.438803  100352 wait_for_controlled_pods.go:325] WaitForControlledPodsRunning: maxDuration=5.002244216s, operationTimeout=15m0s, ratio=0.01
I0923 02:40:50.438816  100352 wait_for_controlled_pods.go:339] WaitForControlledPodsRunning: 1/1 DaemonSets are running with all pods
I0923 02:40:50.623460  100352 wait_for_controlled_pods.go:320] WaitForControlledPodsRunning: running 323, deleted 0, timeout: 0, failed: 0
I0923 02:40:50.623560  100352 wait_for_controlled_pods.go:325] WaitForControlledPodsRunning: maxDuration=5.008263959s, operationTimeout=15m0s, ratio=0.01
I0923 02:40:50.623598  100352 wait_for_controlled_pods.go:339] WaitForControlledPodsRunning: 323/323 Deployments are running with all pods
I0923 02:40:50.623646  100352 simple_test_executor.go:171] Step "[step: 07] Waiting for 'create objects' to be completed" ended
I0923 02:40:50.623675  100352 simple_test_executor.go:149] Step "[step: 08] Creating scheduler throughput measurements" started
I0923 02:40:50.623790  100352 wait_for_controlled_pods.go:216] WaitForControlledPodsRunning: starting wait for controlled pods measurement...
I0923 02:40:50.623898  100352 pod_startup_latency.go:132] PodStartupLatency: labelSelector(group = scheduler-throughput): starting pod startup latency measurement...
... skipping 4 lines ...
I0923 02:40:50.767982  100352 simple_test_executor.go:171] Step "[step: 09] create scheduler throughput pods" ended
I0923 02:40:50.768009  100352 simple_test_executor.go:149] Step "[step: 10] Waiting for scheduler throughput pods to be created" started
I0923 02:40:50.768050  100352 wait_for_controlled_pods.go:247] WaitForControlledPodsRunning: waiting for controlled pods measurement...
I0923 02:40:55.776302  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-2), controlledBy(scheduler-throughput-deployment-0): Pods: 577 out of 1000 created, 414 running (414 updated), 162 pending scheduled, 1 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I0923 02:41:00.792309  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-2), controlledBy(scheduler-throughput-deployment-0): Pods: 1000 out of 1000 created, 911 running (911 updated), 89 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I0923 02:41:05.810078  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-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 
I0923 02:41:05.810149  100352 wait_for_controlled_pods.go:320] WaitForControlledPodsRunning: running 1, deleted 0, timeout: 0, failed: 0
I0923 02:41:05.810162  100352 wait_for_controlled_pods.go:325] WaitForControlledPodsRunning: maxDuration=15.042893215s, operationTimeout=20m0s, ratio=0.01
I0923 02:41:05.810180  100352 wait_for_controlled_pods.go:339] WaitForControlledPodsRunning: 1/1 Deployments are running with all pods
I0923 02:41:05.810210  100352 simple_test_executor.go:171] Step "[step: 10] Waiting for scheduler throughput pods to be created" ended
I0923 02:41:05.810234  100352 simple_test_executor.go:149] Step "[step: 11] Collecting scheduler throughput measurements" started
I0923 02:41:05.810275  100352 scheduling_throughput.go:154] SchedulingThroughput: gathering data
I0923 02:41:05.810333  100352 pod_startup_latency.go:226] PodStartupLatency: labelSelector(group = scheduler-throughput): gathering pod startup latency measurement...
... skipping 33 lines ...
I0923 02:41:06.313572  100352 simple_test_executor.go:149] Step "[step: 13] Waiting for scheduler throughput pods to be deleted" started
I0923 02:41:06.313605  100352 wait_for_controlled_pods.go:247] WaitForControlledPodsRunning: waiting for controlled pods measurement...
I0923 02:41:06.313662  100352 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-1g3gfm-2), controlledBy(scheduler-throughput-deployment-0): starting with timeout: 19m59.999980113s
I0923 02:41:11.322881  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-2), controlledBy(scheduler-throughput-deployment-0): Pods: 458 out of 0 created, 458 running (458 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 82 terminating, 0 unknown, 0 runningButNotReady 
I0923 02:41:16.323646  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-2), controlledBy(scheduler-throughput-deployment-0): Pods: 0 out of 0 created, 0 running (0 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 46 terminating, 0 unknown, 0 runningButNotReady 
I0923 02:41:21.324253  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-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 
I0923 02:41:21.324329  100352 wait_for_controlled_pods.go:320] WaitForControlledPodsRunning: running 0, deleted 1, timeout: 0, failed: 0
I0923 02:41:21.324343  100352 wait_for_controlled_pods.go:325] WaitForControlledPodsRunning: maxDuration=15.01062638s, operationTimeout=20m0s, ratio=0.01
I0923 02:41:21.324362  100352 wait_for_controlled_pods.go:339] WaitForControlledPodsRunning: 0/0 Deployments are running with all pods
I0923 02:41:21.324388  100352 simple_test_executor.go:171] Step "[step: 13] Waiting for scheduler throughput pods to be deleted" ended
I0923 02:41:21.324414  100352 simple_test_executor.go:149] Step "[step: 14] Starting latency pod measurements" started
I0923 02:41:21.324472  100352 wait_for_controlled_pods.go:216] WaitForControlledPodsRunning: starting wait for controlled pods measurement...
I0923 02:41:21.324491  100352 pod_startup_latency.go:132] PodStartupLatency: labelSelector(group = latency): starting pod startup latency measurement...
... skipping 999 lines ...
I0923 02:43:05.560827  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-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 
I0923 02:43:05.761394  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-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 
I0923 02:43:05.965079  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-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 
I0923 02:43:06.162175  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-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 
I0923 02:43:06.362774  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-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 
I0923 02:43:06.564029  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-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 
I0923 02:43:06.986577  100352 wait_for_controlled_pods.go:320] WaitForControlledPodsRunning: running 500, deleted 0, timeout: 0, failed: 0
I0923 02:43:06.986638  100352 wait_for_controlled_pods.go:325] WaitForControlledPodsRunning: maxDuration=5.001593359s, operationTimeout=15m0s, ratio=0.01
I0923 02:43:06.986658  100352 wait_for_controlled_pods.go:339] WaitForControlledPodsRunning: 500/500 Deployments are running with all pods
I0923 02:43:06.986686  100352 simple_test_executor.go:171] Step "[step: 16] Waiting for latency pods to be running" ended
I0923 02:43:06.986709  100352 simple_test_executor.go:149] Step "[step: 17] Deleting latency pods" started
I0923 02:43:07.027449  100352 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(latency-deployment-0): starting with timeout: 14m59.999976244s
I0923 02:43:07.127858  100352 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(latency-deployment-1): starting with timeout: 14m59.999978703s
... skipping 495 lines ...
I0923 02:43:56.729537  100352 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(latency-deployment-497): starting with timeout: 14m59.999975982s
I0923 02:43:56.829234  100352 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(latency-deployment-498): starting with timeout: 14m59.999983363s
I0923 02:43:56.929629  100352 simple_test_executor.go:171] Step "[step: 17] Deleting latency pods" ended
I0923 02:43:56.929664  100352 simple_test_executor.go:149] Step "[step: 18] Waiting for latency pods to be deleted" started
I0923 02:43:56.929697  100352 wait_for_controlled_pods.go:247] WaitForControlledPodsRunning: waiting for controlled pods measurement...
I0923 02:43:56.929790  100352 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(latency-deployment-499): starting with timeout: 14m59.999976995s
I0923 02:44:01.981562  100352 wait_for_controlled_pods.go:320] WaitForControlledPodsRunning: running 0, deleted 500, timeout: 0, failed: 0
I0923 02:44:01.981615  100352 wait_for_controlled_pods.go:325] WaitForControlledPodsRunning: maxDuration=5.001242518s, operationTimeout=15m0s, ratio=0.01
I0923 02:44:01.981640  100352 wait_for_controlled_pods.go:339] WaitForControlledPodsRunning: 0/0 Deployments are running with all pods
I0923 02:44:01.981662  100352 simple_test_executor.go:171] Step "[step: 18] Waiting for latency pods to be deleted" ended
I0923 02:44:01.981693  100352 simple_test_executor.go:149] Step "[step: 19] Collecting pod startup latency" started
I0923 02:44:01.981735  100352 pod_startup_latency.go:226] PodStartupLatency: labelSelector(group = latency): gathering pod startup latency measurement...
I0923 02:44:02.521925  100352 phase_latency.go:141] PodStartupLatency: 100 worst create_to_schedule latencies: [{test-1g3gfm-1/latency-deployment-418-6567bc8b8f-c6k49 0s} {test-1g3gfm-1/latency-deployment-94-6c59f8c59-jl8fh 0s} {test-1g3gfm-1/latency-deployment-236-67799c7d6f-74bfh 0s} {test-1g3gfm-1/latency-deployment-211-7cb857cf-w9mzv 0s} {test-1g3gfm-1/latency-deployment-124-7f5458669c-sx6sm 0s} {test-1g3gfm-1/latency-deployment-185-7c6b7f794c-84qs4 0s} {test-1g3gfm-1/latency-deployment-301-6495fd75cf-6rbtj 0s} {test-1g3gfm-1/latency-deployment-432-7fc576dd49-h495t 0s} {test-1g3gfm-1/latency-deployment-448-cdcc5566c-ghl2m 0s} {test-1g3gfm-1/latency-deployment-449-69dbcf7cd9-zdlks 0s} {test-1g3gfm-1/latency-deployment-462-6bc7ccf967-fnfkv 0s} {test-1g3gfm-1/latency-deployment-168-7bc95bc77c-6pz7s 0s} {test-1g3gfm-1/latency-deployment-242-7d86cf4c99-nt5gp 0s} {test-1g3gfm-1/latency-deployment-351-67b7b96fbf-nhxgg 0s} {test-1g3gfm-1/latency-deployment-481-74898cd6d5-frctr 0s} {test-1g3gfm-1/latency-deployment-109-698dc6f8d7-58m2v 0s} {test-1g3gfm-1/latency-deployment-111-d8644d6c7-v77pr 0s} {test-1g3gfm-1/latency-deployment-201-dcb5d9b6f-jm4hw 0s} {test-1g3gfm-1/latency-deployment-405-78db5cf445-qt8pp 0s} {test-1g3gfm-1/latency-deployment-425-68bdbb58fc-nhb26 0s} {test-1g3gfm-1/latency-deployment-8-57bb45cc99-nvqqt 0s} {test-1g3gfm-1/latency-deployment-81-64b5ff68c5-kk5gx 0s} {test-1g3gfm-1/latency-deployment-223-66455c988f-xdv7c 0s} {test-1g3gfm-1/latency-deployment-278-86bb4b4fb9-9r58x 0s} {test-1g3gfm-1/latency-deployment-292-6c59c4cc49-pq2wf 0s} {test-1g3gfm-1/latency-deployment-369-69c5b95f7f-cq8hw 0s} {test-1g3gfm-1/latency-deployment-414-c89d4964f-t7lqx 0s} {test-1g3gfm-1/latency-deployment-496-5cbf4d8965-vl8ts 0s} {test-1g3gfm-1/latency-deployment-20-5b65b9c48c-bz758 0s} {test-1g3gfm-1/latency-deployment-266-5fd7b57df5-8djkc 0s} {test-1g3gfm-1/latency-deployment-361-fd8495967-j2t2n 0s} {test-1g3gfm-1/latency-deployment-485-699c9b6885-t9wmv 0s} {test-1g3gfm-1/latency-deployment-181-578fcc79b7-xr2th 0s} {test-1g3gfm-1/latency-deployment-310-587989f85f-bqll6 0s} {test-1g3gfm-1/latency-deployment-4-699969d975-28cck 0s} {test-1g3gfm-1/latency-deployment-65-d8c5c776c-tkrd2 0s} {test-1g3gfm-1/latency-deployment-77-7c944f8b95-5mb7f 0s} {test-1g3gfm-1/latency-deployment-366-5c79bfdcf7-9p7s6 0s} {test-1g3gfm-1/latency-deployment-206-6d87964f75-l42db 0s} {test-1g3gfm-1/latency-deployment-251-685cc85cb7-j6nwm 0s} {test-1g3gfm-1/latency-deployment-269-7c5977b79c-hwg8p 0s} {test-1g3gfm-1/latency-deployment-291-6d96b4bfb7-c7lvz 0s} {test-1g3gfm-1/latency-deployment-465-fcd58bfd9-mx825 0s} {test-1g3gfm-1/latency-deployment-468-6c87868687-tsbf5 0s} {test-1g3gfm-1/latency-deployment-120-544bb9cc89-6nm5l 0s} {test-1g3gfm-1/latency-deployment-315-668f95fdb9-dchmh 0s} {test-1g3gfm-1/latency-deployment-443-745b7c7f77-slmtk 0s} {test-1g3gfm-1/latency-deployment-453-686c844f4c-8x6j8 0s} {test-1g3gfm-1/latency-deployment-126-5847867865-49b2z 0s} {test-1g3gfm-1/latency-deployment-306-79f76dbb5c-rpghv 0s} {test-1g3gfm-1/latency-deployment-42-cf5fcd8f9-sg2h8 0s} {test-1g3gfm-1/latency-deployment-203-7f8d7556df-84hdm 0s} {test-1g3gfm-1/latency-deployment-478-7dcdcf6dcc-gmtxt 0s} {test-1g3gfm-1/latency-deployment-43-7597697b6c-fnc2n 0s} {test-1g3gfm-1/latency-deployment-179-54c46c7c4f-t6q59 0s} {test-1g3gfm-1/latency-deployment-457-6fd498bd5f-tlpk8 0s} {test-1g3gfm-1/latency-deployment-325-7d77b6d959-8wqcg 0s} {test-1g3gfm-1/latency-deployment-334-75b5c94fff-t9q82 0s} {test-1g3gfm-1/latency-deployment-469-768b4b488f-d2wsh 0s} {test-1g3gfm-1/latency-deployment-164-5977d79bdf-fjwl5 0s} {test-1g3gfm-1/latency-deployment-314-77cd6b4d47-cx97q 0s} {test-1g3gfm-1/latency-deployment-321-8558767b87-z8kpt 0s} {test-1g3gfm-1/latency-deployment-376-5cbdc846f5-bg2rl 0s} {test-1g3gfm-1/latency-deployment-156-67f47bb879-bsbl9 0s} {test-1g3gfm-1/latency-deployment-158-69bdb64475-xqdw6 0s} {test-1g3gfm-1/latency-deployment-484-7f76d65799-vdx79 0s} {test-1g3gfm-1/latency-deployment-88-585489cd55-4fqqd 0s} {test-1g3gfm-1/latency-deployment-169-cc9bd4847-lf7sl 0s} {test-1g3gfm-1/latency-deployment-280-bff8544c9-nj6jk 0s} {test-1g3gfm-1/latency-deployment-320-7db46cd5-khk29 0s} {test-1g3gfm-1/latency-deployment-372-f7f5c4d79-zgrt8 0s} {test-1g3gfm-1/latency-deployment-487-fd999dc8f-g6pwj 0s} {test-1g3gfm-1/latency-deployment-82-56c8854c5-7grqf 0s} {test-1g3gfm-1/latency-deployment-93-75f97cf9c5-sbxd6 0s} {test-1g3gfm-1/latency-deployment-286-7dc54bd655-8mrpp 0s} {test-1g3gfm-1/latency-deployment-9-6c49b69b8f-7v48n 0s} {test-1g3gfm-1/latency-deployment-262-5499bbfcb7-zgsv8 0s} {test-1g3gfm-1/latency-deployment-439-6bfd7f845f-cznxm 0s} {test-1g3gfm-1/latency-deployment-46-7dcdb569d7-2xdwd 0s} {test-1g3gfm-1/latency-deployment-70-58dbb7f68c-j5p47 0s} {test-1g3gfm-1/latency-deployment-116-5bb688d45f-d48l2 0s} {test-1g3gfm-1/latency-deployment-238-855b959449-m8frb 0s} {test-1g3gfm-1/latency-deployment-417-7b5d5c5cf-9l4dl 0s} {test-1g3gfm-1/latency-deployment-433-5844c4cbb7-q76g7 0s} {test-1g3gfm-1/latency-deployment-12-54994f7bc9-wdzpf 0s} {test-1g3gfm-1/latency-deployment-24-7dc4996fff-4rcxj 0s} {test-1g3gfm-1/latency-deployment-28-7896c7dfff-gjjbk 0s} {test-1g3gfm-1/latency-deployment-99-d577f4455-m6lkk 0s} {test-1g3gfm-1/latency-deployment-256-78fc88d7cc-4vjf8 0s} {test-1g3gfm-1/latency-deployment-355-7bf4d5b89c-mt4ng 0s} {test-1g3gfm-1/latency-deployment-434-968d55d89-6tfll 0s} {test-1g3gfm-1/latency-deployment-19-685c9558bc-jt69p 0s} {test-1g3gfm-1/latency-deployment-128-77544cf49c-hzn42 0s} {test-1g3gfm-1/latency-deployment-294-59c7bb6c65-nf4hf 0s} {test-1g3gfm-1/latency-deployment-27-5f4c6b5cc5-42ghz 0s} {test-1g3gfm-1/latency-deployment-212-7844997445-8t292 1s} {test-1g3gfm-1/latency-deployment-227-556fcbdf6f-hpsvn 1s} {test-1g3gfm-1/latency-deployment-222-5f4698dc9-747d5 1s} {test-1g3gfm-1/latency-deployment-207-67f78464df-w89wn 1s} {test-1g3gfm-1/latency-deployment-217-6fffbd5cc9-dfpsg 1s}]
... skipping 603 lines ...
I0923 02:44:44.073782  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(small-deployment-241): Pods: 6 out of 6 created, 6 running (6 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I0923 02:44:44.095567  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(small-deployment-178): Pods: 3 out of 3 created, 3 running (3 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I0923 02:44:44.344490  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(small-deployment-247): Pods: 3 out of 3 created, 3 running (3 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I0923 02:44:44.353833  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(small-deployment-273): Pods: 6 out of 6 created, 6 running (6 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I0923 02:44:44.448049  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(small-deployment-276): Pods: 3 out of 3 created, 3 running (3 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I0923 02:44:44.606546  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(small-deployment-225): Pods: 6 out of 6 created, 6 running (6 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I0923 02:44:44.648085  100352 wait_for_controlled_pods.go:320] WaitForControlledPodsRunning: running 3, deleted 0, timeout: 0, failed: 0
I0923 02:44:44.648133  100352 wait_for_controlled_pods.go:325] WaitForControlledPodsRunning: maxDuration=5.007069097s, operationTimeout=15m0s, ratio=0.01
I0923 02:44:44.648156  100352 wait_for_controlled_pods.go:339] WaitForControlledPodsRunning: 3/3 Jobs are running with all pods
I0923 02:44:44.829204  100352 wait_for_controlled_pods.go:320] WaitForControlledPodsRunning: running 323, deleted 0, timeout: 0, failed: 0
I0923 02:44:44.829238  100352 wait_for_controlled_pods.go:325] WaitForControlledPodsRunning: maxDuration=5.01248511s, operationTimeout=15m0s, ratio=0.01
I0923 02:44:44.829255  100352 wait_for_controlled_pods.go:339] WaitForControlledPodsRunning: 323/323 Deployments are running with all pods
I0923 02:44:45.308942  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(daemonset-0): Pods: 95 out of 100 created, 90 running (72 updated), 5 pending scheduled, 0 not scheduled, 0 inactive, 5 terminating, 0 unknown, 0 runningButNotReady 
I0923 02:44:50.310946  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(daemonset-0): Pods: 96 out of 100 created, 92 running (92 updated), 4 pending scheduled, 0 not scheduled, 0 inactive, 4 terminating, 0 unknown, 0 runningButNotReady 
I0923 02:44:50.605395  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(medium-statefulset-0): Pods: 34 out of 34 created, 34 running (34 updated), 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady 
I0923 02:44:50.605477  100352 wait_for_controlled_pods.go:320] WaitForControlledPodsRunning: running 2, deleted 0, timeout: 0, failed: 0
I0923 02:44:50.605490  100352 wait_for_controlled_pods.go:325] WaitForControlledPodsRunning: maxDuration=20.005604503s, operationTimeout=15m0s, ratio=0.02
I0923 02:44:50.605505  100352 wait_for_controlled_pods.go:339] WaitForControlledPodsRunning: 2/2 StatefulSets are running with all pods
I0923 02:44:55.313595  100352 wait_for_pods.go:111] WaitForControlledPodsRunning: namespace(test-1g3gfm-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 
I0923 02:44:55.313683  100352 wait_for_controlled_pods.go:320] WaitForControlledPodsRunning: running 1, deleted 0, timeout: 0, failed: 0
I0923 02:44:55.313705  100352 wait_for_controlled_pods.go:325] WaitForControlledPodsRunning: maxDuration=30.112753578s, operationTimeout=15m0s, ratio=0.03
I0923 02:44:55.313725  100352 wait_for_controlled_pods.go:339] WaitForControlledPodsRunning: 1/1 DaemonSets are running with all pods
I0923 02:44:55.313747  100352 simple_test_executor.go:171] Step "[step: 22] Waiting for 'scale and update objects' to be completed" ended
I0923 02:44:55.313770  100352 simple_test_executor.go:149] Step "[step: 23] Starting measurement for 'delete objects'" started
I0923 02:44:55.313821  100352 wait_for_controlled_pods.go:213] WaitForControlledPodsRunning: wait for controlled pods measurement already running
I0923 02:44:55.313835  100352 wait_for_controlled_pods.go:213] WaitForControlledPodsRunning: wait for controlled pods measurement already running
... skipping 157 lines ...
I0923 02:46:29.391251  100352 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(medium-deployment-14): starting with timeout: 14m59.999971621s
I0923 02:46:29.942245  100352 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(small-deployment-28): starting with timeout: 14m59.999976266s
I0923 02:46:30.333542  100352 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(small-deployment-200): starting with timeout: 14m59.999987754s
I0923 02:46:30.986383  100352 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(medium-deployment-3): starting with timeout: 14m59.999974544s
I0923 02:46:30.994257  100352 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(small-deployment-0): starting with timeout: 14m59.999984608s
I0923 02:46:31.200190  100352 wait_for_pods.go:61] WaitForControlledPodsRunning: namespace(test-1g3gfm-1), controlledBy(small-deployment-177): starting with timeout: 14m59.999978302s
{"component":"entrypoint","file":"k8s.io/test-infra/prow/entrypoint/run.go:169","func":"k8s.io/test-infra/prow/entrypoint.Options.ExecuteProcess","level":"error","msg":"Entrypoint received interrupt: terminated","severity":"error","time":"2022-09-23T02:46:31Z"}
++ early_exit_handler
++ '[' -n 174 ']'
++ kill -TERM 174
++ cleanup_dind
++ [[ true == \t\r\u\e ]]
++ echo 'Cleaning up after docker'
... skipping 4 lines ...