Skip to content

Commit 263ab25

Browse files
k8s-ci-robotk8s-ci-robot
authored
Merge pull request kubernetes#121715 from pohly/scheduler-logging-with-instrumentation
scheduler: fix performance regression at -v3 + contextual logging
2 parents 66e20ff + 2a23061 commit 263ab25

File tree

2 files changed

+132
-93
lines changed

2 files changed

+132
-93
lines changed

‎pkg/scheduler/framework/runtime/framework.go‎

Lines changed: 127 additions & 93 deletions
Original file line numberDiff line numberDiff line change
@@ -655,14 +655,16 @@ func (f *frameworkImpl) RunPreFilterPlugins(ctx context.Context, state *framewor
655655
var result *framework.PreFilterResult
656656
var pluginsWithNodes []string
657657
logger := klog.FromContext(ctx)
658-
logger = klog.LoggerWithName(logger, "PreFilter")
659-
// TODO(knelasevero): Remove duplicated keys from log entry calls
660-
// When contextualized logging hits GA
661-
// https://github.com/kubernetes/kubernetes/issues/111672
662-
logger = klog.LoggerWithValues(logger, "pod", klog.KObj(pod))
658+
verboseLogs := logger.V(4).Enabled()
659+
if verboseLogs {
660+
logger = klog.LoggerWithName(logger, "PreFilter")
661+
}
663662
for _, pl := range f.preFilterPlugins {
664-
logger := klog.LoggerWithName(logger, pl.Name())
665-
ctx := klog.NewContext(ctx, logger)
663+
ctx := ctx
664+
if verboseLogs {
665+
logger := klog.LoggerWithName(logger, pl.Name())
666+
ctx = klog.NewContext(ctx, logger)
667+
}
666668
r, s := f.runPreFilterPlugin(ctx, pl, state, pod)
667669
if s.IsSkip() {
668670
skipPlugins.Insert(pl.Name())
@@ -711,17 +713,19 @@ func (f *frameworkImpl) RunPreFilterExtensionAddPod(
711713
nodeInfo *framework.NodeInfo,
712714
) (status *framework.Status) {
713715
logger := klog.FromContext(ctx)
714-
logger = klog.LoggerWithName(logger, "PreFilterExtension")
715-
// TODO(knelasevero): Remove duplicated keys from log entry calls
716-
// When contextualized logging hits GA
717-
// https://github.com/kubernetes/kubernetes/issues/111672
718-
logger = klog.LoggerWithValues(logger, "pod", klog.KObj(podToSchedule), "node", klog.KObj(nodeInfo.Node()), "operation", "addPod")
716+
verboseLogs := logger.V(4).Enabled()
717+
if verboseLogs {
718+
logger = klog.LoggerWithName(logger, "PreFilterExtension")
719+
}
719720
for _, pl := range f.preFilterPlugins {
720721
if pl.PreFilterExtensions() == nil || state.SkipFilterPlugins.Has(pl.Name()) {
721722
continue
722723
}
723-
logger := klog.LoggerWithName(logger, pl.Name())
724-
ctx := klog.NewContext(ctx, logger)
724+
ctx := ctx
725+
if verboseLogs {
726+
logger := klog.LoggerWithName(logger, pl.Name())
727+
ctx = klog.NewContext(ctx, logger)
728+
}
725729
status = f.runPreFilterExtensionAddPod(ctx, pl, state, podToSchedule, podInfoToAdd, nodeInfo)
726730
if !status.IsSuccess() {
727731
err := status.AsError()
@@ -754,17 +758,19 @@ func (f *frameworkImpl) RunPreFilterExtensionRemovePod(
754758
nodeInfo *framework.NodeInfo,
755759
) (status *framework.Status) {
756760
logger := klog.FromContext(ctx)
757-
logger = klog.LoggerWithName(logger, "PreFilterExtension")
758-
// TODO(knelasevero): Remove duplicated keys from log entry calls
759-
// When contextualized logging hits GA
760-
// https://github.com/kubernetes/kubernetes/issues/111672
761-
logger = klog.LoggerWithValues(logger, klog.KObj(podToSchedule), "node", klog.KObj(nodeInfo.Node()))
761+
verboseLogs := logger.V(4).Enabled()
762+
if verboseLogs {
763+
logger = klog.LoggerWithName(logger, "PreFilterExtension")
764+
}
762765
for _, pl := range f.preFilterPlugins {
763766
if pl.PreFilterExtensions() == nil || state.SkipFilterPlugins.Has(pl.Name()) {
764767
continue
765768
}
766-
logger := klog.LoggerWithName(logger, pl.Name())
767-
ctx := klog.NewContext(ctx, logger)
769+
ctx := ctx
770+
if verboseLogs {
771+
logger := klog.LoggerWithName(logger, pl.Name())
772+
ctx = klog.NewContext(ctx, logger)
773+
}
768774
status = f.runPreFilterExtensionRemovePod(ctx, pl, state, podToSchedule, podInfoToRemove, nodeInfo)
769775
if !status.IsSuccess() {
770776
err := status.AsError()
@@ -797,18 +803,20 @@ func (f *frameworkImpl) RunFilterPlugins(
797803
nodeInfo *framework.NodeInfo,
798804
) *framework.Status {
799805
logger := klog.FromContext(ctx)
800-
logger = klog.LoggerWithName(logger, "Filter")
801-
// TODO(knelasevero): Remove duplicated keys from log entry calls
802-
// When contextualized logging hits GA
803-
// https://github.com/kubernetes/kubernetes/issues/111672
804-
logger = klog.LoggerWithValues(logger, "pod", klog.KObj(pod), "node", klog.KObj(nodeInfo.Node()))
806+
verboseLogs := logger.V(4).Enabled()
807+
if verboseLogs {
808+
logger = klog.LoggerWithName(logger, "Filter")
809+
}
805810

806811
for _, pl := range f.filterPlugins {
807-
logger := klog.LoggerWithName(logger, pl.Name())
808-
ctx := klog.NewContext(ctx, logger)
809812
if state.SkipFilterPlugins.Has(pl.Name()) {
810813
continue
811814
}
815+
ctx := ctx
816+
if verboseLogs {
817+
logger := klog.LoggerWithName(logger, pl.Name())
818+
ctx = klog.NewContext(ctx, logger)
819+
}
812820
if status := f.runFilterPlugin(ctx, pl, state, pod, nodeInfo); !status.IsSuccess() {
813821
if !status.IsRejected() {
814822
// Filter plugins are not supposed to return any status other than
@@ -842,19 +850,21 @@ func (f *frameworkImpl) RunPostFilterPlugins(ctx context.Context, state *framewo
842850
}()
843851

844852
logger := klog.FromContext(ctx)
845-
logger = klog.LoggerWithName(logger, "PostFilter")
846-
// TODO(knelasevero): Remove duplicated keys from log entry calls
847-
// When contextualized logging hits GA
848-
// https://github.com/kubernetes/kubernetes/issues/111672
849-
logger = klog.LoggerWithValues(logger, "pod", klog.KObj(pod))
853+
verboseLogs := logger.V(4).Enabled()
854+
if verboseLogs {
855+
logger = klog.LoggerWithName(logger, "PostFilter")
856+
}
850857

851858
// `result` records the last meaningful(non-noop) PostFilterResult.
852859
var result *framework.PostFilterResult
853860
var reasons []string
854861
var rejectorPlugin string
855862
for _, pl := range f.postFilterPlugins {
856-
logger := klog.LoggerWithName(logger, pl.Name())
857-
ctx := klog.NewContext(ctx, logger)
863+
ctx := ctx
864+
if verboseLogs {
865+
logger := klog.LoggerWithName(logger, pl.Name())
866+
ctx = klog.NewContext(ctx, logger)
867+
}
858868
r, s := f.runPostFilterPlugin(ctx, pl, state, pod, filteredNodeStatusMap)
859869
if s.IsSuccess() {
860870
return r, s
@@ -990,14 +1000,16 @@ func (f *frameworkImpl) RunPreScorePlugins(
9901000
metrics.FrameworkExtensionPointDuration.WithLabelValues(metrics.PreScore, status.Code().String(), f.profileName).Observe(metrics.SinceInSeconds(startTime))
9911001
}()
9921002
logger := klog.FromContext(ctx)
993-
logger = klog.LoggerWithName(logger, "PreScore")
994-
// TODO(knelasevero): Remove duplicated keys from log entry calls
995-
// When contextualized logging hits GA
996-
// https://github.com/kubernetes/kubernetes/issues/111672
997-
logger = klog.LoggerWithValues(logger, "pod", klog.KObj(pod))
1003+
verboseLogs := logger.V(4).Enabled()
1004+
if verboseLogs {
1005+
logger = klog.LoggerWithName(logger, "PreScore")
1006+
}
9981007
for _, pl := range f.preScorePlugins {
999-
logger := klog.LoggerWithName(logger, pl.Name())
1000-
ctx := klog.NewContext(ctx, logger)
1008+
ctx := ctx
1009+
if verboseLogs {
1010+
logger := klog.LoggerWithName(logger, pl.Name())
1011+
ctx = klog.NewContext(ctx, logger)
1012+
}
10011013
status = f.runPreScorePlugin(ctx, pl, state, pod, nodes)
10021014
if status.IsSkip() {
10031015
skipPlugins.Insert(pl.Name())
@@ -1046,18 +1058,23 @@ func (f *frameworkImpl) RunScorePlugins(ctx context.Context, state *framework.Cy
10461058

10471059
if len(plugins) > 0 {
10481060
logger := klog.FromContext(ctx)
1049-
logger = klog.LoggerWithName(logger, "Score")
1050-
// TODO(knelasevero): Remove duplicated keys from log entry calls
1051-
// When contextualized logging hits GA
1052-
// https://github.com/kubernetes/kubernetes/issues/111672
1053-
logger = klog.LoggerWithValues(logger, "pod", klog.KObj(pod))
1061+
verboseLogs := logger.V(4).Enabled()
1062+
if verboseLogs {
1063+
logger = klog.LoggerWithName(logger, "Score")
1064+
}
10541065
// Run Score method for each node in parallel.
10551066
f.Parallelizer().Until(ctx, len(nodes), func(index int) {
10561067
nodeName := nodes[index].Name
1057-
logger := klog.LoggerWithValues(logger, "node", klog.ObjectRef{Name: nodeName})
1068+
logger := logger
1069+
if verboseLogs {
1070+
logger = klog.LoggerWithValues(logger, "node", klog.ObjectRef{Name: nodeName})
1071+
}
10581072
for _, pl := range plugins {
1059-
logger := klog.LoggerWithName(logger, pl.Name())
1060-
ctx := klog.NewContext(ctx, logger)
1073+
ctx := ctx
1074+
if verboseLogs {
1075+
logger := klog.LoggerWithName(logger, pl.Name())
1076+
ctx = klog.NewContext(ctx, logger)
1077+
}
10611078
s, status := f.runScorePlugin(ctx, pl, state, pod, nodeName)
10621079
if !status.IsSuccess() {
10631080
err := fmt.Errorf("plugin %q failed with: %w", pl.Name(), status.AsError())
@@ -1156,14 +1173,17 @@ func (f *frameworkImpl) RunPreBindPlugins(ctx context.Context, state *framework.
11561173
metrics.FrameworkExtensionPointDuration.WithLabelValues(metrics.PreBind, status.Code().String(), f.profileName).Observe(metrics.SinceInSeconds(startTime))
11571174
}()
11581175
logger := klog.FromContext(ctx)
1159-
logger = klog.LoggerWithName(logger, "PreBind")
1160-
// TODO(knelasevero): Remove duplicated keys from log entry calls
1161-
// When contextualized logging hits GA
1162-
// https://github.com/kubernetes/kubernetes/issues/111672
1163-
logger = klog.LoggerWithValues(logger, "pod", klog.KObj(pod), "node", klog.ObjectRef{Name: nodeName})
1176+
verboseLogs := logger.V(4).Enabled()
1177+
if verboseLogs {
1178+
logger = klog.LoggerWithName(logger, "PreBind")
1179+
logger = klog.LoggerWithValues(logger, "node", klog.ObjectRef{Name: nodeName})
1180+
}
11641181
for _, pl := range f.preBindPlugins {
1165-
logger := klog.LoggerWithName(logger, pl.Name())
1166-
ctx := klog.NewContext(ctx, logger)
1182+
ctx := ctx
1183+
if verboseLogs {
1184+
logger := klog.LoggerWithName(logger, pl.Name())
1185+
ctx = klog.NewContext(ctx, logger)
1186+
}
11671187
status = f.runPreBindPlugin(ctx, pl, state, pod, nodeName)
11681188
if !status.IsSuccess() {
11691189
if status.IsRejected() {
@@ -1199,14 +1219,16 @@ func (f *frameworkImpl) RunBindPlugins(ctx context.Context, state *framework.Cyc
11991219
return framework.NewStatus(framework.Skip, "")
12001220
}
12011221
logger := klog.FromContext(ctx)
1202-
logger = klog.LoggerWithName(logger, "Bind")
1203-
// TODO(knelasevero): Remove duplicated keys from log entry calls
1204-
// When contextualized logging hits GA
1205-
// https://github.com/kubernetes/kubernetes/issues/111672
1206-
logger = klog.LoggerWithValues(logger, "pod", klog.KObj(pod), "node", klog.ObjectRef{Name: nodeName})
1222+
verboseLogs := logger.V(4).Enabled()
1223+
if verboseLogs {
1224+
logger = klog.LoggerWithName(logger, "Bind")
1225+
}
12071226
for _, pl := range f.bindPlugins {
1208-
logger := klog.LoggerWithName(logger, pl.Name())
1209-
ctx := klog.NewContext(ctx, logger)
1227+
ctx := ctx
1228+
if verboseLogs {
1229+
logger := klog.LoggerWithName(logger, pl.Name())
1230+
ctx = klog.NewContext(ctx, logger)
1231+
}
12101232
status = f.runBindPlugin(ctx, pl, state, pod, nodeName)
12111233
if status.IsSkip() {
12121234
continue
@@ -1243,14 +1265,16 @@ func (f *frameworkImpl) RunPostBindPlugins(ctx context.Context, state *framework
12431265
metrics.FrameworkExtensionPointDuration.WithLabelValues(metrics.PostBind, framework.Success.String(), f.profileName).Observe(metrics.SinceInSeconds(startTime))
12441266
}()
12451267
logger := klog.FromContext(ctx)
1246-
logger = klog.LoggerWithName(logger, "PostBind")
1247-
// TODO(knelasevero): Remove duplicated keys from log entry calls
1248-
// When contextualized logging hits GA
1249-
// https://github.com/kubernetes/kubernetes/issues/111672
1250-
logger = klog.LoggerWithValues(logger, "pod", klog.KObj(pod), "node", klog.ObjectRef{Name: nodeName})
1268+
verboseLogs := logger.V(4).Enabled()
1269+
if verboseLogs {
1270+
logger = klog.LoggerWithName(logger, "PostBind")
1271+
}
12511272
for _, pl := range f.postBindPlugins {
1252-
logger := klog.LoggerWithName(logger, pl.Name())
1253-
ctx := klog.NewContext(ctx, logger)
1273+
ctx := ctx
1274+
if verboseLogs {
1275+
logger := klog.LoggerWithName(logger, pl.Name())
1276+
ctx = klog.NewContext(ctx, logger)
1277+
}
12541278
f.runPostBindPlugin(ctx, pl, state, pod, nodeName)
12551279
}
12561280
}
@@ -1276,14 +1300,17 @@ func (f *frameworkImpl) RunReservePluginsReserve(ctx context.Context, state *fra
12761300
metrics.FrameworkExtensionPointDuration.WithLabelValues(metrics.Reserve, status.Code().String(), f.profileName).Observe(metrics.SinceInSeconds(startTime))
12771301
}()
12781302
logger := klog.FromContext(ctx)
1279-
logger = klog.LoggerWithName(logger, "Reserve")
1280-
// TODO(knelasevero): Remove duplicated keys from log entry calls
1281-
// When contextualized logging hits GA
1282-
// https://github.com/kubernetes/kubernetes/issues/111672
1283-
logger = klog.LoggerWithValues(logger, "pod", klog.KObj(pod), "node", klog.ObjectRef{Name: nodeName})
1303+
verboseLogs := logger.V(4).Enabled()
1304+
if verboseLogs {
1305+
logger = klog.LoggerWithName(logger, "Reserve")
1306+
logger = klog.LoggerWithValues(logger, "node", klog.ObjectRef{Name: nodeName})
1307+
}
12841308
for _, pl := range f.reservePlugins {
1285-
logger := klog.LoggerWithName(logger, pl.Name())
1286-
ctx := klog.NewContext(ctx, logger)
1309+
ctx := ctx
1310+
if verboseLogs {
1311+
logger := klog.LoggerWithName(logger, pl.Name())
1312+
ctx = klog.NewContext(ctx, logger)
1313+
}
12871314
status = f.runReservePluginReserve(ctx, pl, state, pod, nodeName)
12881315
if !status.IsSuccess() {
12891316
if status.IsRejected() {
@@ -1319,15 +1346,19 @@ func (f *frameworkImpl) RunReservePluginsUnreserve(ctx context.Context, state *f
13191346
// Execute the Unreserve operation of each reserve plugin in the
13201347
// *reverse* order in which the Reserve operation was executed.
13211348
logger := klog.FromContext(ctx)
1322-
logger = klog.LoggerWithName(logger, "Unreserve")
1323-
// TODO(knelasevero): Remove duplicated keys from log entry calls
1324-
// When contextualized logging hits GA
1325-
// https://github.com/kubernetes/kubernetes/issues/111672
1326-
logger = klog.LoggerWithValues(logger, "pod", klog.KObj(pod), "node", klog.ObjectRef{Name: nodeName})
1349+
verboseLogs := logger.V(4).Enabled()
1350+
if verboseLogs {
1351+
logger = klog.LoggerWithName(logger, "Unreserve")
1352+
logger = klog.LoggerWithValues(logger, "node", klog.ObjectRef{Name: nodeName})
1353+
}
13271354
for i := len(f.reservePlugins) - 1; i >= 0; i-- {
1328-
logger := klog.LoggerWithName(logger, f.reservePlugins[i].Name())
1329-
ctx := klog.NewContext(ctx, logger)
1330-
f.runReservePluginUnreserve(ctx, f.reservePlugins[i], state, pod, nodeName)
1355+
pl := f.reservePlugins[i]
1356+
ctx := ctx
1357+
if verboseLogs {
1358+
logger := klog.LoggerWithName(logger, pl.Name())
1359+
ctx = klog.NewContext(ctx, logger)
1360+
}
1361+
f.runReservePluginUnreserve(ctx, pl, state, pod, nodeName)
13311362
}
13321363
}
13331364

@@ -1355,14 +1386,17 @@ func (f *frameworkImpl) RunPermitPlugins(ctx context.Context, state *framework.C
13551386
pluginsWaitTime := make(map[string]time.Duration)
13561387
statusCode := framework.Success
13571388
logger := klog.FromContext(ctx)
1358-
logger = klog.LoggerWithName(logger, "Permit")
1359-
// TODO(knelasevero): Remove duplicated keys from log entry calls
1360-
// When contextualized logging hits GA
1361-
// https://github.com/kubernetes/kubernetes/issues/111672
1362-
logger = klog.LoggerWithValues(logger, "pod", klog.KObj(pod), "node", klog.ObjectRef{Name: nodeName})
1389+
verboseLogs := logger.V(4).Enabled()
1390+
if verboseLogs {
1391+
logger = klog.LoggerWithName(logger, "Permit")
1392+
logger = klog.LoggerWithValues(logger, "node", klog.ObjectRef{Name: nodeName})
1393+
}
13631394
for _, pl := range f.permitPlugins {
1364-
logger := klog.LoggerWithName(logger, pl.Name())
1365-
ctx := klog.NewContext(ctx, logger)
1395+
ctx := ctx
1396+
if verboseLogs {
1397+
logger := klog.LoggerWithName(logger, pl.Name())
1398+
ctx = klog.NewContext(ctx, logger)
1399+
}
13661400
status, timeout := f.runPermitPlugin(ctx, pl, state, pod, nodeName)
13671401
if !status.IsSuccess() {
13681402
if status.IsRejected() {

‎pkg/scheduler/schedule_one.go‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -77,6 +77,11 @@ func (sched *Scheduler) scheduleOne(ctx context.Context) {
7777
}
7878

7979
pod := podInfo.Pod
80+
// TODO(knelasevero): Remove duplicated keys from log entry calls
81+
// When contextualized logging hits GA
82+
// https://github.com/kubernetes/kubernetes/issues/111672
83+
logger = klog.LoggerWithValues(logger, "pod", klog.KObj(pod))
84+
ctx = klog.NewContext(ctx, logger)
8085
logger.V(4).Info("About to try and schedule pod", "pod", klog.KObj(pod))
8186

8287
fwk, err := sched.frameworkForPod(pod)

0 commit comments

Comments
 (0)