The logging instrumentation for contextual logging that was added for 1.29
slowed down the scheduler (i.e. logging verbosity <= 3) by a significant
percentage (-28.66% for SchedulingBasic/5000Nodes at -v3) if (and only if!)
contextual logging was enabled.
Retrieving the logger from the context causes no measurable slowdown, it's only
the various WithName/WithValues calls which cause this.
By being more careful about when to use those, the performance impact can be
avoided:
- At -v3 or lower, only `WithValues("pod")` is used once per scheduling cycle.
This has the intended effect that all log messages for the cycle include the
pod information. Once contextual logging is GA, "pod" key/value pairs can
be removed from all log calls.
- At -v4 or higher, richer log entries get produced where `WithValues` is also
used for the node (when applicable) and `WithName` is used for the current
operation and plugin.
With these changes, enabling contextual logging causes no measurable slowdown
at -v3 or lower. At -v4, the slowdown depends on the test case (-30.51%
throughput for SchedulingBasic/5000Nodes, no change for
SchedulingCSIPVs/5000Nodes). For some unknown reason (measuring bias?),
SchedulingCSIPVs/500Nodes has a ~3& *higher* throughput with contextual
logging.
During scheduler_perf testing, roughly 10% of the PodSchedulingContext update
operations failed with a conflict error. Using SSA would avoid that, but
performance measurements showed that this causes a considerable
slowdown (primarily because of the slower encoding with JSON instead of
protobuf, but also because server-side processing is more expensive).
Therefore a normal update is tried first and SSA only gets used when there has
been a conflict. Using SSA in that case instead of giving up outright is better
because it avoids another scheduling attempt.
This fixes a test flake:
[sig-node] DRA [Feature:DynamicResourceAllocation] multiple nodes reallocation [It] works
/nvme/gopath/src/k8s.io/kubernetes/test/e2e/dra/dra.go:552
[FAILED] number of deallocations
Expected
<int64>: 2
to equal
<int64>: 1
In [It] at: /nvme/gopath/src/k8s.io/kubernetes/test/e2e/dra/dra.go:651 @ 09/05/23 14:01:54.652
This can be reproduced locally with
stress -p 10 go test ./test/e2e -args -ginkgo.focus=DynamicResourceAllocation.*reallocation.works -ginkgo.no-color -v=4 -ginkgo.v
Log output showed that the sequence of events leading to this was:
- claim gets allocated because of selected node
- a different node has to be used, so PostFilter sets
claim.status.deallocationRequested
- the driver deallocates
- before the scheduler can react and select a different node,
the driver allocates *again* for the original node
- the scheduler asks for deallocation again
- the driver deallocates again (causing the test failure)
- eventually the pod runs
The fix is to disable allocations first by removing the selected node and then
starting to deallocate.
Instead of modifying the PodSchedulingContext and then creating or updating it,
now the required changes (selected node, potential nodes) are tracked and the
actual input for an API call is created if (and only if) needed at the end.
This makes the code easier to read and change. In particular, replacing the
Update call with Patch or Apply is easy.
When filtering fails because a ResourceClass is missing, we can treat the pod
as "unschedulable" as long as we then also register a cluster event that wakes
up the pod. This is more efficient than periodically retrying.
