Log scheduling queue movement events #111878

yuanchen8911 · 2022-08-17T01:02:55Z

What type of PR is this?

/kind cleanup

What this PR does / why we need it:

Add additional scheduling events for pod movement to an internal scheduling queue to facilitate scheduling troubleshooting.

Added to active queue
Moved from active queue to unschedulable queue
Moved from active queue to backoff queue
Moved from unschedulable queue to active queue
Moved from unschedulable queue to backoff queue
Moved from backoff queue to active queue.

Some events are mutually exclusive and won't appear in the same scheduling cycle.

Below is an example for a failed scheduling with 3 new queue events. There's a single event Add to active queue for a successful pod scheduling.

I0817 00:53:01.018280 1495316 scheduling_queue.go:274] "Pod moved to an internal scheduling queue" pod="yuan/pod-143-c95674667-h6t7b" event="PodAdd"  queue="ActiveQueue"
I0817 00:54:30.877590 1495316 scheduling_queue.go:388] "Pod moved to an internal scheduling queue" pod="yuan/pod-143-c95674667-h6t7b" event="ScheduleAttemptFailure"  queue ="UnschedulablePods"
I0817 00:54:33.456604 1495316 scheduling_queue.go:597] "Pod moved to an internal scheduling queue" pod="yuan/pod-143-c95674667-h6t7b" event="NodeLabelChange" queue="BackoffQueue"

Which issue(s) this PR fixes:

Fixes #

Special notes for your reviewer:

Does this PR introduce a user-facing change?

NONE

Additional documentation e.g., KEPs (Kubernetes Enhancement Proposals), usage docs, etc.:

k8s-ci-robot · 2022-08-17T01:02:59Z

Please note that we're already in Test Freeze for the release-1.25 branch. This means every merged PR will be automatically fast-forwarded via the periodic ci-fast-forward job to the release branch of the upcoming v1.25.0 release.

Fast forwards are scheduled to happen every 6 hours, whereas the most recent run was: Tue Aug 16 19:37:32 UTC 2022.

k8s-ci-robot · 2022-08-17T01:03:03Z

@yuanchen8911: 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.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

yuanchen8911 · 2022-08-17T01:03:30Z

/sig scheduling

yuanchen8911 · 2022-08-17T01:03:46Z

/assign @Huang-Wei

yuanchen8911 · 2022-08-17T02:11:11Z

/retest

yuanchen8911 · 2022-08-17T02:54:13Z

/retest

pkg/scheduler/internal/queue/scheduling_queue.go

Huang-Wei · 2022-08-23T17:16:23Z

pkg/scheduler/internal/queue/scheduling_queue.go

