Repository: kubernetes/kubernetes (language: go)

Issue:
[Flaking Test] integration-master (scheduler_perf tests)
### Which jobs are flaking?

master-blocking:
- integration-master

### Which tests are flaking?

`k8s.io/kubernetes/test/integration/scheduler_perf.scheduler_perf`

### Since when has it been flaking?

The only run that failed on master-blocking was: [5/17/2024, 9:22:18 AM](https://prow.k8s.io/view/gs/kubernetes-jenkins/logs/ci-kubernetes-integration-master/1791315518829891584)

But [Triage](https://storage.googleapis.com/k8s-triage/index.html?test=k8s.io%2Fkubernetes%2Ftest%2Fintegration%2Fscheduler_perf.scheduler_perf) shows this test to be failing across different jobs with an extremely high rate. 

### Testgrid link

https://testgrid.k8s.io/sig-release-master-blocking#integration-master

### Reason for failure (if possible)

The complete build log can be found here: https://storage.googleapis.com/kubernetes-jenkins/logs/ci-kubernetes-integration-master/1795650509529419776/build-log.txt

There are numerous errors, highlighting some of them:

```
E0529 03:48:46.793158  117977 controller.go:159] "Unhandled Error" err="unable to sync kubernetes service: Endpoints \"kubernetes\" is invalid: subsets[0].addresses[0].ip: Invalid value: \"127.0.0.1\": may not be in the loopback range (127.0.0.0/8, ::1/128)" logger="UnhandledError"
...
    schedule_one.go:1052: E0529 03:48:37.463675] Error scheduling pod; retrying err="waiting for resource driver" pod="test/test-drac5bhg"
...
E0529 03:09:54.849485   25438 reflector.go:158] "Unhandled Error" err="k8s.io/client-go/metadata/metadatainformer/informer.go:138: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: the server could not find the requested resource" logger="UnhandledError"
...
E0529 03:08:16.849871   25438 replica_set.go:560] "Unhandled Error" err="sync \"namespace-1716952096-8804/cassandra\" failed with replicationcontrollers \"cassandra\" not found" logger="UnhandledError"
...
E0529 03:07:37.755211   25438 replica_set.go:236] "Unhandled Error" err="ReplicaSet has no controller: &ReplicaSet{ObjectMeta:{frontend  namespace-1716952054-23531  228ae60e-495d-445c-955c-2b4280009709 3244 2 2024-05-29 03:07:36 +0000 UTC <nil> <nil> map[app:guestbook tier:frontend] map[] [] [] []},Spec:ReplicaSetSpec{Replicas:*2,Selector:&v1.LabelSelector{MatchLabels:map[string]string{app: guestbook,tier: frontend,},MatchExpressions:[]LabelSelectorRequirement{},},Template:{{      0 0001-01-01 00:00:00 +0000 UTC <nil> <nil> map[app:guestbook tier:frontend] map[] [] [] []} {[] [] [{php-redis gcr.io/google_samples/gb-frontend:v3 [] []  [{ 0 80 TCP }] [] [{GET_HOSTS_FROM dns nil}] {map[] map[cpu:{{100 -3} {<nil>} 100m DecimalSI} memory:{{104857600 0} {<nil>} 100Mi BinarySI}] []} [] <nil> [] [] nil nil nil nil /dev/termination-log File IfNotPresent nil false false false}] [] Always 0xc00442e218 <nil> ClusterFirst map[]   <nil>  false false false <nil> PodSecurityContext{SELinuxOptions:nil,RunAsUser:nil,RunAsNonRoot:nil,SupplementalGroups:[],FSGroup:nil,RunAsGroup:nil,Sysctls:[]Sysctl{},WindowsOptions:nil,FSGroupChangePolicy:nil,SeccompProfile:nil,AppArmorProfile:nil,} []   nil default-scheduler [] []  <nil> nil [] <nil> <nil> <nil> map[] [] <nil> nil <nil> [] []}},MinReadySeconds:0,},Status:ReplicaSetStatus{Replicas:3,FullyLabeledReplicas:3,ObservedGeneration:1,ReadyReplicas:0,AvailableReplicas:0,Conditions:[]ReplicaSetCondition{},},}" logger="UnhandledError"
```

### Anything else we need to know?

https://testgrid.k8s.io/sig-scalability-benchmarks#scheduler-perf is 🔴 

### Relevant SIG(s)

/sig scalability
@kubernetes/release-team-release-signal 


Discussion / hints:
This issue is currently awaiting triage.

If a SIG or subproject determines this is a relevant issue, they will accept it by applying the `triage/accepted` label and provide further guidance.

The `triage/accepted` label can be added by org members by writing `/triage accepted` in a comment.


<details>

Instructions for interacting with me using PR comments are available [here](https://git.k8s.io/community/contributors/guide/pull-requests.md).  If you have questions or suggestions related to my behavior, please file an issue against the [kubernetes-sigs/prow](https://github.com/kubernetes-sigs/prow/issues/new?title=Prow%20issue:) repository.
</details>
Hey All - hope you're well. Michael here from the Release Signal team.

Just wanted to touch base and make sure we're good to go for the cut on the 4th.

CC @wojtek-t

/sig-scalability
@sanposhiho can you take a look?
cc @gabesaba @macsko
/assign

to put in my todo, but it likely takes some time for me to start working on (I'm about to go on vacation.)
Someone feel free to take over meanwhile, if needed.

---

Do we know when it's started? (Testgrid shows limited number of results)
I had a brief look and found [the master blocking one](https://prow.k8s.io/view/gs/kubernetes-jenkins/logs/ci-kubernetes-integration-master/1791315518829891584) mentioned at the top failed at DRA's test case, which is relatively new one added in https://github.com/kubernetes/kubernetes/pull/123516.
cc @pohly 


```
=== FAIL: test/integration/scheduler_perf TestScheduling/SchedulingWithResourceClaimTemplateStructured/fast (unknown)
I0517 04:43:17.605033  117838 perf_utils.go:68] Making 1 nodes
I0517 04:43:17.612264  117838 perf_utils.go:68] Making 1 nodes
    dra.go:172: creating resource driver "test-driver.cdi.k8s.io" for nodes matching "scheduler-perf-dra-*"
I0517 04:43:17.657585  117838 controller.go:615] quota admission added evaluator for: resourceclaimparameters.resource.k8s.io
    scheduler_perf.go:1296: creating 0 pods in namespace "init"
    scheduler_perf.go:1320: scheduling succeed
    scheduler_perf.go:1296: creating 10 pods in namespace "test"
    scheduler_perf.go:1323: namespace: test, pods: want 10, got 0
    scheduler_perf.go:1323: namespace: test, pods: want 10, got 4
    scheduler_perf.go:1323: namespace: test, pods: want 10, got 4
    scheduler_perf.go:1323: namespace: test, pods: want 10, got 4
    scheduler_perf.go:1323: namespace: test, pods: want 10, got 4
    scheduler_perf.go:1323: namespace: test, pods: want 10, got 4
```

`want 10, got 4` goes until the end, which looks like the cause.

https://storage.googleapis.com/kubernetes-jenkins/logs/ci-kubernetes-integration-master/1791315518829891584/build-log.txt
I also checked two failures in ci-benchmark-scheduler-perf-master side, and all failures in those two were from DRA test cases.

```
=== Failed
=== FAIL: test/integration/scheduler_perf BenchmarkPerfScheduling/SchedulingWithResourceClaimTemplate/2000pods_100nodes (0.00s)
--- FAIL: BenchmarkPerfScheduling/SchedulingWithResourceClaimTemplate/2000pods_100nodes
BenchmarkPerfScheduling/SchedulingWithResourceClaimTemplate/2000pods_200nodes
    scheduler_perf.go:742: disabled by label filter "performance"

=== FAIL: test/integration/scheduler_perf BenchmarkPerfScheduling/SchedulingWithResourceClaimTemplate (0.00s)
--- FAIL: BenchmarkPerfScheduling/SchedulingWithResourceClaimTemplate
BenchmarkPerfScheduling/SchedulingWithMultipleResourceClaims
BenchmarkPerfScheduling/SchedulingWithMultipleResourceClaims/fast
    scheduler_perf.go:742: disabled by label filter "performance"

=== FAIL: test/integration/scheduler_perf BenchmarkPerfScheduling/SchedulingWithResourceClaimTemplateStructured/2000pods_100nodes (0.00s)
--- FAIL: BenchmarkPerfScheduling/SchedulingWithResourceClaimTemplateStructured/2000pods_100nodes
BenchmarkPerfScheduling/SchedulingWithResourceClaimTemplateStructured/2000pods_200nodes
    scheduler_perf.go:742: disabled by label filter "performance"

=== FAIL: test/integration/scheduler_perf BenchmarkPerfScheduling/SchedulingWithResourceClaimTemplateStructured (0.00s)
--- FAIL: BenchmarkPerfScheduling/SchedulingWithResourceClaimTemplateStructured
    scheduler_perf.go:681: full log output:

=== FAIL: test/integration/scheduler_perf BenchmarkPerfScheduling (0.00s)
--- FAIL: BenchmarkPerfScheduling
```

https://storage.googleapis.com/kubernetes-jenkins/logs/ci-benchmark-scheduler-perf-master/1797013157097508864/build-log.txt

```
=== FAIL: test/integration/scheduler_perf BenchmarkPerfScheduling/SchedulingWithResourceClaimTemplateStructured/2000pods_100nodes (0.00s)
--- FAIL: BenchmarkPerfScheduling/SchedulingWithResourceClaimTemplateStructured/2000pods_100nodes
BenchmarkPerfScheduling/SchedulingWithResourceClaimTemplateStructured/2000pods_200nodes
    scheduler_perf.go:742: disabled by label filter "performance"

=== FAIL: test/integration/scheduler_perf BenchmarkPerfScheduling/SchedulingWithResourceClaimTemplateStructured (0.00s)
--- FAIL: BenchmarkPerfScheduling/SchedulingWithResourceClaimTemplateStructured
    scheduler_perf.go:681: full log output:

=== FAIL: test/integration/scheduler_perf BenchmarkPerfScheduling (0.00s)
--- FAIL: BenchmarkPerfScheduling
```

https://storage.googleapis.com/kubernetes-jenkins/logs/ci-benchmark-scheduler-perf-master/1797657849061445632/build-log.txt
/assign

TestScheduling/SchedulingWithMultipleResourceClaims/fast only failed once in ci-kubernetes-integration-master, right? I can't reproduce that locally.

https://testgrid.k8s.io/sig-scalability-benchmarks#scheduler-perf is in a much worse state. There are context cancellation errors, which implies that tests are timing out. We don't have enough history in test grid anymore to verify when that started. I remember that performance got worse when queuing hints were disabled, but I think tests were still passing at that time.


/unassign @sanposhiho 
>  There are context cancellation errors, which implies that tests are timing out.

Whether is it timeout-ed by per-test timeout or timeout for all?
If the latter is true, probably we need to lengthen it as we added new test cases.
https://github.com/kubernetes/test-infra/blob/master/config/jobs/kubernetes/sig-scalability/sig-scalability-periodic-jobs.yaml#L746-L747
I can't reproduce failures in the benchmarks either.

I'm now doing performance comparisons to determine whether there has been a performance regression which could explain the timeouts.

> Whether is it timeout-ed by per-test timeout or timeout for all?

Most likely it is this per-test timeout: https://github.com/kubernetes/kubernetes/blob/ae5543e4c8f99cb1555102a8ebc310aed3c82596/test/integration/scheduler_perf/scheduler_perf.go#L759-L761
I'm not seeing a big drop between 1.30.0 and current master for `go test -timeout=0 -count=5 -run=xxxx -bench=BenchmarkPerfScheduling/.*ResourceClaim.* ./test/integration/scheduler_perf`:

```
name                                                                               old SchedulingThroughput/Average                             new SchedulingThroughput/Average                             delta
PerfScheduling/SchedulingWithResourceClaimTemplate/2000pods_100nodes-36                                                              9.85 ± 0%                                                    9.18 ± 0%   ~     (p=1.000 n=1+1)
PerfScheduling/SchedulingWithResourceClaimTemplateStructured/2000pods_100nodes-36                                                     137 ± 0%                                                     221 ± 0%   ~     (p=1.000 n=1+1)

name                                                                               old SchedulingThroughput/Perc50                              new SchedulingThroughput/Perc50                              delta
PerfScheduling/SchedulingWithResourceClaimTemplate/2000pods_100nodes-36                                                              2.64 ± 0%                                                    0.91 ± 0%   ~     (p=1.000 n=1+1)
PerfScheduling/SchedulingWithResourceClaimTemplateStructured/2000pods_100nodes-36                                                    76.0 ± 0%                                                   247.0 ± 0%   ~     (p=1.000 n=1+1)

name                                                                               old SchedulingThroughput/Perc90                              new SchedulingThroughput/Perc90                              delta
PerfScheduling/SchedulingWithResourceClaimTemplate/2000pods_100nodes-36                                                              16.0 ± 0%                                                    26.8 ± 0%   ~     (p=1.000 n=1+1)
PerfScheduling/SchedulingWithResourceClaimTemplateStructured/2000pods_100nodes-36                                                     276 ± 0%                                                     268 ± 0%   ~     (p=1.000 n=1+1)

name                                                                               old SchedulingThroughput/Perc95                              new SchedulingThroughput/Perc95                              delta
PerfScheduling/SchedulingWithResourceClaimTemplate/2000pods_100nodes-36                                                              48.3 ± 0%                                                    34.0 ± 0%   ~     (p=1.000 n=1+1)
PerfScheduling/SchedulingWithResourceClaimTemplateStructured/2000pods_100nodes-36                                                     276 ± 0%                                                     268 ± 0%   ~     (p=1.000 n=1+1)

name                                                                               old SchedulingThroughput/Perc99                              new SchedulingThroughput/Perc99                              delta
PerfScheduling/SchedulingWithResourceClaimTemplate/2000pods_100nodes-36                                                               112 ± 0%                                                      97 ± 0%   ~     (p=1.000 n=1+1)
PerfScheduling/SchedulingWithResourceClaimTemplateStructured/2000pods_100nodes-36                                                     276 ± 0%                                                     268 ± 0%   ~     (p=1.000 n=1+1)

name                                                                               old runtime_seconds                                          new runtime_seconds                                          delta
PerfScheduling/SchedulingWithResourceClaimTemplate/2000pods_100nodes-36                                                               111 ± 0%                                                     107 ± 0%   ~     (p=1.000 n=1+1)
PerfScheduling/SchedulingWithResourceClaimTemplateStructured/2000pods_100nodes-36                                                    15.0 ± 0%                                                     9.2 ± 0%   ~     (p=1.000 n=1+1)
```


As a first step, shall we make the per-test timeout longer?

https://github.com/kubernetes/kubernetes/pull/125313
A recent failure: https://prow.k8s.io/view/gs/kubernetes-jenkins/pr-logs/pull/125442/pull-kubernetes-integration/1800849705454800896
Hello! This Flake has not been updated for a long time, so I'd like to check what's the status. The code freeze is starting 02:00 UTC Wednesday 10th July 2024 (about 4 weeks from now), and while there is still plenty of time, we want to ensure that each PR has a chance to be merged on time.

As this is tagged for 1.31, is it still planned for this release?
Yes, it's under investigation.

/milestone v1.31
I've added more logging to track down this problem in https://github.com/kubernetes/kubernetes/pull/125313 and also included several other changes there in the hope that they might help, like https://github.com/kubernetes/kubernetes/pull/124595.

The underlying problem is that the following happens:
- pod gets created
- the PreEnqueue check fails for it because the claim for it has not been created yet (it's using a template)
- the claim controller creates the claim and stores its name in the pod status
- the scheduler detects an "Update event" for the pod, but PreEnqueue fails again because the claim has not been received yet
- the claim add event is received and processed, but does not trigger another scheduling attempt

My theory is that the two events (pod modified and claim added) are getting processed so close together that they conflict somehow. Is that plausible?

cc @sanposhiho @kerthcet @alculquicondor 

The "Update event" calls `sched.SchedulingQueue.Update`. The claim event calls `sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue` (from eventhandlers.go).

An example log is https://storage.googleapis.com/kubernetes-jenkins/pr-logs/pull/125313/pull-kubernetes-scheduler-perf/1802029260588716032/build-log.txt.

Grep first for "at least" to get the pod name. Then grep for that pod and the claim created for it. Here the result with annotations:


```
$ grep -e test-drav6c2h-resource-64bqw -e test-drav6c2h build-log.txt 
    graph_builder.go:692: I0615 17:27:27.836960] GraphBuilder process object apiVersion="v1" kind="Pod" object="init/test-drav6c2h" uid="d357b876-caad-4d2f-936e-234ce26e0df9" eventType="add" virtual=    <bool>: false
    eventhandlers.go:129: I0615 17:27:27.881737] Add event for unscheduled pod pod="init/test-drav6c2h"
I0615 17:27:27.881762   27173 dynamicresources.go:471] "pod unschedulable" reason="pod \"init/test-drav6c2h\": ResourceClaim not created yet"
I0615 17:27:27.881779   27173 scheduling_queue.go:539] "Status after running PreEnqueue plugin" pod="init/test-drav6c2h" plugin="DynamicResources" status="pod \"init/test-drav6c2h\": ResourceClaim not created yet"
    controller.go:557: I0615 17:27:30.532358] checking pod="init/test-drav6c2h" podClaim="resource"
    controller.go:660: I0615 17:27:30.536442] Created ResourceClaim podClaim="resource" claim="init/test-drav6c2h-resource-64bqw" pod="init/test-drav6c2h"
I0615 17:27:30.537233   27173 queueset.go:685] QS(exempt) at t=2024-06-15 17:27:30.537212755 R=0.00000000ss: immediate dispatch of request "exempt" &request.RequestInfo{IsResourceRequest:true, Path:"/api/v1/namespaces/init/pods/test-drav6c2h/status", Verb:"patch", APIPrefix:"api", APIGroup:"", APIVersion:"v1", Namespace:"init", Resource:"pods", Subresource:"status", Name:"test-drav6c2h", Parts:[]string{"pods", "test-drav6c2h", "status"}} &user.DefaultInfo{Name:"system:apiserver", UID:"27569865-7db1-4c38-807f-d4c578f5e3b1", Groups:[]string{"system:masters"}, Extra:map[string][]string(nil)}, qs will have 4 executing
I0615 17:27:30.537304   27173 queueset.go:417] QS(exempt): Dispatching request &request.RequestInfo{IsResourceRequest:true, Path:"/api/v1/namespaces/init/pods/test-drav6c2h/status", Verb:"patch", APIPrefix:"api", APIGroup:"", APIVersion:"v1", Namespace:"init", Resource:"pods", Subresource:"status", Name:"test-drav6c2h", Parts:[]string{"pods", "test-drav6c2h", "status"}} &user.DefaultInfo{Name:"system:apiserver", UID:"27569865-7db1-4c38-807f-d4c578f5e3b1", Groups:[]string{"system:masters"}, Extra:map[string][]string(nil)} from its queue
I0615 17:27:30.537360   27173 handler.go:153] kube-aggregator: PATCH "/api/v1/namespaces/init/pods/test-drav6c2h/status" satisfied by nonGoRestful
I0615 17:27:30.537373   27173 pathrecorder.go:250] kube-aggregator: "/api/v1/namespaces/init/pods/test-drav6c2h/status" satisfied by prefix /api/
I0615 17:27:30.537385   27173 handler.go:143] kube-apiserver: PATCH "/api/v1/namespaces/init/pods/test-drav6c2h/status" satisfied by gorestful with webservice /api/v1
I0615 17:27:30.540922   27173 httplog.go:132] "HTTP" verb="APPLY" URI="/api/v1/namespaces/init/pods/test-drav6c2h/status?fieldManager=ResourceClaimController&force=true" latency="3.805799ms" userAgent="scheduler_perf.test/v0.0.0 (linux/amd64) kubernetes/$Format -- BenchmarkPerfScheduling/SchedulingWithResourceClaimTemplate/2000pods_100nodes" audit-ID="37a9993b-9a9a-4993-a5dc-e5b4a3996333" srcIP="127.0.0.1:54668" apf_pl="exempt" apf_fs="exempt" apf_iseats=1 apf_fseats=0 apf_additionalLatency="0s" apf_execution_time="3.549725ms" resp=200
    controller.go:509: I0615 17:27:30.544364] nothing to do for pod, scheduler will deal with it pod="init/test-drav6c2h"
    graph_builder.go:692: I0615 17:27:30.547483] GraphBuilder process object apiVersion="resource.k8s.io/v1alpha2" kind="ResourceClaim" object="init/test-drav6c2h-resource-64bqw" uid="00e8d3f5-21fb-49fc-8649-1fa3b1c609b7" eventType="add" virtual=    <bool>: false
    graph_builder.go:692: I0615 17:27:30.547625] GraphBuilder process object apiVersion="v1" kind="Pod" object="init/test-drav6c2h" uid="d357b876-caad-4d2f-936e-234ce26e0df9" eventType="update" virtual=    <bool>: false
    controller.go:304: I0615 17:27:30.547927] test-driver.cdi.k8s.io/resource controller: Adding new work item key="claim:init/test-drav6c2h-resource-64bqw"

# pod update event:


    eventhandlers.go:152: I0615 17:27:30.579422] Update event for unscheduled pod pod="init/test-drav6c2h"
I0615 17:27:30.579778   27173 dynamicresources.go:471] "pod unschedulable" reason="could not find ResourceClaim \"init/test-drav6c2h-resource-64bqw\""
I0615 17:27:30.579802   27173 scheduling_queue.go:539] "Status after running PreEnqueue plugin" pod="init/test-drav6c2h" plugin="DynamicResources" status="could not find ResourceClaim \"init/test-drav6c2h-resource-64bqw\""

# Now the claim add (verbose because I am do a quick-and-dirty dump of the `obj interface{}`):

    assume_cache.go:222: I0615 17:27:30.582817] AssumeCache add event obj="&ResourceClaim{ObjectMeta:{test-drav6c2h-resource-64bqw test-drav6c2h-resource- init  00e8d3f5-21fb-49fc-8649-1fa3b1c609b7 3751 0 2024-06-15 17:27:30 +0000 UTC <nil> <nil> map[] map[resource.kubernetes.io/pod-claim-name:resource] [{v1 Pod test-drav6c2h d357b876-caad-4d2f-936e-234ce26e0df9 0xc0126b842e 0xc0126b842f}] [] [{scheduler_perf.test Update resource.k8s.io/v1alpha2 2024-06-15 17:27:30 +0000 UTC FieldsV1 {\"f:metadata\":{\"f:annotations\":{\".\":{},\"f:resource.kubernetes.io/pod-claim-name\":{}},\"f:generateName\":{},\"f:ownerReferences\":{\".\":{},\"k:{\\\"uid\\\":\\\"d357b876-caad-4d2f-936e-234ce26e0df9\\\"}\":{}}},\"f:spec\":{\"f:allocationMode\":{},\"f:resourceClassName\":{}}} }]},Spec:ResourceClaimSpec{ResourceClassName:test-class,ParametersRef:nil,AllocationMode:WaitForFirstConsumer,},Status:ResourceClaimStatus{DriverName:,Allocation:nil,ReservedFor:[]ResourceClaimConsumerReference{},DeallocationRequested:false,},}"
    assume_cache.go:261: I0615 17:27:30.582900] Adding object to assume cache description="ResourceClaim" cacheKey="init/test-drav6c2h-resource-64bqw" assumeCache="&ResourceClaim{ObjectMeta:{test-drav6c2h-resource-64bqw test-drav6c2h-resource- init  00e8d3f5-21fb-49fc-8649-1fa3b1c609b7 3751 0 2024-06-15 17:27:30 +0000 UTC <nil> <nil> map[] map[resource.kubernetes.io/pod-claim-name:resource] [{v1 Pod test-drav6c2h d357b876-caad-4d2f-936e-234ce26e0df9 0xc0126b842e 0xc0126b842f}] [] [{scheduler_perf.test Update resource.k8s.io/v1alpha2 2024-06-15 17:27:30 +0000 UTC FieldsV1 {\"f:metadata\":{\"f:annotations\":{\".\":{},\"f:resource.kubernetes.io/pod-claim-name\":{}},\"f:generateName\":{},\"f:ownerReferences\":{\".\":{},\"k:{\\\"uid\\\":\\\"d357b876-caad-4d2f-936e-234ce26e0df9\\\"}\":{}}},\"f:spec\":{\"f:allocationMode\":{},\"f:resourceClassName\":{}}} }]},Spec:ResourceClaimSpec{ResourceClassName:test-class,ParametersRef:nil,AllocationMode:WaitForFirstConsumer,},Status:ResourceClaimStatus{DriverName:,Allocation:nil,ReservedFor:[]ResourceClaimConsumerReference{},DeallocationRequested:false,},}"
    eventhandlers.go:468: I0615 17:27:30.582982] Add ResourceClaim claim="&ResourceClaim{ObjectMeta:{test-drav6c2h-resource-64bqw test-drav6c2h-resource- init  00e8d3f5-21fb-49fc-8649-1fa3b1c609b7 3751 0 2024-06-15 17:27:30 +0000 UTC <nil> <nil> map[] map[resource.kubernetes.io/pod-claim-name:resource] [{v1 Pod test-drav6c2h d357b876-caad-4d2f-936e-234ce26e0df9 0xc0126b842e 0xc0126b842f}] [] [{scheduler_perf.test Update resource.k8s.io/v1alpha2 2024-06-15 17:27:30 +0000 UTC FieldsV1 {\"f:metadata\":{\"f:annotations\":{\".\":{},\"f:resource.kubernetes.io/pod-claim-name\":{}},\"f:generateName\":{},\"f:ownerReferences\":{\".\":{},\"k:{\\\"uid\\\":\\\"d357b876-caad-4d2f-936e-234ce26e0df9\\\"}\":{}}},\"f:spec\":{\"f:allocationMode\":{},\"f:resourceClassName\":{}}} }]},Spec:ResourceClaimSpec{ResourceClassName:test-class,ParametersRef:nil,AllocationMode:WaitForFirstConsumer,},Status:ResourceClaimStatus{DriverName:,Allocation:nil,ReservedFor:[]ResourceClaimConsumerReference{},DeallocationRequested:false,},}"

# And here's nothing from `sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue` - shouldn't the event move the pod to the schedulable queue?

# The driver sees the claim, too, but waits for the scheduler:

    controller.go:375: I0615 17:27:31.604631] test-driver.cdi.k8s.io/resource controller: processing key="claim:init/test-drav6c2h-resource-64bqw"
    controller.go:519: I0615 17:27:31.604675] test-driver.cdi.k8s.io/resource controller: ResourceClaim waiting for first consumer key="claim:init/test-drav6c2h-resource-64bqw"
    controller.go:379: I0615 17:27:31.604707] test-driver.cdi.k8s.io/resource controller: completed key="claim:init/test-drav6c2h-resource-64bqw"

# claim controller again (yes, choosing `controller.go` as filename is bad):

    controller.go:841: I0615 17:27:33.042872] claim reserved for counts currentCount=    <int>: 0 claim="init/test-drav6c2h-resource-64bqw" updatedCount=    <int>: 0 builtinController=    <bool>: false

# This is much later.

    scheduler_perf.go:1017: FATAL ERROR: op 5: error in waiting for pods to get scheduled: at least pod init/test-drav6c2h is not scheduled: context deadline exceeded
```

Any idea what to look at next?

I looked for reasons why `movePodsToActiveOrBackoffQueue` (called by `MoveAllToActiveOrBackoffQueue`) might not do anything for the pod without logging about it. I found `if pInfo.Gated { return }` and added some log output to it. Indeed, that path is taken:
```
    eventhandlers.go:152: I0615 18:41:28.262070] Update event for unscheduled pod pod="init/test-draz7bhb"
    scheduling_queue.go:1208: I0615 18:41:28.270453] Pod is gated pod="init/test-draz7bhb" event="ResourceClaimAdd"
I0615 18:41:28.270698   27173 dynamicresources.go:471] "pod unschedulable" reason="could not find ResourceClaim \"init/test-draz7bhb-resource-ws74z\""
I0615 18:41:28.270730   27173 scheduling_queue.go:539] "Status after running PreEnqueue plugin" pod="init/test-draz7bhb" plugin="DynamicResources" status="could not find Res
ourceClaim \"init/test-draz7bhb-resource-ws74z\""
...
    assume_cache.go:222: I0615 18:41:28.850230] AssumeCache add event obj="&ResourceClaim{ObjectMeta:{test-draz7bhb-resource-ws74z test-draz7bhb-resource- init  7200ea85-4c5d-4ddd-94e9-63e0e5af22cf 3002 0 2024-06-15 18:41:08 +0000 UTC <nil> <nil> map[] map[resource.kubernetes.io/pod-claim-name:resource] [{v1 Pod test-draz7bhb ba015eaf-db8a-4550-913e-811d8e106af9 0xc003d3994e 0xc003d3994f}] [] [{scheduler_perf.test Update resource.k8s.io/v1alpha2 2024-06-15 18:41:08 +0000 UTC FieldsV1 {\"f:metadata\":{\"f:annotations\":{\".\":{},\"f:resource.kubernetes.io/pod-claim-name\":{}},\"f:generateName\":{},\"f:ownerReferences\":{\".\":{},\"k:{\\\"uid\\\":\\\"ba015eaf-db8a-4550-913e-811d8e106af9\\\"}\":{}}},\"f:spec\":{\"f:allocationMode\":{},\"f:resourceClassName\":{}}} }]},Spec:ResourceClaimSpec{ResourceClassName:test-class,ParametersRef:nil,AllocationMode:WaitForFirstConsumer,},Status:ResourceClaimStatus{DriverName:,Allocation:nil,ReservedFor:[]ResourceClaimConsumerReference{},DeallocationRequested:false,},}"
    assume_cache.go:261: I0615 18:41:28.850735] Adding object to assume cache description="ResourceClaim" cacheKey="init/test-draz7bhb-resource-ws74z" assumeCache="&ResourceClaim{ObjectMeta:{test-draz7bhb-resource-ws74z test-draz7bhb-resource- init  7200ea85-4c5d-4ddd-94e9-63e0e5af22cf 3002 0 2024-06-15 18:41:08 +0000 UTC <nil> <nil> map[] map[resource.kubernetes.io/pod-claim-name:resource] [{v1 Pod test-draz7bhb ba015eaf-db8a-4550-913e-811d8e106af9 0xc003d3994e 0xc003d3994f}] [] [{scheduler_perf.test Update resource.k8s.io/v1alpha2 2024-06-15 18:41:08 +0000 UTC FieldsV1 {\"f:metadata\":{\"f:annotations\":{\".\":{},\"f:resource.kubernetes.io/pod-claim-name\":{}},\"f:generateName\":{},\"f:ownerReferences\":{\".\":{},\"k:{\\\"uid\\\":\\\"ba015eaf-db8a-4550-913e-811d8e106af9\\\"}\":{}}},\"f:spec\":{\"f:allocationMode\":{},\"f:resourceClassName\":{}}} }]},Spec:ResourceClaimSpec{ResourceClassName:test-class,ParametersRef:nil,AllocationMode:WaitForFirstConsumer,},Status:ResourceClaimStatus{DriverName:,Allocation:nil,ReservedFor:[]ResourceClaimConsumerReference{},DeallocationRequested:false,},}"
    eventhandlers.go:468: I0615 18:41:28.850990] Add ResourceClaim claim="&ResourceClaim{ObjectMeta:{test-draz7bhb-resource-ws74z test-draz7bhb-resource- init  7200ea85-4c5d-4ddd-94e9-63e0e5af22cf 3002 0 2024-06-15 18:41:08 +0000 UTC <nil> <nil> map[] map[resource.kubernetes.io/pod-claim-name:resource] [{v1 Pod test-draz7bhb ba015eaf-db8a-4550-913e-811d8e106af9 0xc003d3994e 0xc003d3994f}] [] [{scheduler_perf.test Update resource.k8s.io/v1alpha2 2024-06-15 18:41:08 +0000 UTC FieldsV1 {\"f:metadata\":{\"f:annotations\":{\".\":{},\"f:resource.kubernetes.io/pod-claim-name\":{}},\"f:generateName\":{},\"f:ownerReferences\":{\".\":{},\"k:{\\\"uid\\\":\\\"ba015eaf-db8a-4550-913e-811d8e106af9\\\"}\":{}}},\"f:spec\":{\"f:allocationMode\":{},\"f:resourceClassName\":{}}} }]},Spec:ResourceClaimSpec{ResourceClassName:test-class,ParametersRef:nil,AllocationMode:WaitForFirstConsumer,},Status:ResourceClaimStatus{DriverName:,Allocation:nil,ReservedFor:[]ResourceClaimConsumerReference{},DeallocationRequested:false,},}"
            } newObj="&ResourceClaim{ObjectMeta:{test-draz7bhb-resource-ws74z test-draz7bhb-resource- init  7200ea85-4c5d-4ddd-94e9-63e0e5af22cf 3002 0 2024-06-15 18:41:08 +0000 UTC <nil> <nil> map[] map[resource.kubernetes.io/pod-claim-name:resource] [{v1 Pod test-draz7bhb ba015eaf-db8a-4550-913e-811d8e106af9 0xc003d3994e 0xc003d3994f}] [] [{scheduler_perf.test Update resource.k8s.io/v1alpha2 2024-06-15 18:41:08 +0000 UTC FieldsV1 {\"f:metadata\":{\"f:annotations\":{\".\":{},\"f:resource.kubernetes.io/pod-claim-name\":{}},\"f:generateName\":{},\"f:ownerReferences\":{\".\":{},\"k:{\\\"uid\\\":\\\"ba015eaf-db8a-4550-913e-811d8e106af9\\\"}\":{}}},\"f:spec\":{\"f:allocationMode\":{},\"f:resourceClassName\":{}}} }]},Spec:ResourceClaimSpec{ResourceClassName:test-class,ParametersRef:nil,AllocationMode:WaitForFirstConsumer,},Status:ResourceClaimStatus{DriverName:,Allocation:nil,ReservedFor:[]ResourceClaimConsumerReference{},DeallocationRequested:false,},}" pods=["<KObjSlice needs a slice of values implementing KMetadata, got type *framework.QueuedPodInfo>"]
    scheduling_queue.go:1208: I0615 18:41:28.856498] Pod is gated pod="init/test-draz7bhb" event="ResourceClaimAdd"
```

What does it mean that the pod is gated? The docs say "Whether the Pod is scheduling gated (by PreEnqueuePlugins) or not.".

Okay, so that means that `PreEnqueue` returned false:
```
pInfo.Gated = !p.runPreEnqueuePlugins(context.Background(), pInfo)
```

But isn't the event exactly what may have changed the outcome of `PreEnqueue`? If it gets ignored, nothing else is going to wake up that pod.

I don't understand the logic behind this:

https://github.com/kubernetes/kubernetes/blob/c3689b9f8b8c1a1ac2bbc4e3b3cda28d83849ec2/pkg/scheduler/internal/queue/scheduling_queue.go#L1196-L1200

Incidentally, this was added [two months ago](https://github.com/kubernetes/kubernetes/pull/124618). This could be the recent change which caused this breakage.

/assign @gabesaba 
Removing this if check made `pull-kubernetes-scheduler-perf` work again for one test case in my trials.

Let's try the revert with master: https://github.com/kubernetes/kubernetes/issues/125223





Fix patch:
diff --git a/pkg/scheduler/internal/queue/scheduling_queue.go b/pkg/scheduler/internal/queue/scheduling_queue.go
index 292e72916f6a9..9f6a592eccf52 100644
--- a/pkg/scheduler/internal/queue/scheduling_queue.go
+++ b/pkg/scheduler/internal/queue/scheduling_queue.go
@@ -47,6 +47,7 @@ import (
 	"k8s.io/kubernetes/pkg/features"
 	"k8s.io/kubernetes/pkg/scheduler/framework"
 	"k8s.io/kubernetes/pkg/scheduler/framework/plugins/interpodaffinity"
+	"k8s.io/kubernetes/pkg/scheduler/framework/plugins/names"
 	"k8s.io/kubernetes/pkg/scheduler/internal/heap"
 	"k8s.io/kubernetes/pkg/scheduler/metrics"
 	"k8s.io/kubernetes/pkg/scheduler/util"
@@ -1193,11 +1194,25 @@ func (p *PriorityQueue) movePodsToActiveOrBackoffQueue(logger klog.Logger, podIn
 
 	activated := false
 	for _, pInfo := range podInfoList {
-		// Since there may be many gated pods and they will not move from the
-		// unschedulable pool, we skip calling the expensive isPodWorthRequeueing.
-		if pInfo.Gated {
+		// When handling events takes time, a scheduling throughput gets impacted negatively
+		// because of a shared lock within PriorityQueue, which Pop() also requires.
+		//
+		// Scheduling-gated Pods never get schedulable with any events,
+		// except the Pods themselves got updated, which isn't handled by movePodsToActiveOrBackoffQueue.
+		// So, we can skip them early here so that they don't go through isPodWorthRequeuing,
+		// which isn't fast enough to keep a sufficient scheduling throughput
+		// when the number of scheduling-gated Pods in unschedulablePods is large.
+		// https://github.com/kubernetes/kubernetes/issues/124384
+		// This is a hotfix for this issue, which might be changed
+		// once we have a better general solution for the shared lock issue.
+		//
+		// Note that we cannot skip all pInfo.Gated Pods here
+		// because PreEnqueue plugins apart from the scheduling gate plugin may change the gating status
+		// with these events.
+		if pInfo.Gated && pInfo.UnschedulablePlugins.Has(names.SchedulingGates) {
 			continue
 		}
+
 		schedulingHint := p.isPodWorthRequeuing(logger, pInfo, event, oldObj, newObj)
 		if schedulingHint == queueSkip {
 			// QueueingHintFn determined that this Pod isn't worth putting to activeQ or backoffQ by this event.


Test patch:
diff --git a/pkg/scheduler/internal/queue/scheduling_queue_test.go b/pkg/scheduler/internal/queue/scheduling_queue_test.go
index c2ad3d8ce675e..b74d197d6b55c 100644
--- a/pkg/scheduler/internal/queue/scheduling_queue_test.go
+++ b/pkg/scheduler/internal/queue/scheduling_queue_test.go
@@ -44,6 +44,7 @@ import (
 	"k8s.io/kubernetes/pkg/features"
 	"k8s.io/kubernetes/pkg/scheduler/framework"
 	plfeature "k8s.io/kubernetes/pkg/scheduler/framework/plugins/feature"
+	"k8s.io/kubernetes/pkg/scheduler/framework/plugins/names"
 	"k8s.io/kubernetes/pkg/scheduler/framework/plugins/queuesort"
 	"k8s.io/kubernetes/pkg/scheduler/framework/plugins/schedulinggates"
 	"k8s.io/kubernetes/pkg/scheduler/metrics"
@@ -1499,13 +1500,19 @@ func TestPriorityQueue_MoveAllToActiveOrBackoffQueueWithQueueingHint(t *testing.
 			expectedQ: unschedulablePods,
 		},
 		{
-			name:    "QueueHintFunction is not called when Pod is gated",
-			podInfo: setQueuedPodInfoGated(&framework.QueuedPodInfo{PodInfo: mustNewPodInfo(p), UnschedulablePlugins: sets.New("foo")}),
+			name:    "QueueHintFunction is not called when Pod is gated by SchedulingGates plugin",
+			podInfo: setQueuedPodInfoGated(&framework.QueuedPodInfo{PodInfo: mustNewPodInfo(p), UnschedulablePlugins: sets.New(names.SchedulingGates, "foo")}),
 			hint: func(logger klog.Logger, pod *v1.Pod, oldObj, newObj interface{}) (framework.QueueingHint, error) {
 				return framework.Queue, fmt.Errorf("QueueingHintFn should not be called as pod is gated")
 			},
 			expectedQ: unschedulablePods,
 		},
+		{
+			name:      "QueueHintFunction is called when Pod is gated by a plugin other than SchedulingGates",
+			podInfo:   setQueuedPodInfoGated(&framework.QueuedPodInfo{PodInfo: mustNewPodInfo(p), UnschedulablePlugins: sets.New("foo")}),
+			hint:      queueHintReturnQueue,
+			expectedQ: activeQ,
+		},
 	}
 
 	for _, test := range tests {
@@ -1518,14 +1525,13 @@ func TestPriorityQueue_MoveAllToActiveOrBackoffQueueWithQueueingHint(t *testing.
 					QueueingHintFn: test.hint,
 				},
 			}
-			test.podInfo.UnschedulablePlugins = sets.New("foo")
 			cl := testingclock.NewFakeClock(now)
 			q := NewTestQueue(ctx, newDefaultQueueSort(), WithQueueingHintMapPerProfile(m), WithClock(cl))
-			// add to unsched pod pool
 			q.activeQ.Add(q.newQueuedPodInfo(test.podInfo.Pod))
 			if p, err := q.Pop(logger); err != nil || p.Pod != test.podInfo.Pod {
 				t.Errorf("Expected: %v after Pop, but got: %v", test.podInfo.Pod.Name, p.Pod.Name)
 			}
+			// add to unsched pod pool
 			err := q.AddUnschedulableIfNotPresent(logger, test.podInfo, q.SchedulingCycle())
 			if err != nil {
 				t.Fatalf("unexpected error from AddUnschedulableIfNotPresent: %v", err)
diff --git a/test/integration/scheduler/plugins/plugins_test.go b/test/integration/scheduler/plugins/plugins_test.go
index 7f2c3d53fc0ba..ce0a5a87b1860 100644
--- a/test/integration/scheduler/plugins/plugins_test.go
+++ b/test/integration/scheduler/plugins/plugins_test.go
@@ -2651,8 +2651,8 @@ func (pl *SchedulingGatesPluginWOEvents) EventsToRegister() []framework.ClusterE
 	return nil
 }
 
-// This test helps to verify registering nil events for schedulingGates plugin works as expected.
-func TestSchedulingGatesPluginEventsToRegister(t *testing.T) {
+// This test helps to verify registering nil events for PreEnqueue plugin works as expected.
+func TestPreEnqueuePluginEventsToRegister(t *testing.T) {
 	testContext := testutils.InitTestAPIServer(t, "preenqueue-plugin", nil)
 
 	num := func(pl framework.Plugin) int {
@@ -2668,8 +2668,9 @@ func TestSchedulingGatesPluginEventsToRegister(t *testing.T) {
 	}
 
 	tests := []struct {
-		name              string
-		withEvents        bool
+		name       string
+		withEvents bool
+		// count is the expected number of calls to PreEnqueue().
 		count             int
 		queueHintEnabled  []bool
 		expectedScheduled []bool
@@ -2686,7 +2687,7 @@ func TestSchedulingGatesPluginEventsToRegister(t *testing.T) {
 		{
 			name:              "preEnqueue plugin with event registered",
 			withEvents:        true,
-			count:             2,
+			count:             3,
 			queueHintEnabled:  []bool{false, true},
 			expectedScheduled: []bool{true, true},
 		},
@@ -2700,7 +2701,7 @@ func TestSchedulingGatesPluginEventsToRegister(t *testing.T) {
 			t.Run(tt.name+fmt.Sprintf(" queueHint(%v)", queueHintEnabled), func(t *testing.T) {
 				featuregatetesting.SetFeatureGateDuringTest(t, utilfeature.DefaultFeatureGate, features.SchedulerQueueingHints, queueHintEnabled)
 
-				// new plugin every time to clear counts
+				// use new plugin every time to clear counts
 				var plugin framework.PreEnqueuePlugin
 				if tt.withEvents {
 					plugin = &SchedulingGatesPluginWithEvents{SchedulingGates: schedulinggates.SchedulingGates{}}