@@ -313,6 +318,7 @@ func (p *PriorityQueue) Add(pod *v1.Pod) error {
 	if err := p.podBackoffQ.Delete(pInfo); err == nil {
 		klog.ErrorS(nil, "Error: pod is already in the podBackoff queue", "pod", klog.KObj(pod))
 	}
+	klog.V(5).InfoS("Pod moved", "pod", klog.KObj(pod), "event", PodAdd, "from", "", "to", activeQName)


nit: maybe specify it's "from" New (or Incoming)

Changed it New

yuanchen8911 · 2022-08-23T22:09:47Z

/retest

Huang-Wei · 2022-08-23T23:51:07Z

pkg/scheduler/internal/queue/scheduling_queue.go

@@ -558,6 +567,7 @@ func (p *PriorityQueue) Update(oldPod, newPod *v1.Pod) error {
 					return err
 				}
 				p.unschedulablePods.delete(usPodInfo.Pod)
+				klog.V(5).InfoS("Pod moved", "pod", klog.KObj(pInfo.Pod), "event", "PodUpdated", "from", unschedulablePods, "to", activeQName)


(not related to this line)

Add logging below L564? unschedulable -> backoff

Added additional logging unschedulePods to backoff.

Huang-Wei · 2022-08-24T18:11:57Z

/lgtm
/approve

This PR tries to reveal more details about pods moving among internal queues, which is helpful to debug issues that pods may stay in unschedulablePods for a long time.

/hold
for a while in case other folks have concerns.
cc @ahg-g @alculquicondor

Huang-Wei · 2022-08-24T22:50:12Z

pkg/scheduler/internal/queue/scheduling_queue.go

@@ -313,6 +318,7 @@ func (p *PriorityQueue) Add(pod *v1.Pod) error {
 	if err := p.podBackoffQ.Delete(pInfo); err == nil {
 		klog.ErrorS(nil, "Error: pod is already in the podBackoff queue", "pod", klog.KObj(pod))
 	}
+	klog.V(5).InfoS("Pod moved between internal queues", "pod", klog.KObj(pod), "event", PodAdd, "to", activeQName)


how about:

Suggested change

klog.V(5).InfoS("Pod moved between internal queues", "pod", klog.KObj(pod), "event", PodAdd, "to", activeQName)

klog.V(5).InfoS("Pod moved to an internal queue", "pod", klog.KObj(pod), "event", PodAdd, "queue", activeQName)

Changed to Pod moved to an internal scheduling queue.

changed to to queue.

pkg/scheduler/internal/queue/2

pkg/scheduler/internal/queue/scheduling_queue.go

Fix a typo Address comments Log one more queue event Update pkg/scheduler/internal/queue/scheduling_queue.go Co-authored-by: Aldo Culquicondor <1299064+alculquicondor@users.noreply.github.com> Update pkg/scheduler/internal/queue/scheduling_queue.go Co-authored-by: Aldo Culquicondor <1299064+alculquicondor@users.noreply.github.com> Address comments Remove 'source' from scheudling queue events Update scheduling queue event msg. Update scheduling queue events

yuanchen8911 · 2022-08-24T23:50:33Z

Updated the PR description based on the discussion and changes.

Huang-Wei · 2022-08-25T00:01:14Z

/lgtm

alculquicondor

/lgtm

alculquicondor · 2022-08-25T13:16:03Z

/approve
/hold cancel

k8s-ci-robot · 2022-08-25T13:16:47Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: alculquicondor, Huang-Wei, yuanchen8911

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~pkg/scheduler/OWNERS~~ [Huang-Wei,alculquicondor]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

yuanchen8911 · 2022-08-25T17:02:29Z

Thank you, folks!

k8s-ci-robot added release-note-none Denotes a PR that doesn't merit a release note. size/S Denotes a PR that changes 10-29 lines, ignoring generated files. kind/cleanup Categorizes issue or PR as related to cleaning up code, process, or technical debt. labels Aug 17, 2022

k8s-ci-robot added cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. do-not-merge/needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. needs-triage Indicates an issue or PR lacks a `triage/foo` label and requires one. labels Aug 17, 2022

k8s-ci-robot added the needs-priority Indicates a PR lacks a `priority/foo` label and requires one. label Aug 17, 2022

k8s-ci-robot added sig/scheduling Categorizes an issue or PR as relevant to SIG Scheduling. and removed do-not-merge/needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. labels Aug 17, 2022

k8s-ci-robot assigned Huang-Wei Aug 17, 2022

k8s-ci-robot requested review from chendave and denkensk August 17, 2022 01:03

yuanchen8911 force-pushed the events branch from f66b799 to bb12e97 Compare August 17, 2022 02:11

Huang-Wei reviewed Aug 23, 2022

View reviewed changes

yuanchen8911 force-pushed the events branch from 22599d1 to b02d487 Compare August 23, 2022 21:42

yuanchen8911 requested review from Huang-Wei and removed request for chendave and denkensk August 23, 2022 21:42

Huang-Wei reviewed Aug 23, 2022

View reviewed changes

yuanchen8911 force-pushed the events branch from b02d487 to 89db8b6 Compare August 24, 2022 17:52

yuanchen8911 requested a review from Huang-Wei August 24, 2022 17:52

k8s-ci-robot added the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Aug 24, 2022

yuanchen8911 requested review from alculquicondor and removed request for Huang-Wei August 24, 2022 21:42

Huang-Wei reviewed Aug 24, 2022

View reviewed changes

yuanchen8911 force-pushed the events branch from 72b344e to ae4e91f Compare August 24, 2022 23:02

k8s-ci-robot added size/XXL Denotes a PR that changes 1000+ lines, ignoring generated files. and removed size/S Denotes a PR that changes 10-29 lines, ignoring generated files. labels Aug 24, 2022

yuanchen8911 requested review from Huang-Wei and removed request for alculquicondor August 24, 2022 23:03

Huang-Wei reviewed Aug 24, 2022

View reviewed changes

pkg/scheduler/internal/queue/2 Outdated Show resolved Hide resolved

Huang-Wei reviewed Aug 24, 2022

View reviewed changes

pkg/scheduler/internal/queue/scheduling_queue.go Outdated Show resolved Hide resolved

yuanchen8911 requested review from Huang-Wei and alculquicondor and removed request for Huang-Wei August 24, 2022 23:47

yuanchen8911 force-pushed the events branch from 54d4efa to 7e05c0a Compare August 24, 2022 23:47

k8s-ci-robot added size/S Denotes a PR that changes 10-29 lines, ignoring generated files. and removed size/XXL Denotes a PR that changes 1000+ lines, ignoring generated files. labels Aug 24, 2022

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Aug 25, 2022

alculquicondor reviewed Aug 25, 2022

View reviewed changes

k8s-ci-robot removed the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Aug 25, 2022

k8s-ci-robot assigned alculquicondor Aug 25, 2022

k8s-ci-robot merged commit 9ec888e into kubernetes:master Aug 25, 2022

k8s-ci-robot added this to the v1.26 milestone Aug 25, 2022

yuanchen8911 changed the title ~~Log scheduling queue events~~ Log scheduling queue movement events Aug 25, 2022

yuanchen8911 mentioned this pull request Jun 5, 2023

Rename scheduler queue variables for consistency #118467

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Log scheduling queue movement events #111878

Log scheduling queue movement events #111878

yuanchen8911 commented Aug 17, 2022 •

edited

k8s-ci-robot commented Aug 17, 2022

k8s-ci-robot commented Aug 17, 2022

yuanchen8911 commented Aug 17, 2022

yuanchen8911 commented Aug 17, 2022

yuanchen8911 commented Aug 17, 2022

yuanchen8911 commented Aug 17, 2022

Huang-Wei Aug 23, 2022

yuanchen8911 Aug 23, 2022

yuanchen8911 commented Aug 23, 2022

Huang-Wei Aug 23, 2022

yuanchen8911 Aug 24, 2022

Huang-Wei commented Aug 24, 2022

Huang-Wei Aug 24, 2022

yuanchen8911 Aug 24, 2022

yuanchen8911 Aug 24, 2022

yuanchen8911 commented Aug 24, 2022

Huang-Wei commented Aug 25, 2022

alculquicondor left a comment

alculquicondor commented Aug 25, 2022

k8s-ci-robot commented Aug 25, 2022

yuanchen8911 commented Aug 25, 2022

	klog.V(5).InfoS("Pod moved between internal queues", "pod", klog.KObj(pod), "event", PodAdd, "to", activeQName)
	klog.V(5).InfoS("Pod moved to an internal queue", "pod", klog.KObj(pod), "event", PodAdd, "queue", activeQName)

Log scheduling queue movement events #111878

Log scheduling queue movement events #111878

Conversation

yuanchen8911 commented Aug 17, 2022 • edited

What type of PR is this?

What this PR does / why we need it:

Which issue(s) this PR fixes:

Special notes for your reviewer:

Does this PR introduce a user-facing change?

Additional documentation e.g., KEPs (Kubernetes Enhancement Proposals), usage docs, etc.:

k8s-ci-robot commented Aug 17, 2022

k8s-ci-robot commented Aug 17, 2022

yuanchen8911 commented Aug 17, 2022

yuanchen8911 commented Aug 17, 2022

yuanchen8911 commented Aug 17, 2022

yuanchen8911 commented Aug 17, 2022

Huang-Wei Aug 23, 2022

Choose a reason for hiding this comment

yuanchen8911 Aug 23, 2022

Choose a reason for hiding this comment

yuanchen8911 commented Aug 23, 2022

Huang-Wei Aug 23, 2022

Choose a reason for hiding this comment

yuanchen8911 Aug 24, 2022

Choose a reason for hiding this comment

Huang-Wei commented Aug 24, 2022

Huang-Wei Aug 24, 2022

Choose a reason for hiding this comment

yuanchen8911 Aug 24, 2022

Choose a reason for hiding this comment

yuanchen8911 Aug 24, 2022

Choose a reason for hiding this comment

yuanchen8911 commented Aug 24, 2022

Huang-Wei commented Aug 25, 2022

alculquicondor left a comment

Choose a reason for hiding this comment

alculquicondor commented Aug 25, 2022

k8s-ci-robot commented Aug 25, 2022

yuanchen8911 commented Aug 25, 2022

yuanchen8911 commented Aug 17, 2022 •

edited